Long checkpoint
User reported intermittent long checkpoints (87-184 seconds) on IDS 11.7FC on AIX 7, causing lock timeout errors. Expert suggested checking onstat -g ioh output to identify chunks with slow IO performance, noting that IO throughput during problem checkpoint was half normal rates. User planned to investigate further using IO diagnostics.
Auto-generated by DrWatson from the posts below — may be imperfect; read the full thread.
Hi iiug team,
May i ask your help on how can i trap or any utilities available to trap what
is causing the long checkpoint in my production db. It is running IDS 11.7FCx
in AIX 7. This doesn't happened before just started last month and it's not
consistently showing.
Here are the logs i gathered.
------Long transaction dates/time--------------------
11/23/15 19:44:31 Checkpoint Completed: duration was 184 seconds.
11/23/15 19:44:31 Checkpoint Statistics - Avg. Txn Block Time 177.825, # Txns
blocked 2874, Plog used 40786, Llog used 130992
11/29/15 19:32:52 Checkpoint Completed: duration was 125 seconds.
11/29/15 19:32:52 Checkpoint Statistics - Avg. Txn Block Time 120.736, # Txns
blocked 2010, Plog used 31231, Llog used 91712
12/02/15 19:21:31 Checkpoint Completed: duration was 87 seconds.
12/02/15 19:21:31 Checkpoint Statistics - Avg. Txn Block Time 86.223, # Txns
blocked 1433, Plog used 11267, Llog used 41602
12/09/15 19:12:13 Checkpoint Completed: duration was 142 seconds.
12/09/15 19:12:13 Checkpoint Statistics - Avg. Txn Block Time 138.812, # Txns
blocked 1667, Plog used 14930, Llog used 63975
2/09/15 19:12:10 Maximum server connections 6913
12/09/15 19:12:10 Checkpoint Statistics - Avg. Txn Block Time 0.002, # Txns
blocked 0, Plog used 23276, Llog used 0
--------------------onstat -g ckp -------------
This is what i gathered yesterday:take a look at Interval=485741 19:12:12
CKPTINTVL 532451:0x5bb5f3c 142.3 2.9 0.0 1667 138.8 28.9 139.3 25871 891514930 34 63975 145, it showed long transaction that caused the issue.
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
485734 18:34:48 CKPTINTVL 532439:0xa669018 0.2 0.2 0.0 1 0.0 0.0 0.0 29589
29589 17974 59 95597 318
485735 18:39:48 CKPTINTVL 532441:0x7fbc018 0.3 0.3 0.0 5 0.0 0.0 0.0 35788
35788 20912 69 92549 308
485736 18:44:49 CKPTINTVL 532443:0x3aaa018 0.3 0.2 0.0 1 0.0 0.0 0.0 30985
30985 17939 59 84788 281
485737 18:49:49 CKPTINTVL 532444:0xc78e018 0.3 0.2 0.0 2 0.0 0.0 0.0 29279
29279 17922 59 87309 291
485738 18:54:49 CKPTINTVL 532446:0xb8a6018 0.3 0.3 0.0 4 0.0 0.0 0.0 32786
32786 19972 66 98626 328
485739 18:59:50 CKPTINTVL 532448:0x660b018 0.5 0.4 0.0 2 0.0 0.0 0.0 29485
29485 18451 61 81282 270
485740 19:04:50 CKPTINTVL 532450:0x2caf018 0.3 0.3 0.0 2 0.0 0.0 0.0 38505
38505 21534 71 87862 292
485741 19:12:12 CKPTINTVL 532451:0x5bb5f3c 142.3 2.9 0.0 1667 138.8 28.9 139.3
25871 8915 14930 34 63975 145
485742 19:17:12 CKPTINTVL 532453:0x339e018 0.4 0.4 0.0 4 0.0 0.0 0.0 40501
40501 23867 78 92178 304
485743 19:22:13 CKPTINTVL 532454:0xbe8a018 0.2 0.2 0.0 7 0.0 0.0 0.0 30827
30827 18842 62 86823 288
485744 19:27:13 CKPTINTVL 532456:0x72ef018 0.3 0.2 0.0 4 0.0 0.0 0.0 31998
31998 19563 65 83159 277
485745 19:32:15 CKPTINTVL 532458:0x42fb018 0.3 0.3 0.0 3 0.0 0.0 0.0 33894
33894 19917 65 90149 298
485746 19:37:16 CKPTINTVL 532460:0x9baf658 0.3 0.3 0.0 5 0.0 0.0 0.0 37736
37736 22391 74 125239 416
485747 19:42:16 CKPTINTVL 532462:0x94c9018 0.3 0.2 0.0 5 0.0 0.0 0.0 34235
34235 20937 69 100705 335
485748 19:47:17 CKPTINTVL 532464:0x96c7344 0.4 0.3 0.0 9 0.0 0.0 0.0 41459
41459 23133 76 103005 342
485749 19:52:19 CKPTINTVL 532466:0x8e8f018 0.3 0.3 0.0 3 0.0 0.0 0.0 38774
38774 21404 70 100332 332
485750 19:57:19 CKPTINTVL 532468:0x5c48198 0.3 0.3 0.0 3 0.0 0.0 0.0 36308
36308 21244 70 89616 298
485751 20:02:19 CKPTINTVL 532470:0x3a78018 0.3 0.3 0.0 8 0.0 0.0 0.0 36139
36139 20656 68 93775 312
485752 20:07:20 CKPTINTVL 532471:0xa5c1c18 0.3 0.2 0.0 8 0.0 0.0 0.0 31932
31932 18548 61 78751 261
485753 20:12:21 CKPTINTVL 532473:0x7fb3018 0.3 0.3 0.0 1 0.0 0.0 0.0 38619
38619 21196 70 92707 307
Max Plog Max Llog Max Dskflush Avg Dskflush Avg Dirty Blocked
pages/sec pages/sec Time pages/sec pages/sec Time
6706 3688 7 42347 9 0
I didn't see any error message in DB log but long checkpoint shows it's
affecting the application, eventually had "ISAM error: Lock Timeout Expired".
Thanks in advance.
Ron
Look at the right side of the onstat -g ckp output. The IO/sec outputs are
half of what they are when the checkpoints are "normal". That's a clue.
Check your onstat -g ioh output around the time of the long checkpoint and
see what chunks are experiencing slow IO performance and start the tracking
from there. For now, you can try to shift some of the IO back towards more
idle writes and less checkpoint IO.
Art
Art S. Kagel, President and Principal Consultant
ASK Database Management
www.askdbmgt.com
Blog: http://informix-myview.blogspot.com/
Disclaimer: Please keep in mind that my own opinions are my own opinions
and do not reflect on the IIUG, nor any other organization with which I am
associated either explicitly, implicitly, or by inference. Neither do
those opinions reflect those of other individuals affiliated with any
entity with which I am affiliated nor those of the entities themselves.
On Wed, Dec 9, 2015 at 7:40 PM, RONALD OLAVIDEZ <ronald.olavidez@gmail.com>
wrote:
> Hi iiug team,
>
> May i ask your help on how can i trap or any utilities available to trap
> what
> is causing the long checkpoint in my production db. It is running IDS
> 11.7FCx
> in AIX 7. This doesn't happened before just started last month and it's not
> consistently showing.
>
> Here are the logs i gathered.
>
> ------Long transaction dates/time--------------------
>
> 11/23/15 19:44:31 Checkpoint Completed: duration was 184 seconds.
> 11/23/15 19:44:31 Checkpoint Statistics - Avg. Txn Block Time 177.825, #
> Txns
> blocked 2874, Plog used 40786, Llog used 130992
>
> 11/29/15 19:32:52 Checkpoint Completed: duration was 125 seconds.
> 11/29/15 19:32:52 Checkpoint Statistics - Avg. Txn Block Time 120.736, #
> Txns
> blocked 2010, Plog used 31231, Llog used 91712
>
> 12/02/15 19:21:31 Checkpoint Completed: duration was 87 seconds.
> 12/02/15 19:21:31 Checkpoint Statistics - Avg. Txn Block Time 86.223, #
> Txns
> blocked 1433, Plog used 11267, Llog used 41602
>
> 12/09/15 19:12:13 Checkpoint Completed: duration was 142 seconds.
> 12/09/15 19:12:13 Checkpoint Statistics - Avg. Txn Block Time 138.812, #
> Txns
> blocked 1667, Plog used 14930, Llog used 63975
>
> 2/09/15 19:12:10 Maximum server connections 6913
> 12/09/15 19:12:10 Checkpoint Statistics - Avg. Txn Block Time 0.002, # Txns
> blocked 0, Plog used 23276, Llog used 0
>
> --------------------onstat -g ckp -------------
>
> This is what i gathered yesterday:take a look at Interval=485741 19:12:12
> CKPTINTVL 532451:0x5bb5f3c 142.3 2.9 0.0 1667 138.8 28.9 139.3 25871 8915> 14930 34 63975 145, it showed long transaction that caused the issue.
>
> 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
> 485734 18:34:48 CKPTINTVL 532439:0xa669018 0.2 0.2 0.0 1 0.0 0.0 0.0 29589
> 29589 17974 59 95597 318
> 485735 18:39:48 CKPTINTVL 532441:0x7fbc018 0.3 0.3 0.0 5 0.0 0.0 0.0 35788
> 35788 20912 69 92549 308
> 485736 18:44:49 CKPTINTVL 532443:0x3aaa018 0.3 0.2 0.0 1 0.0 0.0 0.0 30985
> 30985 17939 59 84788 281
> 485737 18:49:49 CKPTINTVL 532444:0xc78e018 0.3 0.2 0.0 2 0.0 0.0 0.0 29279
> 29279 17922 59 87309 291
> 485738 18:54:49 CKPTINTVL 532446:0xb8a6018 0.3 0.3 0.0 4 0.0 0.0 0.0 32786
> 32786 19972 66 98626 328
> 485739 18:59:50 CKPTINTVL 532448:0x660b018 0.5 0.4 0.0 2 0.0 0.0 0.0 29485
> 29485 18451 61 81282 270
> 485740 19:04:50 CKPTINTVL 532450:0x2caf018 0.3 0.3 0.0 2 0.0 0.0 0.0 38505
> 38505 21534 71 87862 292
> 485741 19:12:12 CKPTINTVL 532451:0x5bb5f3c 142.3 2.9 0.0 1667 138.8 28.9
> 139.3
> 25871 8915 14930 34 63975 145
> 485742 19:17:12 CKPTINTVL 532453:0x339e018 0.4 0.4 0.0 4 0.0 0.0 0.0 40501
> 40501 23867 78 92178 304
> 485743 19:22:13 CKPTINTVL 532454:0xbe8a018 0.2 0.2 0.0 7 0.0 0.0 0.0 30827
> 30827 18842 62 86823 288
> 485744 19:27:13 CKPTINTVL 532456:0x72ef018 0.3 0.2 0.0 4 0.0 0.0 0.0 31998
> 31998 19563 65 83159 277
> 485745 19:32:15 CKPTINTVL 532458:0x42fb018 0.3 0.3 0.0 3 0.0 0.0 0.0 33894
> 33894 19917 65 90149 298
> 485746 19:37:16 CKPTINTVL 532460:0x9baf658 0.3 0.3 0.0 5 0.0 0.0 0.0 37736
> 37736 22391 74 125239 416
> 485747 19:42:16 CKPTINTVL 532462:0x94c9018 0.3 0.2 0.0 5 0.0 0.0 0.0 34235
> 34235 20937 69 100705 335
> 485748 19:47:17 CKPTINTVL 532464:0x96c7344 0.4 0.3 0.0 9 0.0 0.0 0.0 41459
> 41459 23133 76 103005 342
> 485749 19:52:19 CKPTINTVL 532466:0x8e8f018 0.3 0.3 0.0 3 0.0 0.0 0.0 38774
> 38774 21404 70 100332 332
> 485750 19:57:19 CKPTINTVL 532468:0x5c48198 0.3 0.3 0.0 3 0.0 0.0 0.0 36308
> 36308 21244 70 89616 298
> 485751 20:02:19 CKPTINTVL 532470:0x3a78018 0.3 0.3 0.0 8 0.0 0.0 0.0 36139
> 36139 20656 68 93775 312
> 485752 20:07:20 CKPTINTVL 532471:0xa5c1c18 0.3 0.2 0.0 8 0.0 0.0 0.0 31932
> 31932 18548 61 78751 261
> 485753 20:12:21 CKPTINTVL 532473:0x7fb3018 0.3 0.3 0.0 1 0.0 0.0 0.0 38619
> 38619 21196 70 92707 307
>
> Max Plog Max Llog Max Dskflush Avg Dskflush Avg Dirty Blocked
> pages/sec pages/sec Time pages/sec pages/sec Time
> 6706 3688 7 42347 9 0
>
> I didn't see any error message in DB log but long checkpoint shows it's
> affecting the application, eventually had "ISAM error: Lock Timeout
> Expired".
>
> Thanks in advance.
>
> Ron
>
>
>
>
*******************************************************************************
> Forum Note: Use "Reply" to post a response in the discussion forum.
>
>
--001a113eeaf43bce1105268101b8
Hi Art,
Thanks a lot for your suggestion. I'll check it out with my team if we can
have it running. btw, you mean "onstat -g iof" right? :)
This may take a week or two to capture what was causing that long checkpoint
but i'll post it here once we get the correct cause and solution.
Best,
Ron
No, onstat -g iof is fine, but if you have v12.10 there is a new onstat
report that is not well documented.
The iof report reports on averages since the stats were zero't out. The new
onstat -g ioh report reports on snapshot performance data taken everyminute and kept in memory for one hour, so it shows the last rolling 60
minutes of data. That is more accurate and can be correlated to events like
your long checkpoint. Here's a sample:
IBM Informix Dynamic Server Version 12.10.FC5W1 -- On-Line -- Up 7 days
08:17:31 -- 658908 Kbytes
AIO global files:
gfd pathname bytes read page reads bytes write page writes
io/s
3 rootdb.1.chunk 165507072 80814 107714560 52595
26.2
avg read avg write
time reads io/s op time writes io/s op time
21:37:16 1 0.0 0.01486 11 0.2 0.03587
21:36:16 0 0.0 0.00000 0 0.0 0.00000
21:35:16 0 0.0 0.00000 0 0.0 0.00000
21:34:16 0 0.0 0.00000 0 0.0 0.00000
21:33:16 0 0.0 0.00000 0 0.0 0.00000
21:32:16 2 0.0 0.01014 23 0.4 0.04940
21:31:16 0 0.0 0.00000 0 0.0 0.00000
21:30:16 1 0.0 0.00913 0 0.0 0.00000
21:29:16 0 0.0 0.00000 0 0.0 0.00000
21:28:16 0 0.0 0.00000 0 0.0 0.00000
21:27:16 1 0.0 0.00034 11 0.2 0.04143
21:26:16 0 0.0 0.00000 0 0.0 0.00000
21:25:16 0 0.0 0.00000 0 0.0 0.00000
21:24:16 0 0.0 0.00000 0 0.0 0.00000
21:23:16 0 0.0 0.00000 0 0.0 0.00000
21:22:16 3 0.1 0.00502 16 0.3 0.06193
21:21:16 0 0.0 0.00000 0 0.0 0.00000
21:20:16 0 0.0 0.00000 0 0.0 0.00000
21:19:16 0 0.0 0.00000 0 0.0 0.00000
21:18:16 0 0.0 0.00000 0 0.0 0.00000
21:17:16 0 0.0 0.00000 9 0.1 0.05993
21:16:16 0 0.0 0.00000 0 0.0 0.00000
21:15:16 0 0.0 0.00000 0 0.0 0.00000
21:14:16 0 0.0 0.00000 0 0.0 0.00000
21:13:16 0 0.0 0.00000 0 0.0 0.00000
21:12:16 0 0.0 0.00000 10 0.2 0.04532
21:11:16 0 0.0 0.00000 0 0.0 0.00000
21:10:16 0 0.0 0.00000 0 0.0 0.00000
21:09:16 0 0.0 0.00000 0 0.0 0.00000
21:08:16 1 0.0 0.02486 0 0.0 0.00000
21:07:16 1 0.0 0.00095 11 0.2 0.03938
21:06:16 0 0.0 0.00000 0 0.0 0.00000
21:05:16 0 0.0 0.00000 0 0.0 0.00000
21:04:16 0 0.0 0.00000 0 0.0 0.00000
21:03:16 0 0.0 0.00000 0 0.0 0.00000
21:02:16 0 0.0 0.00000 10 0.2 0.05415
21:01:16 0 0.0 0.00000 0 0.0 0.00000
21:00:16 0 0.0 0.00000 0 0.0 0.00000
20:59:16 0 0.0 0.00000 0 0.0 0.00000
20:58:16 0 0.0 0.00000 0 0.0 0.00000
20:57:16 0 0.0 0.00000 10 0.2 0.04224
20:56:16 0 0.0 0.00000 0 0.0 0.00000
20:55:16 0 0.0 0.00000 0 0.0 0.00000
20:54:16 0 0.0 0.00000 0 0.0 0.00000
20:53:16 0 0.0 0.00000 0 0.0 0.00000
20:52:16 1 0.0 0.05565 10 0.2 0.02850
20:51:16 0 0.0 0.00000 0 0.0 0.00000
20:50:16 0 0.0 0.00000 0 0.0 0.00000
20:49:16 0 0.0 0.00000 0 0.0 0.00000
20:48:16 0 0.0 0.00000 0 0.0 0.00000
20:47:16 0 0.0 0.00000 10 0.2 0.04617
20:46:16 0 0.0 0.00000 0 0.0 0.00000
20:45:16 0 0.0 0.00000 0 0.0 0.00000
20:44:16 0 0.0 0.00000 0 0.0 0.00000
20:43:16 0 0.0 0.00000 0 0.0 0.00000
20:42:16 1 0.0 0.02481 10 0.2 0.02892
...
Art S. Kagel, President and Principal Consultant
ASK Database Management
www.askdbmgt.com
Blog: http://informix-myview.blogspot.com/
Disclaimer: Please keep in mind that my own opinions are my own opinions
and do not reflect on the IIUG, nor any other organization with which I am
associated either explicitly, implicitly, or by inference. Neither do
those opinions reflect those of other individuals affiliated with any
entity with which I am affiliated nor those of the entities themselves.
On Wed, Dec 9, 2015 at 9:31 PM, RONALD OLAVIDEZ <ronald.olavidez@gmail.com>
wrote:
> Hi Art,
>
> Thanks a lot for your suggestion. I'll check it out with my team if we can
> have it running. btw, you mean "onstat -g iof" right? :)
>
> This may take a week or two to capture what was causing that long
> checkpoint
> but i'll post it here once we get the correct cause and solution.
>
> Best,
> Ron
>
>
>
>
*******************************************************************************
> Forum Note: Use "Reply" to post a response in the discussion forum.
>
>
--047d7bea3d28e8c1030526821df1
Thanks Art, we only have 11.7FCx. haven't used 12.10 yet but good to know
about 'onstat -g ioh'.
Regards,
Ron
A good start is to monitor 'onstat -F' continuously through the checkpoint.
This will show which chunks are being flushed during a checkpoint. A common
scenario is having everything waiting on a single chunk to flush towards the
end.
You can also monitor 'onstat -u' and check the flags on each thread. Ignore
stuff like 'Y--P---'. This may lead you to the SQL causing the problem.
Ben.
Related threads
- Posting from the Informix-list
- Migrating from IDS 9.40.UC6 to 11.50.UC3
- Ip for a network session
- questions onstat -g