Advanced Troubleshooting of CSS Heartbeat Failures (Network)

@ Oracle Confidential (INTERNAL). Do not distribute to customers
@ Reason: Contains CSS Internals

@ (AuthWiz 2.5.5)
@ Click here to edit in wizard.

Applies to:
Oracle Server – Enterprise Edition – Version: 10.2.0.1 to 10.2.0.1
Information in this document applies to any platform.
Purpose
Internal Note to Explain How to Troubleshoot CSS Heartbeat Failures (Network).
Scope and Application
For Oracle Support and Development
Internal Only: Advanced Troubleshooting of CSS Heartbeat Failures (Network)

The tell tale sign of a CSS network heartbeat related issue is the following type of message in the CSS log:
[ CSSD]2007-09-06 18:38:45.861 [18] >WARNING: clssnmPollingThread: node scadfrai11 (2) at 50% heartbeat fatal, eviction in 14.275 seconds

The first thing to do is find out if the missed checkins ARE the problem or are a result of the node going down due to other reasons. Check the messages file to see what exact time the node went down and compare it to the time of the missed checkins.
- If the messages file reboot time < missed checkin time then the node eviction was
likely not due to these missed checkins.

- If the messages file reboot time > missed checkin time then the node eviction was
likely a result of the missed checkins.

If you determine that CSS actually did reboot the node due to missed checkins, then we need to find out why.  There are 3 threads in CSS that deal with CSS heartbeats:

clssnmSendingThread – This thread periodically wakes up and sends appropriate packets (based on the join state) to other nodes so that other members know we are still alive. For the heartbeat he sends “status” packets to the other nodes to tell them that they are alive. This can be seen at CSS trace level 2 or higher. Example:
[ CSSD]2007-09-06 18:37:07.857 [19] >TRACE: clssnmSendingThread: sending status msg to all nodes

Notice that the thread # for the clssnmSendingThread is 19 in this example.  This is important to know so that you don’t end up troubleshooting the wrong thread

With CSS trace level 4 + CLSC tracing you can see more details important details like:
[ CSSD]2007-09-06 18:38:31.584 [19] >TRACE: clssnmsendmsg: sending msg type 3 to node 1
[ CSSD]2007-09-06 18:38:31.584 [19] >TRACE: clscsendx: (b8aaf0) sending msg (f395c8) type 3, size 68, srqh (eed3d0)
[ CSSD]2007-09-06 18:38:31.587 [19] >TRACE: clscsendx: (b8aaf0) sent msg type 3, size 68, rc 0 srqh (eed3d0)

If you also turn on CLSC NS tracing you can see the Oracle Net tracing for this.  You can see something like:
(19) [000013 06-SEP-2007 18:38:31:586] nsdo: cid=1, opcode=67, *bl=68, *what=1, uflgs=0×2, cflgs=0×3
(19) [000013 06-SEP-2007 18:38:31:586] snsbitts_ts: acquired the bit
(19) [000013 06-SEP-2007 18:38:31:586] nsdo: rank=64, nsctxrnk=0
(19) [000013 06-SEP-2007 18:38:31:586] nsdo: nsctx: state=8, flg=0x400d, mvd=0
(19) [000013 06-SEP-2007 18:38:31:586] nsdo: 68 bytes to transport
(19) [000013 06-SEP-2007 18:38:31:586] nttmwr: entry
(19) [000013 06-SEP-2007 18:38:31:587] nttmwr: socket 26 had bytes written=68
(19) [000013 06-SEP-2007 18:38:31:587] nttmwr: exit

And of course OS Watcher is good to look at things underneath CSS.

The code path for sending a heartbeat message is clssnmSendingThread–>clssnmsendmsg–>clscsendx

clssnmClusterListener thread – This thread listens for incoming packets from other nodes by calling clscselect and dispatches them for appropriate handling. When the clssnmClusterListener receives a packet, it calls clssnmProcessPkt to process the packet. If it is a status packet then clssnmProcessPkt calls clssnmHandleStatus. In clssnmHandleStatus we put the packet info in memory to let it get seen by the polling thread so it can decide what to do with them.

At CSS trace level 3 or higher you can see the clssnmClusterListener thread waking up and going through it’s loop. You can also see
[ CSSD]2007-09-06 18:38:31.299 [13] >TRACE: clssnmClusterListener: Entering select blocking

Notice that the thread # for the clssnmClusterListener thread is 13 in this example. This is important to know so that you don’t end up troubleshooting the wrong thread

