wait for mutex ... IDS hang....

Hi, Folks, Build Version: 11.10.UC2 Build OS: AIX 5.3 We had IDS hang that seems caused by Waiting for Mutex. I attached some info and question embedded below. Hope experts can give some ideas. Thanks a lot! Frank (1) No waring info in Online log. (2) onstat -u's output informix@dora $ onstat -u IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days 03:00:54 -- 2120544 Kbytes Userthreads address flags sessid user tty wait tout locks nreads nwrites 90728018 ---P--D 1 informix - 0 0 0 2335 35670 907285d0 ---P--F 0 informix - 0 0 0 0 8807 90728b88 ---P--F 0 informix - 0 0 0 0 43922 90729140 ---P--F 0 informix - 0 0 0 0 43917 907296f8 ---P--F 0 informix - 0 0 0 0 43762 90729cb0 ---P--F 0 informix - 0 0 0 0 17686 9072a268 ---P--F 0 informix - 0 0 0 0 15684 9072a820 ---P--F 0 informix - 0 0 0 0 39372 9072add8 ---P--F 0 informix - 0 0 0 0 9174 9072b390 ---P--F 0 informix - 0 0 0 0 4 9072b948 ---P--F 0 informix - 0 0 0 0 8 9072bf00 ---P--F 0 informix - 0 0 0 0 12 9072c4b8 ---P--F 0 informix - 0 0 0 0 0 9072ca70 ---P--F 0 informix - 0 0 0 0 0 9072d028 ---P--F 0 informix - 0 0 0 0 0 9072d5e0 ---P--F 0 informix - 0 0 0 0 0 9072db98 ---P--F 0 informix - 0 0 0 0 0 9072e150 ---P--- 32 informix - 0 0 0 0 504 9072e708 ---P--B 33 informix - 0 0 0 19971 1024 9072ecc0 Y--P--- 132 informix - 925c4988 0 1 3 0 9072f278 Y--P--- 134 informix - 927333d8 0 1 8 1174 9072f830 S--P--D 37 informix - 407aa028 0 0 0 0 9072fde8 ---P--- 49 informix - 0 0 1 177 2 907303a0 ---P--- 44 informix - 0 0 0 0 0 90730958 Y--P--D 42 informix - 407f0570 0 0 0 0 90730f10 ---P--- 16 informix 0 0 0 1 0 0 907314c8 ---P--- 46 informix - 0 0 1 0 0 90731a80 Y--P--- 47 informix - 91aebf18 0 3 0 0 90732038 ---P--- 50 informix - 0 0 2 1633 3222 907325f0 ---P--- 51 informix - 0 0 2 5182 7282 90732ba8 S--P--- 52 informix - 407aa028 0 0 3 0 90733160 ---P--- 53 informix - 0 0 1 0 29216 90733718 ---P--- 54 informix - 0 0 1 0 28926 90733cd0 ---P--- 55 informix - 0 0 1 0 29470 90734288 ---P--- 56 informix - 0 0 1 0 28992 90734840 ---P--- 57 informix - 0 0 1 0 29242 90734df8 ---P--- 58 informix - 0 0 1 0 28488 907353b0 ---P--- 59 informix - 0 0 1 0 28808 90735968 ---P--- 60 informix - 0 0 1 0 29020 90735f20 ---P--- 62 informix - 0 0 0 12584 0 907364d8 ---P--- 133 informix - 0 0 0 0 6924 90736a90 ---P--- 64 informix - 0 0 1 230 0 90737048 Y--P--- 135 informix - 927333d8 0 1 40 1138 90737600 Y--P--- 136 informix - 925c4b28 0 1 0 0 90737bb8 Y--P--- 137 informix - 925c4b28 0 1 0 0 90738170 Y--P--- 138 informix - 925c4b28 0 1 0 0 90738728 Y--P--- 139 informix - 925c4b28 0 1 0 0 90738ce0 Y--P--- 140 informix - 925c4b28 0 1 0 0 90739298 Y--P--- 141 informix - 925c4b28 0 1 0 0 9073a978 Y--P--- 1044 saatmgr - 92d97f48 0 1 1 0 9073af30 Y--P--- 305 wwwmgr - 9283f648 0 1 10 0 9073c058 Y--P--- 79423 wwwmgr - 944fefb0 0 1 307 8 9073c610 Y--P--- 1051 saatmgr - 92c33f48 0 1 16 0 9073d180 Y--P--- 1021 saatmgr - 92ca0720 0 1 9 0 9073dcf0 ---PR-- 86754 informix 7 0 0 1 0 0 9073e860 S--P--- 86755 informix - 407aa028 0 0 0 0 9073ee18 Y--P--- 1760 saatmgr - 92f76d80 0 1 0 0 90744f50 ---P--- 86747 informix - 0 0 0 0 0 907471a0 Y--P--- 78168 saatmgr 1 92ca09a0 0 1 819 10 59 active, 128 total, 98 maximum concurrent (3) The session that are waiting for mutex, informix@dora $ onstat -g ses 52 IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days 03:01:45 -- 2120544 Kbytes informix@dora $ onstat -g ses 86755 IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days 03:01:52 -- 2120544 Kbytes session #RSAM total used dynamic id user tty pid hostname threads memory memory explain 86755 informix - 0 - 1 32768 28624 off tid name rstcb flags curstk status 73926 sqlexec 9073e860 S--P--- 3288 mutex wait(session) Memory pools count 1 name class addr totalsize freesize #allocfrag #freefrag 86755 V 914a3020 32768 4144 28 5 name free used name free used overhead 0 1664 scb 0 96 opentable 0 280 filetable 0 40 log 0 14096 gentcb 0 1216 ostcb 0 2736 sqscb 0 6656 sql 0 40 hashfiletab 0 280 sqtcb 0 1472 fragman 0 48 (4) mutex holder ??? it shows session 88852, but onstat -g ses 88852 shows nothing ( see below) informix@dora $ onstat -g lmx IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days 03:03:29 -- 2120544 Kbytes Locked mutexes: mid addr name holder lkcnt waiter waittime 13 407aa028 session 88852 0 13 48356 88609 48268 88607 48268 73925 47286 73927 47286 73926 47286 15 46301 86531 43079 84681 43079 91 40641 88399 35879 86532 35879 76 3216 1853 2355 1852 2355 1854 2355 1844 1475 1848 1475 1839 1475 Number of mutexes on VP free lists: 4323 informix@dora $ onstat -g ses 88852 IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days 03:04:46 -- 2120544 Kbytes (5) Strange session 73283 ??, which is not in output of "onstat -u" ( why?) host name shows as corrupted string!!! what is guy doing? what does "Changing data structure forced command termination." means? informix@dora $ onstat -g ses IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days 03:14:35 -- 2120544 Kbytes session #RSAM total used dynamic id user tty pid hostname threads memory memory explain 86755 informix - 0 - 1 32768 28624 off 86754 informix 7 733226 dora 1 491520 475944 off 86747 informix - 0 - 1 32768 28624 off 86514 saatmgr - 4800624 1 61440 14808 off 86487 saatmgr - 4800624 gilbert- 1 40960 12840 off 86305 wwwmgr - -1 gaston-d 1 28672 11840 off 84452 wwwmgr - -1 gaston-d 1 61440 13352 off 84451 wwwmgr - -1 gaston-d 1 28672 11840 off 82609 wwwmgr - -1 gaston-d 1 69632 13400 off 79423 wwwmgr - -1 isidore- 1 241664 178560 off 78168 saatmgr 1 2593168 gustav-d 1 90112 65000 off 73283 saatmgr - 4771938 ɧl"¸¹ 1 86016 17552 off 73282 saatmgr - 655606 gilbert- 1 65536 16224 off 73274 saatmgr - 4870234 1 65536 14968 off 1784 saatmgr - 4935712 gilbert- 1 40960 13008 off 1783 saatmgr - 397448 gilbert- 1 45056 12984 off 1782 saatmgr - 4714644 gilbert- 1 40960 12984 off 1777 saatmgr - 4604046 1 45056 13184 off 1774 saatmgr - 4616380 gilbert- 1 45056 13184 off 1763 saatmgr - 4784352 gilbert- 1 45056 13184 off 1760 saatmgr - 2806098 gaston-d 1 81920 61760 off 1051 saatmgr - 2101258 isaac-da 1 69632 52232 off 1044 saatmgr - 1822916 isabel-d 1 81920 61552 off 1021 saatmgr - 2601292 gustav-d 1 77824 61768 off 305 wwwmgr - -1 isidore- 1 73728 69704 off 131 informix - 0 - 0 12288 8584 off 51 informix - 0 - 1 270336 222272 off 50 informix - 0 - 1 364544 285192 off 49 informix - 0 - 1 208896 170320 off 16 informix 0 696542

