Monday, September 12, 2011

Changing the default logging level for ocssd

I just want to write about ocssd and to change logging level. ocssd is process for CSS. when you want to debug CSS. You should know how to change logging level for ocssd. The default logging level for ocssd on Oracle 11.2 is 2. When you want to change logging level for ocssd, you have to use root user to change it.
# crsctl get log css CSSD
Get CSSD Module: CSSD Log Level: 2
Logging Levels:
2 : default
3 : display each heartbeat message including the misstime, that is helpful to debug Network Heartbeat
4 : super verbose

You can check ocssd.log at $GRID_HOME/log/$HOST/cssd PATH

In ocssd.log file - CSSD Log Level: 2
2011-09-12 21:45:14.448: [ CSSD][1113188672]clssnmSendingThread: sending status msg to all nodes
2011-09-12 21:45:14.448: [ CSSD][1113188672]clssnmSendingThread: sent 4 status msgs to all nodes
Not more for information.

You can change logging by using crsctl command-line (root user)
crsctl set log css CSSD:N (where N = the logging level)
Changed to level 3:
# crsctl set log css CSSD:3
Set CSSD Module: CSSD Log Level: 3
In ocssd.log file - CSSD Log Level: 3
2011-09-12 21:46:15.211: [ CSSD][1108457792]clssnmvDiskCheck: Checking configured voting files
2011-09-12 21:46:15.211: [ CSSD][1108457792]clssnmvDiskPMT: sleeping for 1000 ms
2011-09-12 21:46:15.291: [ CSSD][1100572992]clssgmExecuteClientRequest: PRIINFO recvd from client 4 (0x2aaaac24c330)
2011-09-12 21:46:15.291: [ CSSD][1100572992]clssgmLookupMember: mbr no 2, privincarn 216985, pubincarn 0
2011-09-12 21:46:15.291: [ CSSD][1100572992]clssgmMemberPrivateInfo: Data found localNode
2011-09-12 21:46:15.588: [ CSSD][1113188672]clssnmHBInfo: css timestmp 1315838775 588 slgtime 528281614 DTO 28130 (index=0) biggest misstime 600 NTO 27900
2011-09-12 21:46:16.011: [ CSSD][1100572992]clssgmExecuteClientRequest: Received data update request from client (0x2aaaac24c330), type 1
2011-09-12 21:46:16.011: [ CSSD][1100572992]clssgmMbrDataUpdt: grockName HB+ASM Nameoffset 112 dataoffset119 datasize 4 mlen 123
2011-09-12 21:46:16.011: [ CSSD][1100572992]clssgmBroadcastMap: msg (0x15530ba8), type 13, len 123, sendcnt 2
2011-09-12 21:46:16.011: [ CSSD][1100572992]clssgmQueueGrockEvent: No event, groupName(HB+ASM) event(6) member 1, events 0x1, state 0x0
2011-09-12 21:46:16.011: [ CSSD][1100572992]clssgmQueueGrockEvent: skipping remote member 2
More information with "misstime"

