Internal Only: Advanced Troubleshooting of CSS Heartbeat Failures (Network) (Doc ID 457772.1)

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. <<<<<시간을 통해 리부트가 Miss 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:
<<<<<각 노드마다 css 하트비트를 처리하는 세 개의 theads가 있습니다. 하나는 수신하고 하나는 발송하고 하나는 표결합니다.진단할 때 이 몇 개가 모두 수신되었는지,miss checkin이 존재하는지 확인해야 한다.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=0x2, cflgs=0x3
(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 0x0000, 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=0x0, cflgs=0x3
(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: /bin/crsctl debug log css CSSD:4 (default is 1) (No subsequent reboot needed if you do it this way)
Prior versions: /bin/crsctl set css trace 4 (default is 1) And set the following /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//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...
References
@ BUG:6394860- NODE REBOOT/EVICTIONS DUE TO HEARTBEAT LOST ON NETWORK NOTE:265769.1- Troubleshooting CRS Reboots
@ NOTE:305689.1- CSS (Cluster Synchronization Services) Internals (INTERNAL ONLY) clssnm.c and clssnm.h