This discussion is archived
1 2 Previous Next 16 Replies Latest reply: Jan 11, 2013 3:18 AM by User477708-OC RSS

RAC crashed - errors in messages log

User477708-OC Journeyer
Currently Being Moderated
2 node RAC. running 1 node config.
OEL 5.
Oracle 11.2.0.2.0

RAC crashed this morning with following errors in ASM log
ORA-27300: OS system dependent operation:semget failed with status: 28
ORA-27301: OS failure message: No space left on device
ORA-27302: failure occurred at: sskgpsemsper

Found blog notes to up the semaphores in the kernel. http://arjudba.blogspot.ie/2008/09/database-startup-fails-with-ora-27302.html
bumped up to the following as per note but didnt fix

from: kernel.sem = 256 32000 100 128
to: kernel.sem = 256 32768 100 228

then tried 258 - didnt work
found another blog note that said to try 288 and that DID work so appears to be a semaphore issue. 2 questions:
1: How can this happen all of a sudden? no changes on box for last 5-6 weeks, nothing else running except RAC.
2. Error in /var/log/messages log file. RAC came down at 10:02, messges in the log file from 10:01, must be related. anyone know what they are? Looks like storage to me.
Jan 10 10:01:48 orcldub817 kernel: lpfc 0000:08:00.0: 0:(0):0713 SCSI layer issued Device Reset (0, 23) return x2002
Jan 10 10:02:17 orcldub817 kernel: INFO: task MpxPeriodicCall:28484 blocked for more than 120 seconds.
Jan 10 10:02:17 orcldub817 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jan 10 10:02:17 orcldub817 kernel: MpxPeriodicCa D ffffffff80151248     0 28484      1         28485 28483 (L-TLB)
Jan 10 10:02:17 orcldub817 kernel:  ffff810c0d8e78a0 0000000000000046 ffff810095560840 ffff810c2f7b14f8
Jan 10 10:02:17 orcldub817 kernel:  ffff810c2f7b1000 000000000000000a ffff810c28a96100 ffff81062fd6a100
Jan 10 10:02:17 orcldub817 kernel:  00267af542a39442 0000000000008106 ffff810c28a962e8 000000072e01a0c8
Jan 10 10:02:17 orcldub817 kernel: Call Trace:
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff80064167>] wait_for_completion+0x79/0xa2
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff8008e16d>] default_wake_function+0x0/0xe
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff801459cc>] blk_execute_rq_nowait+0x86/0x9a
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff80145a78>] blk_execute_rq+0x98/0xc0
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff8840b90d>] :emcp:emcp_scsi_cmd_ioctl+0x2ad/0x400
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff88412cb5>] :emcp:PowerPlatformBottomDispatch+0x3d5/0x760
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff884130d8>] :emcp:PowerSyncIoBottomDispatch+0x78/0xd0
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff88413626>] :emcp:PowerDispatchX+0x356/0x410
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff884147fd>] :emcp:EmsInquiry+0x9d/0x1a0
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff8863245a>] :emcpmpx:ClariionKLam_getPathLunStatus+0x8a/0x110
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff88622391>] :emcpmpx:MpxDefaultTestPath+0x21/0x80
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff88631bf3>] :emcpmpx:MpxLnxTestPath+0x43/0x270
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff800a1bad>] autoremove_wake_function+0x9/0x2e
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff8008c597>] __wake_up_common+0x3e/0x68
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff8002e511>] __wake_up+0x38/0x4f
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff88407e9e>] :emcp:PowerPutSema+0x4e/0x60
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff8006f1f5>] do_gettimeofday+0x40/0x90
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff8862a054>] :emcpmpx:MpxTestPath+0x234/0x1fc0
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff80063ff8>] thread_return+0x62/0xfe
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff8862e8cb>] :emcpmpx:MpxPeriodicTestPath+0x9b/0x230
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff8840e9c4>] :emcp:PowerTimeout+0x1a4/0x1e0
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff8006f1f5>] do_gettimeofday+0x40/0x90
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff8862ed5a>] :emcpmpx:MpxPeriodicCallout+0x2fa/0x410
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff8862ea60>] :emcpmpx:MpxPeriodicCallout+0x0/0x410
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff8841164d>] :emcp:PowerServiceDaemonQ+0xad/0xd0
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff8005efb1>] child_rip+0xa/0x11
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff88411670>] :emcp:PowerDaemonStart+0x0/0x20
Jan 10 10:02:17 orcldub817 kernel:  [<ffffffff8005efa7>] child_rip+0x0/0x11
Jan 10 10:02:17 orcldub817 kernel:
second node messages log has exact same...
Jan 10 10:01:48 orcldub818 kernel: lpfc 0000:08:00.0: 0:(0):0713 SCSI layer issued Device Reset (1, 23) return x2002
Jan 10 10:02:11 orcldub818 kernel: INFO: task MpxPeriodicCall:28298 blocked for more than 120 seconds.
Jan 10 10:02:11 orcldub818 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jan 10 10:02:11 orcldub818 kernel: MpxPeriodicCa D ffffffff80151248     0 28298      1         28299 28297 (L-TLB)
Jan 10 10:02:11 orcldub818 kernel:  ffff810626d7d8a0 0000000000000046 ffff8107adac6500 ffff810c2ff7e4f8
Jan 10 10:02:11 orcldub818 kernel:  ffff810c2ff7e000 000000000000000a ffff81062a2ad7a0 ffff81062fcf80c0
Jan 10 10:02:11 orcldub818 kernel:  00267d060c8f888d 000000000002ac41 ffff81062a2ad988 0000000676dd2cd8
..
..
and same messages as per node 1 above.
Edited by: 961469 on Jan 10, 2013 5:46 AM
  • 1. Re: RAC crashed - errors in messages log
    Dude! Guru
    Currently Being Moderated
    Why do you think it's a problem with kernel semaphores?

    There are 2 other issues that I suggest to look into first:

    SCSI layer issued Device Reset (0, 23)
    ORA-27301: OS failure message: No space left on device

    To me this looks like a hardware problem with your EMC storage

    Also please provide exact details about your OS version and system.
  • 2. Re: RAC crashed - errors in messages log
    User477708-OC Journeyer
    Currently Being Moderated
    Dude wrote:
    Why do you think it's a problem with kernel semaphores?

    There are 2 other issues that I suggest to look into first:

    SCSI layer issued Device Reset (0, 23)
    ORA-27301: OS failure message: No space left on device

    To me this looks like a hardware problem with your EMC storage

    Also please provide exact details about your OS version and system.
    See the errors in the ASM first of all. A few notes are thrown up when we look for those errors. Upping the semaphores resolved. My task now is to get to root cause.

    versions: x86_64 2.6.18-194.el5

    While increasing the semaphores resolved, I too think it looks like a problem with the storage as we get the same issue in the messages fil eon both nodes at same time.

    couple of things looking at ipcs that dont make sense
    [root@orcld818 proc]# ipcs -sa | wc -l
    242
    [root@orcl818 proc]# ipcs -sa
    ..
    ..
    242 listed - 
    0x45116b13 7241949    root      666        1         
    0x45116ab3 7274718    root      666        1         
    0x45116a13 7307487    root      666        1         
    0x45116a73 7340256    root      666        1         
    0x45116a93 7373025    root      666        1         
    0x45119ca9 7405794    root      666        1         
    0x451187f7 7438563    root      666        1      
    All those returned are root owned, this doesnt make sense to me, I thought there should be only a few listed owned by oracle

    If I try to identify any the processes associated with those, theres a PID listed, yet the pid doesnt exist when I try to query it e.g. the last one listed above...
    [root@orcl818 proc]# ipcs -i 7438563 -s
    
    Semaphore Array semid=7438563
    uid=0    gid=0   cuid=0  cgid=0
    mode=0666, access_perms=0666
    nsems = 1
    otime = Thu Jan 10 11:15:13 2013  
    ctime = Thu Jan 10 11:15:12 2013  
    semnum     value      ncount     zcount     pid       
    0          0          0          0          22922     
    
    [root@orcl818 proc]# ps -ef | grep 22922
    root     19611  9740  0 14:54 pts/2    00:00:00 grep 22922
    [root@orcl818 proc]# 
    
    [root@orcl818 proc]# ls /proc/22922
    ls: /proc/22922: No such file or directory
    [root@orcl818 proc]# 
  • 3. Re: RAC crashed - errors in messages log
    Dude! Guru
    Currently Being Moderated
    couple of things looking at ipcs that dont make sense
    Could it be you are using POSIX Shared Memory and Oracle Database Automatic Shared Memory (AMM)?

    In this case shared memory will be located in /dev/shm, which you can cd into and look around or see its usage using df -h
  • 4. Re: RAC crashed - errors in messages log
    User477708-OC Journeyer
    Currently Being Moderated
    ok, sorry, jsut discovered I had no oracle semaphores owned as I was running it on the inactive node of the 2 rac node. on the active node I have the oracle semaphores as expected but a couple of hundred other dead semaphores owned by root. ie, when I look at the pid owned by any of the root semaphores, its the same PID and the PID doesnt exist when I search for it with ps or in the /proc folder nor in the /dev/shm

    I do see all the used processes in /dev/shm but none for that PID
  • 5. Re: RAC crashed - errors in messages log
    Dude! Guru
    Currently Being Moderated
    A hardware failure, if it does not crash the system, may require a system restart to release screwed up resources. Do you have multipath or powerpath configured? You should be able to see problematic processes in the ps -ef output and search for e.g. process D states. The system will most likely not let you kill these process as they may break data integrity. I still think what you are seeing are the follow-up issues of an I/O disk error. If you can, restart the machine.
  • 6. Re: RAC crashed - errors in messages log
    User477708-OC Journeyer
    Currently Being Moderated
    We have a p1 opened with EMC on it as well. the semaphores were initially set to 128 as per default oracle settings, I set to 228 as per arups blog note seen earlier, rebooted, still wouldnt start. The count of semaphores was seen to be at 228 held by root. so I upped again to 288 and that was enough for it to start.

    The defunct semaphore count is hovering around the 240 mark. (its varying around that but not growing).

    We're going to remove the defunct ones with ipcsrm this evening. So now I need to find why those defunct processes are being created, as already noted, theyre all owned by the same defunct PID which I cant find. same on both nodes, and when we combine that with the errors in the messages log its pointing to something related, which is the storage hence the p1 with emc.
  • 7. Re: RAC crashed - errors in messages log
    Dude! Guru
    Currently Being Moderated
    So you're saying you restarted the system and cannot start the database?
  • 8. Re: RAC crashed - errors in messages log
    User477708-OC Journeyer
    Currently Being Moderated
    Dude wrote:
    So you're saying you restarted the system and cannot start the database?
    not when we bounced after upping the semaphores from 128 to 228, but could when I upped from 228 to 288. looking at the used sms count (ipcs -sa | wc -l) I can see the sms count is around 240 so 288 was enough for it to start after that. It probably needed just a few more to get it to start so 250 might have done it but I'm not changing anything else until tonight. Intraday and all that jazz.
  • 9. Re: RAC crashed - errors in messages log
    Dude! Guru
    Currently Being Moderated
    Well, I wish you would have have mentioned that in your initial post, because the situation wasn't obvious from what you posted.

    My question was, why do you have to modify kernel semaphores to bring up the database now?
    What changed that the previous kernel setting are no longer working?

    Here's the OL5 oracle-validated setting for kernel.sem:
    250 32000 100 142

    Perhaps you should compare your other kernel parameters to make sure there are set correctly.
  • 10. Re: RAC crashed - errors in messages log
    User477708-OC Journeyer
    Currently Being Moderated
    Dude wrote:
    Well, I wish you would have have mentioned that in your initial post, because the situation wasn't obvious from what you posted.

    My question was, why do you have to modify kernel semaphores to bring up the database now?
    What changed that the previous kernel setting are no longer working?

    Here's the OL5 oracle-validated setting for kernel.sem:
    250 32000 100 142

    Perhaps you should compare your other kernel parameters to make sure there are set correctly.
    my apologies, my first time looking at this stuff so Im learning exactly whats important and how to phrase.

    What changed? well really nothing that we can see. We've a pretty tight change process and nothing has changed in weeks. no drivers, no OS settings, kernel settings, software installs. The other kernel settings dont seem to affect it, its just that last semaphore setting. where you have 142, we had 128, worked fine for months, after the issue this morning, 128 was upped to 228 but as I described that wasnt enough either.
    I have a suspicion that rebooting after the changing the kernel to 228 meant that whatever process is spawning the defunct semaphores used all available up to 228, manually changing it to 288 then gave it some breathing space to start. We'll prove this later on tonight when bouncing the nodes. We still have yet to see what process is spawning the semaphores. as we only started getting this issue after getting the entries in the messages logs on both nodes at the same time, one would have to think its related to something common to both nodes. Storage.
  • 11. Re: RAC crashed - errors in messages log
    Dude! Guru
    Currently Being Moderated
    Btw, notice the correct calculation of the kernel.sem paramter:

    kern.sem represents SEMMSL, SEMMNS, SEMOPM, and SEMMNI, in that order.

    SEMMSL setting should be 10 plus the largest number of processes of an oracle instance.

    SEMMNS is the maximum number of semaphores, not semaphore sets, that can be allocated.
    It should be SEMMNS or (SEMMSL * SEMMNI), whichever is less.

    SEMMSL defines the maximum number of semaphore operations per system call and can be equal to SEMMSL

    SEMMNI defines the max number of semaphore sets.

    According to this if you increase your SEMMNI to 288, then SEMMNS should be 288 * 256 = 73728

    kern.sem = 256 73728 100 228

    For testing you can change the semaphore parameters of a running system:

    echo "256 73728 100 228" > /proc/sys/kernel/sem
  • 12. Re: RAC crashed - errors in messages log
    User477708-OC Journeyer
    Currently Being Moderated
    dude, thanks so much for your thoughts on this yesterday.

    Update, we rebooted the RAC last night and seen same behaviour, some process owned by root is using all available semaphores as specificed by SEMMNI so if we set it to 128 thats whats used, if we set it to 228, thats what used. The PID associated with those semaphores is the same one and when we try to find out what it is, nothing is returned.
    We can kill those semaphores with that redundant PID with an ipcrm script but we so far havent been able to find out what is generating it.

    We get the same problem on both nodes of the RAC. The only thing we have to go on is that first error encountered in the messages file on both nodes which is pointing at an emc problem but noone can say so far why that would cause the semaphore issue.

    Is there anyway to trace a redundant process to see where it came from?
  • 13. Re: RAC crashed - errors in messages log
    Dude! Guru
    Currently Being Moderated
    I think your dead root processes showing up semaphores could be from processes that were not shut down cleanly or programs that cause a memory leak. Semaphores just tell if a resource is busy or available.

    Perhaps the best way to find out is to see what starts up on your system that is not plain vanilla standard. Turn it off and gradually start things to see when the problem appears.

    You are not starting any Oracle processes as root are you?
  • 14. Re: RAC crashed - errors in messages log
    User477708-OC Journeyer
    Currently Being Moderated
    googling my little fingers off I think found the issue.

    http://jfsaucier.wordpress.com/2012/05/03/beware-of-the-semaphores/

    This describes us perfectly, we recently went to vmax which was the storage change 6 weeks ago. My one issue now is why did this only become an issue yesterday. The only thing I can think of is that we had done no other work on the vmax until earlier the day before when we allocated more luns from it to another server. But even after reading that note I cant see how that could have affected the RAC.

    Im going to do the count on the luns and paths and set the semaphores accordingly.
1 2 Previous Next

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points