With trace level 4 + CLSC tracing you can see more details important details like:
[ CSSD]2007-09-06 18:38:30.070 [13] >TRACE: clsc_receive: (f16470) prepare to receive
[ CSSD]2007-09-06 18:38:30.074 [13] >TRACE: clsc_receive: (f16470) compl recv, rc 0, nsret 0, flgs 0×0000, size 68
[ CSSD]2007-09-06 18:38:30.074 [13] >TRACE: clsc_receive: (f16470, 1) recv msg type 3, size 68, msgsz 68
[ CSSD]2007-09-06 18:38:30.074 [13] >TRACE: clssnmHandleStatus: src[2] dest[0] dom[0] seq[0] sync[53]
[ CSSD]2007-09-06 18:38:31.299 [13] >TRACE: clssnmClusterListener: Entering select blocking

If you also turn on CLSC NS tracing you can see the Oracle Net tracing for this.  You can see something like:
(13) [000014 06-SEP-2007 18:38:30:071] nsdo: cid=2, opcode=68, *bl=131136, *what=0, uflgs=0×0, cflgs=0×3
(13) [000014 06-SEP-2007 18:38:30:071] snsbitts_ts: acquired the bit
(13) [000014 06-SEP-2007 18:38:30:071] nsdo: rank=64, nsctxrnk=0
(13) [000014 06-SEP-2007 18:38:30:071] nsdo: nsctx: state=8, flg=0x400c, mvd=0
(13) [000014 06-SEP-2007 18:38:30:072] nsdo: reading from transport…
(13) [000014 06-SEP-2007 18:38:30:072] nttmrd: entry
(13) [000014 06-SEP-2007 18:38:30:073] nttmrd: socket 95 had bytes read=68
(13) [000014 06-SEP-2007 18:38:30:073] nttmrd: exit

And of course OS Watcher is good to look at things underneath CSS.

The code path for receiving a heartbeat message is clssnmClusterListener–>clscselect
The code path to process a received heartbeat message is clssnmClusterListener–>clssnmProcessPkt–>clssnmHandleStatus

clssnmPollingThread – Periodically wakes up and scans to see who is active and has been checking in regularly by reading from the node db in memory. If the last last packet time in memory reaches 1/2 of misscount you will see this famous message:
[ CSSD]2007-09-06 18:38:45.861 [18] >WARNING: clssnmPollingThread: node scadfrai11 (2) at 50% heartbeat fatal, eviction in 14.275 seconds

Not much more useful trace info you can turn on for this guy. He just reads the last packet time in memory and takes action if we reach misscount (sends out poison packets, etc…).

Things to Look For:

- Is the clssnmSendingThread sending a status message to every other node continuously?
If the answer is no, see if the clssnmSendingThread is stuck (stack traces of all threads of CSS) or if there is a resource problem or network error in OS Watcher (netstat, vmstat, etc…)

- Is the clssnmClusterListener receiving a status message from every other node continuously?
Again, if the answer is no, see if the clssnmClusterListener is stuck (stack traces of all threads of CSS) or if there is a resource problem or network error in OS Watcher (netstat, vmstat, etc…)

As long as you can confirm that the sending thread from node x is sending and the listening thread from node y is receiving you should not see any missed checkins.

For Extremely Detailed Tracing of CSS Heartbeats (Be Careful Suggesting This to Customers):

10.2.0.2 (Bundle Patch 2) and above:

<CRS_HOME>/bin/crsctl debug log css CSSD:4 (default is 1)
(No subsequent reboot needed if you do it this way)

Prior versions:

<CRS_HOME>/bin/crsctl set css trace 4 (default is 1)

And set the following <CRS_HOME>/bin/ocssd:

CLSC_TRACE_LVL=5
export CLSC_TRACE_LVL
CLSC_NSTRACE_LVL=12
export CLSC_NSTRACE_LVL

Then restart CRS.

This would provide A LOT of detail about the underlying Oracle network layers under CSS but obviously would generate trace info very fast in CRS_HOME/log/<hostname>/cssd so the data would have to be captured quickly before the CSS log wraps. Either that or have a job to save off and compress all the logs every 10-15 min.

Sample script to archive CSS logs every 10 minutes (archcsslogs.sh):

# archcsslogs.sh
#
# Archive CSS logs Every 10 Minutes to /tmp
#
# Set the CSSLOGDIR before running the script..(<CRS_HOME>/log/nodename/cssd)
#
# Example:
# CSSLOGDIR=/u01/oracrs/product/11.1.0/log/node1/cssd

CSSLOGDIR=<insert path here>

while [ 1 -ne 0 ]; do
CSSFILE=/tmp/css_`date +%m%d%y”_”%H%M`.tar
tar cf $CSSFILE $CSSLOGDIR/*
compress $CSSFILE
sleep 600
done
exit

To run:

chmod 755 archcsslogs.sh
nohup ./archcsslogs.sh &

Then kill the archcsslogs.sh process when you want it to stop archiving…