Frank wrote: (4) mutex holder ??? it shows session 88852, but onstat -g ses 88852 shows nothing ( see below) informix@dora $ onstat -g lmx IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days 03:03:29 -- 2120544 Kbytes Locked mutexes: mid addr name holder lkcnt waiter waittime 13 407aa028 session 88852 0 13 48356 Response: The "88852" is not the session number for the holder of the mutex. It's the thread id, as is the waiter field. So instead of looking at onstat -g ses for that number, you need to look at onstat -g ath and get the matching thread id (first column output). Then take the value for the rstcb column from that onstat -g ath output and match that to the 1st column of the onstat -u output,and then use the session number from the onstat -u. You would probably also want to get onstat -g stk <thread id> output for the holder of the mutex. This looks like some sort of mutex deadlock, but onstat -g stk 88852 output along with onstat -g ses output for the correct session of the holder would probably help. Jacques Renaut IBM Informix Advanced Support APD Team

Thanks a lot Jacques!! I did the trace and found the session( see detail info_1 below). Its father process 733226 had already been stopped. But the session is still there and running... , onmode -z 86754 hangs., So the final solution is to reboot the IDS ? By the way, what does the "Changing data structure forced command termination." mean at the end of Info_2 below? Thanks, Frank ++++++++++++++++++++++++++ Info_1 ++++++++++++++++++++++++++++++ informix@dora $ onstat -g lmx IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days 04:12:29 -- 2120544 Kbytes Locked mutexes: mid addr name holder lkcnt waiter waittime 13 407aa028 session 88852 0 13 52496 88609 52408 88607 52408 73925 51426 73927 51426 73926 51426 15 50441 86531 47219 84681 47219 91 44781 88399 40019 86532 40019 76 7356 1853 6495 1852 6495 1854 6495 1844 5615 1848 5615 1839 5615 Number of mutexes on VP free lists: 4317 informix@dora $ onstat -g ath | grep 88852 88852 944b8168 9073dcf0 1 running 5cpu sqlexec informix@dora $ onstat -u | grep 9073dcf0 9073dcf0 ---PR-- 86754 informix 7 0 0 1 0 0 informix@dora $ onstat -g ses 86754 IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days 04:14:50 -- 2120544 Kbytes session #RSAM total used dynamic id user tty pid hostname threads memory memory explain 86754 informix 7 733226 dora 1 491520 475944 off tid name rstcb flags curstk status 88852 sqlexec 9073dcf0 ---PR-- 6248 running Memory pools count 2 name class addr totalsize freesize #allocfrag #freefrag 86754 V 93bea020 487424 13144 234 18 86754*O0 V 940fb020 4096 2432 1 1 name free used name free used overhead 0 3328 mtmisc 0 40 scb 0 96 opentable 0 5288 filetable 0 1016 log 0 14096 temprec 0 96840 keys 0 352 ralloc 0 317880 gentcb 0 1224 ostcb 0 2736 sqscb 0 15240 sql 0 40 rdahead 0 6208 hashfiletab 0 280 osenv 0 2344 buft_buffer 0 4184 sqtcb 0 3640 fragman 0 904 sapi 0 40 udr 0 128 sqscb info scb sqscb optofc pdqpriority sqlstats optcompind directives 945be060 93b33018 0 0 0 0 1 Sess SQL Current Iso Lock SQL ISAM F.E. Id Stmt type Database Lvl Mode ERR ERR Vers Explain 86754 SELECT sysmaster CR Not Wait 0 0 9.30 Off Current statement name : c_000000000 Current SQL statement : SELECT a.scs_sessionid, a.scs_currdb, a.scs_isolationlevel, a.scs_sqlstatement FROM syssqlcurses a where a.scs_sessionid <> DBINFO('sessionid') and length(a.scs_sqlstatement) >1 Last parsed SQL statement : SELECT a.scs_sessionid, a.scs_currdb, a.scs_isolationlevel, a.scs_sqlstatement FROM syssqlcurses a where a.scs_sessionid <> DBINFO('sessionid') and length(a.scs_sqlstatement) >1 informix@dora $ onstat -g stk 88852 IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days 04:16:35 -- 2120544 Kbytes Stack for thread: 88852 sqlexecbase: 0x93bb2000 len: 69632 pc: 0x1004b164 tos: 0x93bc1798 state: running vp: 5 0x00000000 ++++++++++++++++++++++++++++ info_2 ++++++++++++++++++++++++++++ IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days 04:33:24 -- 2120544 Kbytes session #RSAM total used dynamic id user tty pid hostname threads memory memory explain 73283 saatmgr - 4771938 ɧl"¸¹ 1 86016 17552 off tid name rstcb flags curstk status 73927 sqlexec 9073a3c0 S------ 3288 mutex wait(session) Memory pools count 2 name class addr totalsize freesize #allocfrag #freefrag 73283 V 93c33020 81920 66032 164 47 73283*O0 V 93beb020 4096 2432 1 1 name free used name free used overhead 0 3328 scb 0 96 gentcb 0 648 sqscb 0 10928 osenv 0 2456 sqtcb 0 96 sqscb info scb sqscb optofc pdqpriority sqlstats optcompind directives 932f0060 9337d018 0 0 0 0 1 Sess SQL Current Iso Lock SQL ISAM F.E. Id Stmt type Database Lvl Mode ERR ERR Vers Explain 73283 Ã2`'dÁ CR Wait 0 0 9.29 Off Changing data structure forced command termination. ++++++++++++++++++++++++++++++++++++++++++++++++++++++++ On Tue, Aug 17, 2010 at 1:51 PM, JACQUES RENAUT <jrenaut@us.ibm.com> wrote: > Frank wrote: > (4) mutex holder ??? it shows session 88852, but onstat -g ses 88852 shows > nothing ( see below) > > informix@dora $ onstat -g lmx > > IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days > 03:03:29 -- 2120544 Kbytes> > Locked mutexes: > mid addr name holder lkcnt waiter waittime > 13 407aa028 session 88852 0 13 48356 > > Response: > > The "88852" is not the session number for the holder of the mutex. It's the > thread id, as is the waiter field. So instead of looking at onstat -g ses > for > that number, you need to look at onstat -g ath and get the matching thread > id > (first column output). Then take the value for the rstcb column from that > onstat -g ath output and match that to the 1st column of the onstat -u > output,> and then use the session number from the onstat -u. You would probably also > want to get onstat -g stk <thread id> output for the holder of the mutex. > This > looks like some sort of mutex deadlock, but onstat -g stk 88852 output > along > with onstat -g ses output for the correct session of the holder would > probably > help. > > Jacques Renaut > IBM Informix Advanced Support > APD Team > > > > ******************************************************************************* > Forum Note: Use "Reply" to post a response in the discussion forum. > > --005045024396343cd3048e091d99

Frank wrote: Thanks a lot Jacques!! I did the trace and found the session( see detail info_1 below). Its father process 733226 had already been stopped. But the session is still there and running... , onmode -z 86754 hangs., So the final solution is to reboot the IDS ? By the way, what does the "Changing data structure forced command termination." mean at the end of Info_2 below? Thanks, Frank Response: If the server is hung, then unfortunately, unmode -z is very unlikely to work. I did see in your output that the thread that owned the mutex was running, which unfortunately means that onstat -g stk <thread id> won't work. It generally can't be used to get the stack of running threads, you'd have to get a debugger or some other unix utility to get a stack trace for the pid of the cpu vp that the sqlexec thread was running on. If you want to get more info about why it's hung, that's what you'd need to do. If you just want it running again, then yes, you'll most likely need to restart the instance. As for "Changing data structure" message from onstat, that is the output you get from onstat when it gets a signal (segv/bus error) when it's traversing memory structures and it would have core dumped otherwise. Since onstat doesn't lock any memory structures as it's looking at them, it can hit bad pointers if the memory structures are getting changed while it's looking at them, so the signal handler was put in place to report that message should a signal of those types happen, and then just terminate the onstat command. Jacques Renaut IBM Informix Advanced Support APD Team