Non-Blocking Checkpoints Appear to be Blocking

IDS 11.50.FC4X1 Running on AIX 5300-10. Physical Log size: 2GB Why would 11.50 touted non-blocking checkpoints be blocking on RTO checkpoint? I have stored procedures that normally run in 0.0580 seconds and logs show that during this checkpoint they lengthened out to max of 6.915 seconds. This time frame from our logs coincides exactly with the checkpoint listed below: 11:41:55 Checkpoint Completed: duration was 32 seconds. 11:41:55 Checkpoint Statistics - Avg. Txn Block Time 0.001, # Txns blocked 13, Plog used 107308, Llog used 193875 informix @ ibm46:/wic/log/informix: grep Checkpoint /wic/log/informix/message.020210 03:10:35 Checkpoint Completed: duration was 45 seconds. 03:10:35 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 92353, Llog used 205129 04:55:19 Checkpoint Completed: duration was 0 seconds. 04:55:19 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 51468, Llog used 119537 04:55:29 Checkpoint Completed: duration was 0 seconds. 04:55:29 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 556, Llog used 235 05:00:12 Checkpoint Completed: duration was 0 seconds. 05:00:12 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 683, Llog used 628 05:01:05 Checkpoint Completed: duration was 1 seconds. 05:01:05 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 193, Llog used 97 11:41:55 Checkpoint Completed: duration was 32 seconds. 11:41:55 Checkpoint Statistics - Avg. Txn Block Time 0.001, # Txns blocked 13, Plog used 107308, Llog used 193875 14:44:02 Checkpoint Completed: duration was 33 seconds. 14:44:02 Checkpoint Statistics - Avg. Txn Block Time 0.005, # Txns blocked 2, Plog used 81431, Llog used 211561 17:36:07 Checkpoint Completed: duration was 32 seconds. 17:36:07 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 4, Plog used 79542, Llog used 211501 20:46:23 Checkpoint Completed: duration was 25 seconds. 20:46:23 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 1, Plog used 46930, Llog used 228595 22:03:44 Checkpoint Completed: duration was 19 seconds. 22:03:44 Checkpoint Statistics - Avg. Txn Block Time 0.005, # Txns blocked 8, Plog used 69919, Llog used 219724 informix @ ibm46:/wic/log/informix: onstat -g ckp IBM Informix Dynamic Server Version 11.50.FC4X1 -- On-Line -- Up 76 days 06:34:36 -- 4496752 Kbytes AUTO_CKPTS=On RTO_SERVER_RESTART=60 seconds Estimated recovery time 21 seconds Critical Sections Physical Log Logical Log Clock Total Flush Block # Ckpt Wait Long # Dirty Dskflu Total Avg Total Avg Interval Time Trigger LSN Time Time Time Waits Time Time Time Buffers /Sec Pages /Sec Pages /Sec 100595 22:48:16 RTO 5257:0xf587018 12.6 12.5 0.0 5 0.0 0.1 0.1 59380 4749 58660 26 219019 99 100596 23:22:05 RTO 5260:0x116bc018 13.8 13.8 0.0 2 0.0 0.1 0.1 57247 4162 56585 27 223985 110 100597 23:58:52 RTO 5264:0x937018 16.7 16.6 0.0 2 0.0 0.0 0.1 63266 3806 62737 28 218204 99 100598 03:10:35 RTO 5266:0xfb82018 45.5 45.4 0.0 0 0.0 0.0 0.0 92849 2046 92353 8 205129 17 100599 04:55:19 *User 5268:0x9fed2ac 0.1 0.1 0.0 1 0.0 0.1 0.1 213 213 51468 8 119537 18 100600 04:55:29 *User 5268:0xa0d8018 0.1 0.0 0.0 1 0.0 0.1 0.1 226 226 556 55 235 23 100601 05:00:12 *User 5268:0xa34c428 0.1 0.0 0.0 1 0.0 0.1 0.1 182 182 683 2 628 2 100602 05:01:05 *Backup 5268:0xa3ad88c 0.1 0.1 0.0 0 0.0 0.0 0.0 356 356 193 3 97 1 100603 11:41:55 RTO 5271:0xc0aa018 32.2 31.7 0.0 13 0.0 0.2 0.4 94655 2982 107308 4 193875 8 100604 14:44:01 RTO 5274:0xb2d3018 33.7 33.6 0.0 2 0.0 0.0 0.0 86938 2588 81431 7 211561 19 100605 17:36:06 RTO 5277:0xa4f2018 32.3 32.3 0.0 4 0.0 0.0 0.0 85584 2653 79542 7 211501 20 100606 20:46:23 RTO 5280:0xda81018 25.2 25.1 0.0 1 0.0 0.0 0.0 53568 2137 46930 4 228595 20 100607 22:03:43 RTO 5283:0xe80a3f4 19.6 19.5 0.0 8 0.0 0.1 0.1 93680 4809 69919 15 219724 47 100608 02:33:50 RTO 5286:0x9544018 53.4 53.2 0.0 0 0.0 0.0 0.0 92451 1736 106508 6 193448 11 100609 04:55:12 *User 5286:0x10a3f018 0.2 0.1 0.0 1 0.0 0.2 0.2 173 173 26071 3 29947 3 100610 04:55:16 *User 5286:0x10a46018 0.0 0.0 0.0 1 0.0 0.0 0.0 0 0 6 1 7 1 100611 04:55:25 *User 5286:0x10b4a018 0.1 0.0 0.0 2 0.0 0.0 0.1 238 238 593 65 260 28 100612 05:00:12 *User 5286:0x10df6420 0.1 0.0 0.0 1 0.0 0.1 0.1 186 186 758 2 684 2 100613 05:01:05 *Backup 5286:0x10e4f018 0.1 0.1 0.0 0 0.0 0.0 0.0 352 352 189 3 89 1 100614 11:48:17 RTO 5289:0xc037018 31.2 30.5 0.0 17 0.0 0.4 0.7 89151 2923 109921 4 193749 7 Max Plog Max Llog Max Dskflush Avg Dskflush Avg Dirty Blocked pages/sec pages/sec Time pages/sec pages/sec Time 1228 1227 78 1594 0 0 Anybody have any tips on this?