Changed to level 4:
# crsctl set log css CSSD:4
Set CSSD Module: CSSD Log Level: 4
In ocssd.log file - CSSD Log Level: 4
2011-09-12 21:47:16.269: [ CSSD][1110034752]clssscSelect: processing event 1 endp 0xf84c sta 0 cont 0x6ff
2011-09-12 21:47:16.269: [ CSSD][1110034752]clssgmPeerEventhndlr: RECV endp 0xf84c type 13 size 123 src 2
2011-09-12 21:47:16.269: [ CSSD][1110034752]clssgmDispatchCMXMSG: msg type 13, src 2, size 123, RPC#0, generation 0, incarnation(210863521)
2011-09-12 21:47:16.269: [ CSSD][1110034752]clssgmTagize: version(1), type(13), tagizer(0x45e6a8)
2011-09-12 21:47:16.269: [ CSSD][1110034752]clssgmHandleDataInvalid: grock HB+ASM, member 2 node 2, birth 11
2011-09-12 21:47:16.269: [ CSSD][1110034752]clssgmGrockFind: grock HB+ASM, type 2, ct 0
2011-09-12 21:47:16.269: [ CSSD][1110034752]clssgmLookupMember: mbr no 2, privincarn 217014, pubincarn 0
2011-09-12 21:47:16.269: [ CSSD][1110034752]clssgmHandleDataInvalid: grockName HB+ASM Nameoffset 112 dataoffset 119 datasize 4 msglen 123
2011-09-12 21:47:16.269: [ CSSD][1110034752]clssgmQueueGrockEvent: No event, groupName(HB+ASM) event(6) member 1, events 0x1, state 0x0
2011-09-12 21:47:16.269: [ CSSD][1110034752]clssgmQueueGrockEvent: skipping remote member 2
2011-09-12 21:47:16.269: [ CSSD][1110034752]clssgmGrockUnlock: grock HB+ASM, type 2, ct 0
2011-09-12 21:47:16.329: [ CSSD][1111611712]clssnmWaitThread: thrd(2), timeout(1000), elapsed 1000
2011-09-12 21:47:16.329: [ CSSD][1111611712]clssnmPollingThread: node 2, node02, ninfmisstime 200, misstime 200, skgxnbit 4, vcwmisstime 0, syncstage 0
2011-09-12 21:47:16.329: [ CSSD][1111611712]clssnmWaitThread: thrd(2), timeout(1000), wakeonpost(2)
2011-09-12 21:47:16.341: [ CSSD][1108457792]clssnmWaitThread: thrd(9), timeout(1000), elapsed 1000
2011-09-12 21:47:16.341: [ CSSD][1108457792]clssnmvDiskCheck: Checking configured voting files
2011-09-12 21:47:16.341: [ CSSD][1108457792]clssnmvDiskCheck: disk still good (910/ORCL:DATA)
2011-09-12 21:47:16.341: [ CSSD][1108457792]clssnmvDiskPMT: sleeping for 1000 ms
2011-09-12 21:47:16.341: [ CSSD][1108457792]clssnmWaitThread: thrd(9), timeout(1000), wakeonpost(0)
2011-09-12 21:47:16.430: [ CSSD][1105303872]clssnmWaitThread: thrd(8), timeout(1000), elapsed 1000
2011-09-12 21:47:16.430: [ CSSD][1105303872]clssnmvDiskPing:curInfo name node01 seq 460715
2011-09-12 21:47:16.431: [ CSSD][1105303872]clssnmWaitThread: thrd(8), timeout(1000), wakeonpost(0)
2011-09-12 21:47:16.736: [ CSSD][1113188672]clssnmWaitThread: thrd(1), timeout(1000), elapsed 1010
2011-09-12 21:47:16.736: [ CSSD][1113188672]clssscAllocAsyncMsg: msg(0x2aaaac04b718), len(124), asqhd(0x2aaaac04b6f0), flags(0x083)
2011-09-12 21:47:16.736: [ CSSD][1113188672]clssnmsendmsg: sending msg type 3 size 124 to node 2 endp 0xf7ae
2011-09-12 21:47:16.736: [ CSSD][1113188672]clssnmSendGIPC: cookie 0x14f05a10 - endp 0xf7ae type 3 size 124 dst 0
2011-09-12 21:47:16.736: [ CSSD][1113188672]clssnmsendmsg: msg type 3 sent to node 2
2011-09-12 21:47:16.736: [ CSSD][1113188672]clssnmHBInfo: css timestmp 1315838836 736 slgtime 528342754 DTO 28190 (index=0) biggest misstime 610 NTO 27890
2011-09-12 21:47:16.736: [ CSSD][1113188672]clssgmSendClient: client (0x15381340) proc (0x2aaaac058860), pid 24822 dead state 0, msgtype 22, msgsize 104
2011-09-12 21:47:16.736: [ CSSD][1113188672]clssscAllocAsyncMsg: msg(0x2aaaac20cb78), len(104), asqhd(0x2aaaac20cb50), flags(0x081)
2011-09-12 21:47:16.736: [ CSSD][1113188672]clssgmclSendGIPC: cookie 0x15381340 - endp(0xc41), msg(0x2aaaac20cb78), type(22), size(104)
2011-09-12 21:47:16.736: [ CSSD][1113188672]clssgmSendClient: client (0x15270ba0) proc (0x2aaaac043130), pid 24804 dead state 0, msgtype 22, msgsize 104
2011-09-12 21:47:16.736: [ CSSD][1116342592]clssscSelect: processing event 0 endp 0xf7ae sta 0 cont 0x6d
2011-09-12 21:47:16.736: [ CSSD][1113188672]clssscAllocAsyncMsg: msg(0x2aaaac017b78), len(104), asqhd(0x2aaaac017b50), flags(0x081)
2011-09-12 21:47:16.736: [ CSSD][1113188672]clssgmclSendGIPC: cookie 0x15270ba0 - endp(0xc2e), msg(0x2aaaac017b78), type(22), size(104)
2011-09-12 21:47:16.736: [ CSSD][1116342592]SENDCOMPLETE: sendreq 0x2aaaac2db3d0 link 0x2aaaac2db3d8 rattr 0
2011-09-12 21:47:16.736: [ CSSD][1116342592]clssnmeventhndlr: freeing sendreq 0x2aaaac2db3d0
2011-09-12 21:47:16.736: [ CSSD][1116342592]clssscFreeAsyncMsg: freeing msg (0x2aaaac04b718), asqhd (0x2aaaac04b6f0), sendct 0, flags 0x00000002
2011-09-12 21:47:16.736: [ CSSD][1113188672]clssnmWaitThread: thrd(1), timeout(1000), wakeonpost(0)
2011-09-12 21:47:16.736: [ CSSD][1116342592]clssnmClusterListener: calling select
2011-09-12 21:47:16.737: [ CSSD][1100572992]clssscSelect: processing event 0 endp 0xc41 sta 0 cont 0x72
2011-09-12 21:47:16.737: [ CSSD][1100572992]clssgmclienteventhndlr: cookie cmProc 0x15381340
2011-09-12 21:47:16.737: [ CSSD][1100572992]clssscFreeAsyncMsg: freeing msg (0x2aaaac20cb78), asqhd (0x2aaaac20cb50), sendct 0, flags 0x00000000
2011-09-12 21:47:16.737: [ CSSD][1100572992]clssgmCheckReqNMCompletions: enter
2011-09-12 21:47:16.737: [ CSSD][1100572992]clssgmCheckReqNMCompletions: exit
2011-09-12 21:47:16.737: [ CSSD][1100572992]clssgmProcClientReqs: entering select
2011-09-12 21:47:16.737: [ CSSD][1100572992]clssscSelect: processing event 0 endp 0xc2e sta 0 cont 0x72
2011-09-12 21:47:16.737: [ CSSD][1100572992]clssgmclienteventhndlr: cookie cmProc 0x15270ba0
2011-09-12 21:47:16.737: [ CSSD][1100572992]clssscFreeAsyncMsg: freeing msg (0x2aaaac017b78), asqhd (0x2aaaac017b50), sendct 0, flags 0x00000000
2011-09-12 21:47:16.737: [ CSSD][1100572992]clssgmCheckReqNMCompletions: enter
2011-09-12 21:47:16.737: [ CSSD][1100572992]clssgmCheckReqNMCompletions: exit
2011-09-12 21:47:16.737: [ CSSD][1100572992]clssgmProcClientReqs: entering select
2011-09-12 21:47:16.907: [ CSSD][1090758976]clssnmWaitThread: thrd(10), timeout(1000), elapsed 1010
2011-09-12 21:47:16.907: [ CSSD][1090758976]clssnmWaitThread: thrd(10), timeout(1000), wakeonpost(0)
2011-09-12 21:47:17.133: [ CSSD][1116342592]clssscSelect: processing event 1 endp 0xf7ae sta 0 cont 0x6d
2011-09-12 21:47:17.133: [ CSSD][1116342592]RECV: endp 0xf7ae type 3 size 124 src 2
2011-09-12 21:47:17.133: [ CSSD][1116342592]clssnmeventhndlr: msg type 3 recvd from node 2
2011-09-12 21:47:17.133: [ CSSD][1116342592]clssnmHandleStatus: src[2] dest[0] dom[-1] seq[162] sync[0]
2011-09-12 21:47:17.133: [ CSSD][1116342592]clssnmClusterListener: calling select
2011-09-12 21:47:17.150: [ CSSD][1100572992]clssscSelect: processing event 1 endp 0xdea sta 0 cont 0x72
2011-09-12 21:47:17.150: [ CSSD][1100572992]RECV: endp 0xdea type 5 size 114
2011-09-12 21:47:17.150: [ CSSD][1100572992]clssgmExecuteClientRequest: GRPSTATE recvd from proc 5 (0x2aaaac2ed760)
2011-09-12 21:47:17.150: [ CSSD][1100572992]clssgmGrockFind: grock haip.cluster_interconnect, type 2, ct 0
2011-09-12 21:47:17.150: [ CSSD][1100572992]clssgmGroupState: requested group state of group haip.cluster_interconnect, member count 2
2011-09-12 21:47:17.150: [ CSSD][1100572992]clssgmGrockUnlock: grock haip.cluster_interconnect, type 2, ct 0
2011-09-12 21:47:17.150: [ CSSD][1100572992]clssgmSendClient: client ((nil)) proc (0x2aaaac2ed760), pid 24777 dead state 0, msgtype 5, msgsize 178
2011-09-12 21:47:17.150: [ CSSD][1100572992]clssscAllocAsyncMsg: msg(0x2aaab4041bd8), len(178), asqhd(0x2aaab4041bb0), flags(0x081)
2011-09-12 21:47:17.150: [ CSSD][1100572992]clssgmclSendGIPC: cookie 0x2aaaac2ed760 - endp(0xdea), msg(0x2aaab4041bd8), type(5), size(178)
2011-09-12 21:47:17.150: [ CSSD][1100572992]clssgmCheckReqNMCompletions: enter
2011-09-12 21:47:17.150: [ CSSD][1100572992]clssgmCheckReqNMCompletions: exit
2011-09-12 21:47:17.150: [ CSSD][1100572992]clssgmProcClientReqs: entering select
2011-09-12 21:47:17.151: [ CSSD][1100572992]clssscSelect: processing event 0 endp 0xdea sta 0 cont 0x72
2011-09-12 21:47:17.151: [ CSSD][1100572992]clssgmclienteventhndlr: cookie cmProc 0x2aaaac2ed760
2011-09-12 21:47:17.151: [ CSSD][1100572992]clssscFreeAsyncMsg: freeing msg (0x2aaab4041bd8), asqhd (0x2aaab4041bb0), sendct 0, flags 0x00000000
2011-09-12 21:47:17.151: [ CSSD][1100572992]clssgmCheckReqNMCompletions: enter
2011-09-12 21:47:17.151: [ CSSD][1100572992]clssgmCheckReqNMCompletions: exit
2011-09-12 21:47:17.151: [ CSSD][1100572992]clssgmProcClientReqs: entering select
2011-09-12 21:47:17.151: [ CSSD][1100572992]clssscSelect: processing event 1 endp 0xe19 sta 0 cont 0x72
2011-09-12 21:47:17.151: [ CSSD][1100572992]RECV: endp 0xe19 type 10 size 72
2011-09-12 21:47:17.151: [ CSSD][1100572992]clssgmExecuteClientRequest: PRIINFO recvd from client 1 (0x2aaaac2ee130)
2011-09-12 21:47:17.151: [ CSSD][1100572992]clssgmGrockLock: grock haip.cluster_interconnect, type 2, ct 0
2011-09-12 21:47:17.151: [ CSSD][1100572992]clssgmLookupMember: mbr no 2, privincarn 2, pubincarn 0
2011-09-12 21:47:17.151: [ CSSD][1100572992]clssgmMemberPrivateInfo: Data found localNode
2011-09-12 21:47:17.151: [ CSSD][1100572992]clssgmGrockUnlock: grock haip.cluster_interconnect, type 2, ct 0
2011-09-12 21:47:17.151: [ CSSD][1100572992]clssgmSendClient: client (0x2aaaac2ee130) proc (0x2aaaac2ed760), pid 24777 dead state 0, msgtype 10, msgsize 88
2011-09-12 21:47:17.151: [ CSSD][1100572992]clssscAllocAsyncMsg: msg(0x2aaab40374e8), len(88), asqhd(0x2aaab40374c0), flags(0x081)
2011-09-12 21:47:17.151: [ CSSD][1100572992]clssgmclSendGIPC: cookie 0x2aaaac2ee130 - endp(0xe19), msg(0x2aaab40374e8), type(10), size(88)
2011-09-12 21:47:17.151: [ CSSD][1100572992]clssgmCheckReqNMCompletions: enter
2011-09-12 21:47:17.151: [ CSSD][1100572992]clssgmCheckReqNMCompletions: exit
2011-09-12 21:47:17.152: [ CSSD][1100572992]clssgmProcClientReqs: entering select
2011-09-12 21:47:17.152: [ CSSD][1100572992]clssscSelect: processing event 0 endp 0xe19 sta 0 cont 0x72
2011-09-12 21:47:17.152: [ CSSD][1100572992]clssgmclienteventhndlr: cookie cmProc 0x2aaaac2ee130
2011-09-12 21:47:17.152: [ CSSD][1100572992]clssscFreeAsyncMsg: freeing msg (0x2aaab40374e8), asqhd (0x2aaab40374c0), sendct 0, flags 0x00000000
2011-09-12 21:47:17.152: [ CSSD][1100572992]clssgmCheckReqNMCompletions: enter
2011-09-12 21:47:17.152: [ CSSD][1100572992]clssgmCheckReqNMCompletions: exit
2011-09-12 21:47:17.152: [ CSSD][1100572992]clssgmProcClientReqs: entering select
Wow!!! many informations.
However, The issue can be solved with default (level 2). But you should know steps to change logging level, maybe the default level not enough.

ocssd idea
- Sending Network Heartbeat and Local Heartbeat at the same time.
- Disk Ping (Disk Heartbeat)
- Cluster Listener = receive message from other nodes

No comments: