11.50.FC9W3:Long checkpoint due to 2 sessions in c

Hello, I have problem which appears sporadically (~10 times this year) on some systems which our customers installs. Affected Informix is 11.50.FC9W3, SLES11 SP4. Behaviour is always same. Informix remains blocked in "CKPT REQ" state for long time (~4-12 hours) and is not accessible e.g. over dbaccess. I checked that checkpoint is waiting until some sessions leave critical section. What is strange is that both sessions are in critical section for read/write on same table (h_port) at same time. How it is possible? h_port table is locked with HDR+X by session 72802 which do delete from table. I cannot certainly identify which session entered critical section first, but I think from my observation that it is session 19340. If Linux process related to session 19340 is stopped, database immediatelly continue and finish checkpoint. oncheck output is fine for complete database. How can I continue with analysis? Thank you in advance. I can provide complete onstat -a output if anybody is interested in. onstat - IBM Informix Dynamic Server Version 11.50.FC9W3 -- On-Line (CKPT REQ) -- Up 5 days 00:25:17 -- 5213048 KbytesBlocked:CKPT hipath-man:/var/informix # onstat -u Userthreads address flags sessid user tty wait tout locks nreads nwrites ... 163390220 ---PX-- 72802 sad - 0 0 2 0 640 163390a78 ---PR-- 19340 sad - 0 0 1 0 0 ... hipath-man:/var/informix # onstat -g ses 72802 IBM Informix Dynamic Server Version 11.50.FC9W3 -- On-Line (CKPT REQ) -- Up 5 days 00:27:07 -- 5213048 KbytesBlocked:CKPT session effective #RSAM total used dynamic id user user tty pid hostname threads memory memory explain 72802 sad - - 18649 hipath-m 1 212992 206752 off Program : /opt/cm/sad/bin/uxsdbsyn tid name rstcb flags curstk status 73146 sqlexec 163390220 ---PX-- 11392 IO Wait- Memory pools count 2 name class addr totalsize freesize #allocfrag #freefrag 72802 V 16772b040 208896 5432 353 4 72802*O0 V 164db4040 4096 808 1 1 name free used name free used overhead 0 6576 scb 0 144 opentable 0 13344 filetable 0 3648 ru 0 600 log 0 16536 temprec 0 11424 keys 0 240 ralloc 0 98200 gentcb 0 1584 ostcb 0 2920 sqscb 0 26280 sql 0 72 rdahead 0 1120 hashfiletab 0 552 osenv 0 3040 sqtcb 0 9792 fragman 0 8896 udr 0 1784 sqscb info scb sqscb optofc pdqpriority optcompind directives 16622c050 165381028 0 0 1 1 Sess SQL Current Iso Lock SQL ISAM F.E. Id Stmt type Database Lvl Mode ERR ERR Vers Explain 72802 DELETE cdb NL Not Wait 0 0 9.37 Off Current SQL statement (2096) : delete from h_port where switch_name = ? and issue = ? and extension = ?; Host variables : address type flags value ----------------------------------------- 0x0000000165e47b60 CHAR 0x000 A002 0x0000000165e47bf0 CHAR 0x000 C 0x0000000165e47c80 CHAR 0x000 2286 Last parsed SQL statement : delete from h_port where switch_name = ? and issue = ? and extension = ?; 2072 byte(s) of memory is allocated from the sscpool hipath-man:/var/informix # onstat -g ses 19340 IBM Informix Dynamic Server Version 11.50.FC9W3 -- On-Line (CKPT REQ) -- Up 5 days 00:27:46 -- 5213048 KbytesBlocked:CKPT session effective #RSAM total used dynamic id user user tty pid hostname threads memory memory explain 19340 sad - - 18283 hipath-m 1 184320 161888 off Program : /opt/cm/sad/bin/umproxy tid name rstcb flags curstk status 19560 sqlexec 163390a78 ---PR-- 5568 running- Memory pools count 2 name class addr totalsize freesize #allocfrag #freefrag 19340 V 167af5040 180224 21624 272 9 19340*O0 V 165748040 4096 808 1 1 name free used name free used overhead 0 6576 scb 0 144 opentable 0 5064 filetable 0 1200 log 0 16536 temprec 0 13472 keys 0 1080 ralloc 0 66832 gentcb 0 1584 ostcb 0 2920 sort 0 104 sqscb 0 28000 sql 0 72 rdahead 0 1120 hashfiletab 0 552 osenv 0 3040 sqtcb 0 9304 fragman 0 4152 sapi 0 64 sqscb info scb sqscb optofc pdqpriority optcompind directives 1658110c0 165e24028 0 0 1 1 Sess SQL Current Iso Lock SQL ISAM F.E. Id Stmt type Database Lvl Mode ERR ERR Vers Explain 19340 SELECT cdb NL Not Wait 0 0 9.37 Off Current statement name : curs Current SQL statement (51815) : select um_operation_id from h_port where switch_name = "A002" and extension = "2286" and active = "A" Last parsed SQL statement : select um_operation_id from h_port where switch_name = "A002" and extension = "2286" and active = "A" Locks address wtlist owner lklist type tblsnum rowid key#/bsiz 478e4010 0 1633895a8 4835b410 HDR+X 1000f2 302 0 478e4090 0 163396640 4835ae10 HDR+IX 20015b 0 0 478e4110 0 16338aeb0 0 S 100002 207 0 478e4b90 0 163392bd8 0 S 100002 207 0 47c60d90 0 1633884f8 0 S 100002 206 0 47c60f10 0 16339a900 0 S 100002 207 0 47c60f90 0 163396e98 0 S 100002 207 0 47c61090 0 16339f418 47fdde90 HDR+IX 2000d0 0 0 47c61110 0 16339e368 0 S 100002 207 0 47c61810 0 163390220 47fdde10 HDR+X 2001b9 0 0 47fddb10 0 163388d50 0 S 100002 206 0 47fddb90 0 163393430 0 S 100002 207 0 47fddc10 0 16338c7b8 0 S 100002 207 0 47fdde10 0 163390220 0 S 100002 207 0 47fdde90 0 16339f418 0 S 100002 207 0 47fde310 0 16338f9c8 0 HDR+S 100002 201 0 47fde410 0 16338e0c0 0 S 100002 207 0 47fde990 0 16339b158 0 S 100002 207 0 47fdf710 0 16339db10 0 S 100002 207 0 4835a890 0 1633895a8 0 HDR+S 100002 206 0 4835a990 0 16339b9b0 0 S 100002 207 0 4835aa10 0 16338d010 0 S 100002 207 0 4835aa90 0 163390a78 0 S 100002 207 0 4835ad90 0 1633944e0 0 S 100002 207 0 4835ae10 0 163396640 0 S 100002 207 0 4835af90 0 163392380 0 HDR+S 100002 207 0 4835b410 0 1633895a8 4835a890 HDR+IX 1000f2 0 0 4835b490 0 16338d010 4835aa10 HDR+IX 2000c7 0 0 4835b510 0 16338d010 4835b490 HDR+X 2000c7 100 0 4835b690 0 16339f418 47c61090 HDR+X 2000d0 300 0 486d7710 0 163394d38 0 S 100002 207 0 486d7910 0 1633912d0 0 S 100002 207 0 486d7b90 0 16339fc70 0 S 100002 207 0 486d7c10 0 1633987a0 0 S 100002 207 0 486d7e90 0 1633a36d8 0 S 100002 207 0 486d8290 0 16338d868 0 S 100002 207 0 48a54390 0 163393c88 0 S 100002 207 0 48a54410 0 1633a04c8 0 S 100002 207 0 48a54510 0 163398ff8 0 S 100002 207 0 48a54910 0 163395590 0 S 100002 207 0 48a55090 0 16339ca60 0 S 100002 207 0 48dd1310 0 163399850 0 S 100002 207 0 48dd1490 0 16338f170 0 S 100002 207 0 48dd1590 0 16338e918 0 S 100002 207 0 44 active, 200000 total, 65536 hash buckets, 0 lock table overflows

Hi, I haven't got an answer to this one but I would look at what I/O activity is going on during your 8-12 hour period in which you're waiting for the thread to come out of critical section. Do you see waiting for buffers? In which case "onstat -X" might help, otherwise "onstat -g iof", "onstat -g ppf" or "onstat -u". Monitoring the I/O might give you clues as to what is happening. Are there any triggers to consider? Recently this defect became public which has similar symptoms but would require an insert to be happening: IT16125: INSTANCE CAN GET BLOCKED IN CHECKPOINT IF MAX_FILL_DATA_PAGES SET TO 1 AND CONCURRENT INSERTS OF 'LONG' ROWS OCCURS Ben.

Threads "look" for the chkpt flag before entering a critical section. Threads in a critical section get to finish and don't need to look for the ckpt flag. So these are getting stuck in a critical section and never come out, thus the chkpt wait/block. It used to be that there was a hard-limit on the number of pages a critical section could hold, but I don't know anymore. Both of the tables involved are in "non-logged" databases so iso level is dirty read for the select, and the delete is done as singletons. Regardless, this still looks like a deadly embrace. That's supported by the one process being killed (the delete I assume) and the engine moves along. It appears that the select is waiting on the delete but that makes no sense with DR. Looks like a bug to me. Mark Scranton The Mark Scranton Group mark@markscranton.com