Sorry to top post but I still haven't found a good way to post to the forum from work. From the onstat -g ckp output, all the RTO checkpoints are flagged as interval flushing (nonblocking for the flush) due to the lack of the "*". There are several blocking checkpoints, the "User" and "Backup" ones. The checkpoint statistics itself does show 13 txns did have to block but the avg block time was 0.001. Since the checkpoint duration itself was 32 seconds, if it was really blocking during the buffer pool flush I would expect that your stored procedures (at least 1 or some of them) would have come closer to matching the entire checkpoint duration, not just a fairly small portion of it (6.9 seconds out of 32). Could there be some other contention that would hold up the procedure from completing? Like a lock or maybe even IO? To really say for sure that it's the checkpoint blocking modifications, I'd really like to see onstat -u output showing users waiting on the checkpoint flag. I'd maybe start to collect onstat -u and onstat -g ath output that you can look at that would also coincide with the long stored procedure runnings to try and identify for sure what is holding the procedure up as the onstat -g ckp output you have doesn't indicate any transactions/users that were held up for nearly that long at all. I think the longest wait for that checkpoint was 0.4 seconds. So while it is certainly possible that checkpoint statistics could be incorrect, I would think it's also possible that it was something else that caused the stored procedures to run much longer then expected. Jacques Renaut IBM Informix Advanced Support APD team You wrote-------------------------------------------------------- IDS 11.50.FC4X1 Running on AIX 5300-10. Physical Log size: 2GB Why would 11.50 touted non-blocking checkpoints be blocking on RTO checkpoint? I have stored procedures that normally run in 0.0580 seconds and logs show that during this checkpoint they lengthened out to max of 6.915 seconds. This time frame from our logs coincides exactly with the checkpoint listed below: 11:41:55 Checkpoint Completed: duration was 32 seconds. 11:41:55 Checkpoint Statistics - Avg. Txn Block Time 0.001, # Txns blocked 13, Plog used 107308, Llog used 193875 <stuff deleted> AUTO_CKPTS=On RTO_SERVER_RESTART=60 seconds Estimated recovery time 21 seconds Critical Sections Physical Log Logical Log Clock Total Flush Block # Ckpt Wait Long # Dirty Dskflu Total Avg Total Avg Interval Time Trigger LSN Time Time Time Waits Time Time Time Buffers /Sec Pages /Sec Pages /Sec 100595 22:48:16 RTO 5257:0xf587018 12.6 12.5 0.0 5 0.0 0.1 0.1 59380 4749 58660 26 219019 99 100596 23:22:05 RTO 5260:0x116bc018 13.8 13.8 0.0 2 0.0 0.1 0.1 57247 4162 56585 27 223985 110 100597 23:58:52 RTO 5264:0x937018 16.7 16.6 0.0 2 0.0 0.0 0.1 63266 3806 62737 28 218204 99 100598 03:10:35 RTO 5266:0xfb82018 45.5 45.4 0.0 0 0.0 0.0 0.0 92849 2046 92353 8 205129 17 100599 04:55:19 *User 5268:0x9fed2ac 0.1 0.1 0.0 1 0.0 0.1 0.1 213 213 51468 8 119537 18 100600 04:55:29 *User 5268:0xa0d8018 0.1 0.0 0.0 1 0.0 0.1 0.1 226 226 556 55 235 23 100601 05:00:12 *User 5268:0xa34c428 0.1 0.0 0.0 1 0.0 0.1 0.1 182 182 683 2 628 2 100602 05:01:05 *Backup 5268:0xa3ad88c 0.1 0.1 0.0 0 0.0 0.0 0.0 356 356 193 3 97 1 100603 11:41:55 RTO 5271:0xc0aa018 32.2 31.7 0.0 13 0.0 0.2 0.4 94655 2982 107308 4 193875 8 100604 14:44:01 RTO 5274:0xb2d3018 33.7 33.6 0.0 2 0.0 0.0 0.0 86938 2588 81431 7 211561 19 100605 17:36:06 RTO 5277:0xa4f2018 32.3 32.3 0.0 4 0.0 0.0 0.0 85584 2653 79542 7 211501 20 <stuff deleted> Anybody have any tips on this?