Checkpoints slowing down the insert on Primary
A busy IDS 11.70 primary (with RSS and ER) saw insert throughput collapse for a second or two right after every checkpoint, which ran every ~5 minutes via CKPTINTVL. Advice was to switch from interval-driven checkpoints to RTO_SERVER_RESTART (1800) and check onstat -g ckp/vpcache; when tried, checkpoints fired every minute (heavy logical-log use: 195MB logs, one every 2-3 minutes) so it was rolled back. Another suggestion was that one chunk holding the hot indexes is cleaned by a single page cleaner, so active tables/indexes should be spread or fragmented across more dbspaces. The poster planned to isolate the busiest index (tqh_idx9) on its own dbspace; no confirmed resolution is recorded.
Auto-generated by DrWatson from the posts below — may be imperfect; read the full thread.
Hello,
In our production environment (IDS 11.70.FC5X7) on
uname -a
SunOS Generic_147441-07 i86pc i386 i86pc
we are experiecing issues whenever checkpoints happen. Below is the checkpoint
info and number of records per second in the table. I notice whenever
checkpoint finishes, database only manages to add 100 records per second for
next couple of milliseconds. 100 is also the batch size at the app level.
Similar behaviour is observed with a different table where the batch size is
1, I see 1 record per millisecond after checkpoint is over.
03/18/14 09:29:13 Checkpoint Completed: duration was 5 seconds.
03/18/14 09:34:16 Checkpoint Completed: duration was 3 seconds.
03/18/14 09:39:20 Checkpoint Completed: duration was 3 seconds.
03/18/14 09:44:26 Checkpoint Completed: duration was 3 seconds.
03/18/14 09:49:32 Checkpoint Completed: duration was 5 seconds.
03/18/14 09:54:39 Checkpoint Completed: duration was 3 seconds.
03/18/14 09:59:44 Checkpoint Completed: duration was 3 seconds.
09:39:00|1559.0|
09:39:01|1554.0|
09:39:02|1793.0|
09:39:03|1682.0|
09:39:04|1127.0|
09:39:05|946.0|
09:39:06|1395.0|
09:39:07|863.0|
09:39:08|836.0|
09:39:09|1029.0|
09:39:10|1108.0|
09:39:11|1047.0|
09:39:12|1601.0|
09:39:13|1021.0|
09:39:14|1132.0|
09:39:15|1183.0|
09:39:16|1226.0|
09:39:17|1145.0|
09:39:18|1053.0|
09:39:19|889.0|
09:39:20|535.0|
09:39:22|100.0|
09:39:24|100.0|
09:39:26|1900.0|
09:39:27|3234.0|
09:39:28|666.0|
.....
09:44:12|1381.0|
09:44:13|1656.0|
09:44:14|1330.0|
09:44:15|770.0|
09:44:16|822.0|
09:44:17|827.0|
09:44:18|1681.0|
09:44:19|1461.0|
09:44:20|1288.0|
09:44:21|1157.0|
09:44:22|724.0|
09:44:23|912.0|
09:44:24|911.0|
09:44:25|786.0|
09:44:27|100.0|
09:44:29|300.0|
09:44:30|1000.0|
09:44:31|1779.0|
09:44:32|2463.0|
09:44:33|1334.0|
09:44:34|1146.0|
...
09:49:25|835.0|
09:49:26|1366.0|
09:49:27|735.0|
09:49:28|858.0|
09:49:29|854.0|
09:49:30|1022.0|
09:49:32|100.0|
09:49:34|100.0|
09:49:35|3300.0|
09:49:36|2791.0|
09:49:37|754.0|
09:49:38|803.0|
09:49:39|806.0|
The instance has a RSS (async) connected and also some of the tables are ER to
a different instance. Below are some of the onconfig variables
LOGFILES 90
LOGSIZE 1000
DYNAMIC_LOGS 2
LOGBUFF 256
CKPTINTVL 300AUTO_CKPTS 1
RTO_SERVER_RESTART 0
BLOCKTIMEOUT 3600
BUFFERPOOL
size=2K,buffers=5000000,lrus=64,lru_min_dirty=0.50,lru_max_dirty=1.50
AUTO_LRU_TUNING 1
Please suggest what can be the reason of slowing down of engine after the
checkpoint completes.
regards,
Nitin
Hello. A good starting point to your checkpoint perfomance investigation,
would be the output of onstat -g ckp command, could you post it here?
Regards.
Alexandre Marini
IBM Informix Certified Professional v10 / v11.50 / v11.70 / v12.10
IBM Information Management Informix Technical Professional
IBM Infosphere DataStage Technical Professional
Informix Senior DBA - Orizon Brasil
BRIUG website administrator
Informix independent consultant
> To: ids@iiug.org
> From: nitin_maths@rediffmail.com
> Subject: Checkpoints slowing down the insert on Primary [32735]
> Date: Tue, 18 Mar 2014 12:01:01 -0400
>
> Hello,
>
> In our production environment (IDS 11.70.FC5X7) on
> uname -a
> SunOS Generic_147441-07 i86pc i386 i86pc
>
> we are experiecing issues whenever checkpoints happen. Below is the
checkpoint
> info and number of records per second in the table. I notice whenever
> checkpoint finishes, database only manages to add 100 records per second for
> next couple of milliseconds. 100 is also the batch size at the app level.
> Similar behaviour is observed with a different table where the batch size is
> 1, I see 1 record per millisecond after checkpoint is over.
>
> 03/18/14 09:29:13 Checkpoint Completed: duration was 5 seconds.
> 03/18/14 09:34:16 Checkpoint Completed: duration was 3 seconds.
> 03/18/14 09:39:20 Checkpoint Completed: duration was 3 seconds.
> 03/18/14 09:44:26 Checkpoint Completed: duration was 3 seconds.
> 03/18/14 09:49:32 Checkpoint Completed: duration was 5 seconds.
> 03/18/14 09:54:39 Checkpoint Completed: duration was 3 seconds.
> 03/18/14 09:59:44 Checkpoint Completed: duration was 3 seconds.
>
> 09:39:00|1559.0|
> 09:39:01|1554.0|
> 09:39:02|1793.0|
> 09:39:03|1682.0|
> 09:39:04|1127.0|
> 09:39:05|946.0|
> 09:39:06|1395.0|
> 09:39:07|863.0|
> 09:39:08|836.0|
> 09:39:09|1029.0|
> 09:39:10|1108.0|
> 09:39:11|1047.0|
> 09:39:12|1601.0|
> 09:39:13|1021.0|
> 09:39:14|1132.0|
> 09:39:15|1183.0|
> 09:39:16|1226.0|
> 09:39:17|1145.0|
> 09:39:18|1053.0|
> 09:39:19|889.0|
> 09:39:20|535.0|
> 09:39:22|100.0|
> 09:39:24|100.0|
> 09:39:26|1900.0|
> 09:39:27|3234.0|
> 09:39:28|666.0|
> ......
> 09:44:12|1381.0|
> 09:44:13|1656.0|
> 09:44:14|1330.0|
> 09:44:15|770.0|
> 09:44:16|822.0|
> 09:44:17|827.0|
> 09:44:18|1681.0|
> 09:44:19|1461.0|
> 09:44:20|1288.0|
> 09:44:21|1157.0|
> 09:44:22|724.0|
> 09:44:23|912.0|
> 09:44:24|911.0|
> 09:44:25|786.0|
> 09:44:27|100.0|
> 09:44:29|300.0|
> 09:44:30|1000.0|
> 09:44:31|1779.0|
> 09:44:32|2463.0|
> 09:44:33|1334.0|
> 09:44:34|1146.0|
> ....
> 09:49:25|835.0|
> 09:49:26|1366.0|
> 09:49:27|735.0|
> 09:49:28|858.0|
> 09:49:29|854.0|
> 09:49:30|1022.0|
> 09:49:32|100.0|
> 09:49:34|100.0|
> 09:49:35|3300.0|
> 09:49:36|2791.0|
> 09:49:37|754.0|
> 09:49:38|803.0|
> 09:49:39|806.0|
>
> The instance has a RSS (async) connected and also some of the tables are ER
to
> a different instance. Below are some of the onconfig variables
>
> LOGFILES 90
> LOGSIZE 1000
> DYNAMIC_LOGS 2
> LOGBUFF 256
> CKPTINTVL 300> AUTO_CKPTS 1
> RTO_SERVER_RESTART 0
> BLOCKTIMEOUT 3600
> BUFFERPOOL
> size=2K,buffers=5000000,lrus=64,lru_min_dirty=0.50,lru_max_dirty=1.50
> AUTO_LRU_TUNING 1>
> Please suggest what can be the reason of slowing down of engine after the
> checkpoint completes.
>
> regards,
> Nitin
>
>
>
*******************************************************************************
> Forum Note: Use "Reply" to post a response in the discussion forum.
>
Sorry, I thought about it and forgot to add.
IBM Informix Dynamic Server Version 11.70.FC5X7 -- On-Line (Prim) -- Up 10
days 00:09:33 -- 36404224 Kbytes
AUTO_CKPTS=On RTO_SERVER_RESTART=Off
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
185855 08:18:16 CKPTINTVL 98816:0x5ca0018 1.9 1.9 0.0 0 0.0 0.0 0.0 51112
26793 18470 61 92921 307
185856 08:23:20 CKPTINTVL 98817:0x2658018 4.5 4.4 0.0 0 0.0 0.0 0.0 49147
11064 18821 62 87204 289
185857 08:28:22 CKPTINTVL 98818:0x1e9c018 2.0 2.0 0.0 0 0.0 0.0 0.0 51443
25725 17939 59 98884 325
185858 08:33:26 CKPTINTVL 98819:0xe5874e8 4.7 4.7 0.0 1 0.0 0.0 0.0 48898
10379 42451 140 152687 505
185859 08:38:32 CKPTINTVL 98820:0x12271018 4.3 4.2 0.0 1 0.0 0.0 0.0 62287
14774 23154 75 116821 381
185860 08:43:35 CKPTINTVL 98821:0x17bc0018 3.5 3.4 0.0 0 0.0 0.0 0.0 62591
18215 30176 99 124453 409
185861 08:48:39 CKPTINTVL 98823:0x46f5018 3.0 3.0 0.0 1 0.0 0.0 0.0 65737
21981 24324 80 122102 401
185862 08:53:42 CKPTINTVL 98824:0xeb22470 3.1 3.1 0.0 1 0.0 0.0 0.0 65485
21238 25418 83 143792 474
185863 08:58:47 CKPTINTVL 98825:0x163ae018 3.1 3.1 0.0 1 0.0 0.0 0.0 65762
21475 22345 73 131980 432
185864 09:03:52 CKPTINTVL 98827:0x86db018 5.5 5.5 0.0 1 0.0 0.0 0.0 51727 9396
27646 91 145299 479
185865 09:08:59 CKPTINTVL 98828:0x10986018 5.1 5.1 0.0 1 0.0 0.0 0.0 69155
13663 26038 84 135209 440
185866 09:14:02 CKPTINTVL 98829:0x183c7018 3.3 3.3 0.0 1 0.0 0.0 0.0 70003
21282 28833 94 132456 434
185867 09:19:05 CKPTINTVL 98831:0x692d018 3.8 3.8 0.0 1 0.0 0.0 0.0 66942
17755 27606 91 128707 424
185868 09:24:07 CKPTINTVL 98832:0xe6ba018 2.9 2.9 0.0 0 0.0 0.0 0.0 69358
23798 28789 95 133520 440
185869 09:29:12 CKPTINTVL 98834:0x159018 5.3 5.3 0.0 2 0.0 0.0 0.0 70586 13300
27445 90 143522 475
185870 09:34:15 CKPTINTVL 98836:0x11109018 3.9 3.9 0.0 3 0.0 0.0 0.0 65929
16945 64942 212 271300 889
185871 09:39:20 CKPTINTVL 98838:0x17823018 3.2 3.1 0.0 3 0.0 0.1 0.1 61311
19690 38871 127 228144 748
185872 09:44:25 CKPTINTVL 98841:0x1193018 3.3 3.2 0.0 1 0.0 0.0 0.0 54812
16913 38254 125 209929 688
185873 09:49:32 CKPTINTVL 98843:0x2bd6018 5.0 5.0 0.0 1 0.0 0.0 0.0 51866
10418 35486 116 208526 683
185874 09:54:38 CKPTINTVL 98845:0x4058018 3.6 3.5 0.0 1 0.0 0.0 0.0 51728
14739 36368 118 207003 672
Max Plog Max Llog Max Dskflush Avg Dskflush Avg Dirty Blocked
pages/sec pages/sec Time pages/sec pages/sec Time
13235 9809 71 3491 0 0
Ok the first thing I´d suggest: activate RTO, instead of using the old feature
of frequent checkpoints.
Do it and also increase the default value of memory cache for cpu vps.
That should let the engine run itself, and runs a checkpoint everytime it
need, in order to complete the specified RTO policy. I should go for 1800, the
maximum allowed value.
Frequent checkpoints are good for non data loss ensurance, but the engine is
keeping running with a step on the brakes, every X minutes... let it run by
itself. It´s an usual way to start to boost your performance, in a general
way. You might see your cpu vps memory caches through onstat -g vpcache report.
After that, you might see some recommendations through onstat -g ckp report,
you should follow them in order to grow your RTO policy needs.
Regards.
Alexandre Marini
IBM Informix Certified Professional v10 / v11.50 / v11.70 / v12.10
IBM Information Management Informix Technical Professional
IBM Infosphere DataStage Technical Professional
Informix Senior DBA - Orizon Brasil
BRIUG website administrator
Informix independent consultant
> To: ids@iiug.org
> From: nitin_maths@rediffmail.com
> Subject: Re: RE: Checkpoints slowing down the insert on.... [32738]
> Date: Tue, 18 Mar 2014 14:25:05 -0400
>
> Sorry, I thought about it and forgot to add.
>
> IBM Informix Dynamic Server Version 11.70.FC5X7 -- On-Line (Prim) -- Up 10
> days 00:09:33 -- 36404224 Kbytes
>
> AUTO_CKPTS=On RTO_SERVER_RESTART=Off>
> 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
> 185855 08:18:16 CKPTINTVL 98816:0x5ca0018 1.9 1.9 0.0 0 0.0 0.0 0.0 51112
> 26793 18470 61 92921 307
> 185856 08:23:20 CKPTINTVL 98817:0x2658018 4.5 4.4 0.0 0 0.0 0.0 0.0 49147
> 11064 18821 62 87204 289
> 185857 08:28:22 CKPTINTVL 98818:0x1e9c018 2.0 2.0 0.0 0 0.0 0.0 0.0 51443
> 25725 17939 59 98884 325
> 185858 08:33:26 CKPTINTVL 98819:0xe5874e8 4.7 4.7 0.0 1 0.0 0.0 0.0 48898
> 10379 42451 140 152687 505
> 185859 08:38:32 CKPTINTVL 98820:0x12271018 4.3 4.2 0.0 1 0.0 0.0 0.0 62287
> 14774 23154 75 116821 381
> 185860 08:43:35 CKPTINTVL 98821:0x17bc0018 3.5 3.4 0.0 0 0.0 0.0 0.0 62591
> 18215 30176 99 124453 409
> 185861 08:48:39 CKPTINTVL 98823:0x46f5018 3.0 3.0 0.0 1 0.0 0.0 0.0 65737
> 21981 24324 80 122102 401
> 185862 08:53:42 CKPTINTVL 98824:0xeb22470 3.1 3.1 0.0 1 0.0 0.0 0.0 65485
> 21238 25418 83 143792 474
> 185863 08:58:47 CKPTINTVL 98825:0x163ae018 3.1 3.1 0.0 1 0.0 0.0 0.0 65762
> 21475 22345 73 131980 432
> 185864 09:03:52 CKPTINTVL 98827:0x86db018 5.5 5.5 0.0 1 0.0 0.0 0.0 51727
9396
> 27646 91 145299 479
> 185865 09:08:59 CKPTINTVL 98828:0x10986018 5.1 5.1 0.0 1 0.0 0.0 0.0 69155
> 13663 26038 84 135209 440
> 185866 09:14:02 CKPTINTVL 98829:0x183c7018 3.3 3.3 0.0 1 0.0 0.0 0.0 70003
> 21282 28833 94 132456 434
> 185867 09:19:05 CKPTINTVL 98831:0x692d018 3.8 3.8 0.0 1 0.0 0.0 0.0 66942
> 17755 27606 91 128707 424
> 185868 09:24:07 CKPTINTVL 98832:0xe6ba018 2.9 2.9 0.0 0 0.0 0.0 0.0 69358
> 23798 28789 95 133520 440
> 185869 09:29:12 CKPTINTVL 98834:0x159018 5.3 5.3 0.0 2 0.0 0.0 0.0 70586
13300
> 27445 90 143522 475
> 185870 09:34:15 CKPTINTVL 98836:0x11109018 3.9 3.9 0.0 3 0.0 0.0 0.0 65929
> 16945 64942 212 271300 889
> 185871 09:39:20 CKPTINTVL 98838:0x17823018 3.2 3.1 0.0 3 0.0 0.1 0.1 61311
> 19690 38871 127 228144 748
> 185872 09:44:25 CKPTINTVL 98841:0x1193018 3.3 3.2 0.0 1 0.0 0.0 0.0 54812
> 16913 38254 125 209929 688
> 185873 09:49:32 CKPTINTVL 98843:0x2bd6018 5.0 5.0 0.0 1 0.0 0.0 0.0 51866
> 10418 35486 116 208526 683
> 185874 09:54:38 CKPTINTVL 98845:0x4058018 3.6 3.5 0.0 1 0.0 0.0 0.0 51728
> 14739 36368 118 207003 672
>
> Max Plog Max Llog Max Dskflush Avg Dskflush Avg Dirty Blocked
> pages/sec pages/sec Time pages/sec pages/sec Time
> 13235 9809 71 3491 0 0
>
>
>
*******************************************************************************
> Forum Note: Use "Reply" to post a response in the discussion forum.
>
Hi Alexandre,
Finally managed to make the changes to the instance with
RTO_SERVER_RESTART=1800, but that started triggered checkpoints every 1 minute
so we quickly rolled back the change. Please see below.
What do we do next?
romeo502.prod.otc(informix)$ onstat -g ckp
IBM Informix Dynamic Server Version 11.70.FC5X7 -- On-Line -- Up 3 days
22:11:13 -- 45767680 Kbytes
AUTO_CKPTS=On RTO_SERVER_RESTART=Off
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
191060 07:49:49 RTO 100496:0x154441cc 1.2 1.1 0.0 1 0.0 0.0 0.0 24696 21611
18463 184 19528 195
191061 07:50:56 RTO 100497:0x17947d4 2.2 2.2 0.0 1 0.0 0.0 0.0 29144 13426
22913 347 18968 287
191062 07:51:23 RTO 100497:0x61a2018 2.3 2.3 0.0 0 0.0 0.0 0.0 31618 13658
24920 922 19645 727
191063 07:52:34 RTO 100497:0xb044018 1.2 1.2 0.0 1 0.0 0.0 0.0 22556 19249
15475 214 20273 281
191064 07:53:49 RTO 100497:0x10256018 0.9 0.9 0.0 0 0.0 0.0 0.0 22227 22227
14750 194 21143 278
191065 07:55:05 RTO 100497:0x152d6018 1.6 1.6 0.0 0 0.0 0.0 0.0 32040 20069
24772 330 21851 291
191066 07:56:28 RTO 100498:0x1cf8018 2.7 2.7 0.0 0 0.0 0.0 0.0 21706 8151
14605 178 21146 257
191067 07:57:44 RTO 100498:0x69a0018 1.7 1.7 0.0 0 0.0 0.0 0.0 22984 13857
16180 210 20083 260
191068 07:58:55 RTO 100498:0xb89b3e8 1.4 1.4 0.0 1 0.0 0.0 0.0 23107 16283
16123 227 21316 300
191069 08:00:12 RTO 100498:0x1128c018 2.2 2.2 0.0 1 0.0 0.0 0.0 24548 11241
16434 216 23644 311
191070 08:01:23 RTO 100498:0x1603f018 1.7 1.7 0.0 0 0.0 0.0 0.0 25109 14705
18267 253 20316 282
191071 08:02:39 RTO 100499:0x293b018 1.9 1.9 0.0 1 0.0 0.0 0.0 23384 12335
16341 215 21160 278
191072 08:03:54 RTO 100499:0x7883018 0.8 0.8 0.0 0 0.0 0.0 0.0 22108 22108
15040 197 20683 272
191073 08:05:15 RTO 100499:0xc7c6018 1.4 1.4 0.0 0 0.0 0.0 0.0 22657 16422
15608 195 20554 256
191074 08:06:32 RTO 100499:0x11715484 2.1 2.1 0.0 1 0.0 0.0 0.0 30283 14538
23421 308 21005 276
191075 08:07:34 RTO 100499:0x1654a018 2.1 2.1 0.0 0 0.0 0.0 0.0 30261 14731
23505 379 20743 334
191076 08:08:45 RTO 100500:0x2ac3018 1.1 0.8 0.0 0 0.0 0.0 0.0 23374 23374
16611 230 19767 274
191077 08:09:55 RTO 100500:0x7784018 1.0 0.8 0.0 0 0.0 0.0 0.0 23232 23232
16420 231 19850 279
191078 08:11:06 RTO 100500:0xc5e8018 1.6 1.5 0.0 0 0.0 0.0 0.0 26252 16997
19474 278 20332 290
191079 08:21:32 CKPTINTVL 100502:0x148dc018 1.3 1.2 0.0 1 0.0 0.0 0.0 25112
20303 50337 80 233813 373
Max Plog Max Llog Max Dskflush Avg Dskflush Avg Dirty Blocked
pages/sec pages/sec Time pages/sec pages/sec Time
24777 87963 76 4610 2 0
regards,
Nitin
Hello.
Are you sure your "onstat -g ckp" output was generated after activating the
RTO policy?
Your ouput header says it is turned off:
AUTO_CKPTS=On RTO_SERVER_RESTART=Off What is the size/ammount of your
logical-log files?
That must be causing your engine to run a checkpoint so frequently, and might
not be any warning in onstat -g ckp for incresing them.
Can you post your online.log lines saying that RTO is activated?
Please provide any additional information, for a further analysis.
Regards.
Alexandre Marini
IBM Informix Certified Professional v10 / v11.50 / v11.70 / v12.10
IBM Information Management Informix Technical Professional
IBM Infosphere DataStage Technical Professional
Informix Senior DBA - Orizon Brasil
BRIUG website administrator
Informix independent consultant
> To: ids@iiug.org
> From: nitin_maths@rediffmail.com
> Subject: Re: RE: Checkpoints slowing down the insert on.... [32848]
> Date: Wed, 2 Apr 2014 10:25:00 -0400
>
> Hi Alexandre,
>
> Finally managed to make the changes to the instance with
> RTO_SERVER_RESTART=1800, but that started triggered checkpoints every 1
minute
> so we quickly rolled back the change. Please see below.
>
> What do we do next?
>
> romeo502.prod.otc(informix)$ onstat -g ckp
>
> IBM Informix Dynamic Server Version 11.70.FC5X7 -- On-Line -- Up 3 days
> 22:11:13 -- 45767680 Kbytes
>
> AUTO_CKPTS=On RTO_SERVER_RESTART=Off>
> 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
> 191060 07:49:49 RTO 100496:0x154441cc 1.2 1.1 0.0 1 0.0 0.0 0.0 24696 21611
> 18463 184 19528 195
> 191061 07:50:56 RTO 100497:0x17947d4 2.2 2.2 0.0 1 0.0 0.0 0.0 29144 13426
> 22913 347 18968 287
> 191062 07:51:23 RTO 100497:0x61a2018 2.3 2.3 0.0 0 0.0 0.0 0.0 31618 13658
> 24920 922 19645 727
> 191063 07:52:34 RTO 100497:0xb044018 1.2 1.2 0.0 1 0.0 0.0 0.0 22556 19249
> 15475 214 20273 281
> 191064 07:53:49 RTO 100497:0x10256018 0.9 0.9 0.0 0 0.0 0.0 0.0 22227 22227
> 14750 194 21143 278
> 191065 07:55:05 RTO 100497:0x152d6018 1.6 1.6 0.0 0 0.0 0.0 0.0 32040 20069
> 24772 330 21851 291
> 191066 07:56:28 RTO 100498:0x1cf8018 2.7 2.7 0.0 0 0.0 0.0 0.0 21706 8151
> 14605 178 21146 257
> 191067 07:57:44 RTO 100498:0x69a0018 1.7 1.7 0.0 0 0.0 0.0 0.0 22984 13857
> 16180 210 20083 260
> 191068 07:58:55 RTO 100498:0xb89b3e8 1.4 1.4 0.0 1 0.0 0.0 0.0 23107 16283
> 16123 227 21316 300
> 191069 08:00:12 RTO 100498:0x1128c018 2.2 2.2 0.0 1 0.0 0.0 0.0 24548 11241
> 16434 216 23644 311
> 191070 08:01:23 RTO 100498:0x1603f018 1.7 1.7 0.0 0 0.0 0.0 0.0 25109 14705
> 18267 253 20316 282
> 191071 08:02:39 RTO 100499:0x293b018 1.9 1.9 0.0 1 0.0 0.0 0.0 23384 12335
> 16341 215 21160 278
> 191072 08:03:54 RTO 100499:0x7883018 0.8 0.8 0.0 0 0.0 0.0 0.0 22108 22108
> 15040 197 20683 272
> 191073 08:05:15 RTO 100499:0xc7c6018 1.4 1.4 0.0 0 0.0 0.0 0.0 22657 16422
> 15608 195 20554 256
> 191074 08:06:32 RTO 100499:0x11715484 2.1 2.1 0.0 1 0.0 0.0 0.0 30283 14538
> 23421 308 21005 276
> 191075 08:07:34 RTO 100499:0x1654a018 2.1 2.1 0.0 0 0.0 0.0 0.0 30261 14731
> 23505 379 20743 334
> 191076 08:08:45 RTO 100500:0x2ac3018 1.1 0.8 0.0 0 0.0 0.0 0.0 23374 23374
> 16611 230 19767 274
> 191077 08:09:55 RTO 100500:0x7784018 1.0 0.8 0.0 0 0.0 0.0 0.0 23232 23232
> 16420 231 19850 279
> 191078 08:11:06 RTO 100500:0xc5e8018 1.6 1.5 0.0 0 0.0 0.0 0.0 26252 16997
> 19474 278 20332 290
> 191079 08:21:32 CKPTINTVL 100502:0x148dc018 1.3 1.2 0.0 1 0.0 0.0 0.0 25112
> 20303 50337 80 233813 373
>
> Max Plog Max Llog Max Dskflush Avg Dskflush Avg Dirty Blocked
> pages/sec pages/sec Time pages/sec pages/sec Time
> 24777 87963 76 4610 2 0
>
> regards,
> Nitin
>
>
>
*******************************************************************************
> Forum Note: Use "Reply" to post a response in the discussion forum.
>
I posted the output after rolling back the change, please see the lines from
the online log (I also turned OFF AUTO_CKPTS)
4/01/14 16:48:29 Maximum server connections 31
04/01/14 16:48:29 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns
blocked 0, Plog used 12727, Llog used 25651
04/01/14 16:53:30 Checkpoint Completed: duration was 0 seconds.
04/01/14 16:53:30 Tue Apr 1 - loguniq 100491, logpos 0xdaf0018, timestamp:
0xbd378740 Interval: 191005
04/01/14 16:53:30 Maximum server connections 31
04/01/14 16:53:30 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns
blocked 0, Plog used 13964, Llog used 28492
04/01/14 16:58:30 Checkpoint Completed: duration was 0 seconds.
04/01/14 16:58:30 Tue Apr 1 - loguniq 100491, logpos 0x14f15018, timestamp:
0xbd3ff0a7 Interval: 191006
04/01/14 16:58:30 Maximum server connections 31
04/01/14 16:58:30 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns
blocked 0, Plog used 10918, Llog used 29775
04/01/14 17:00:06 Logical Log 100491 Complete, timestamp: 0xbd43dd3a.
04/01/14 17:00:06 Logical Log 100491 - Backup Started
04/01/14 17:00:21 Logical Log 100491 - Backup Completed
04/01/14 17:00:58 Value of RTO_SERVER_RESTART has been changed to 1800.
04/01/14 17:01:01 Checkpoint Completed: duration was 2 seconds.
04/01/14 17:01:01 Tue Apr 1 - loguniq 100492, logpos 0x5cf2138, timestamp:
0xbd49dd36 Interval: 191007
04/01/14 17:01:01 Maximum server connections 31
04/01/14 17:01:01 Checkpoint Statistics - Avg. Txn Block Time 0.001, # Txns
blocked 1, Plog used 63430, Llog used 38520
04/01/14 17:01:07 Value of AUTO_CKPTS has been changed to Off.
04/01/14 17:10:09 Checkpoint Completed: duration was 3 seconds.
04/01/14 17:10:09 Tue Apr 1 - loguniq 100492, logpos 0xd8c4198, timestamp:
0xbd549679 Interval: 191008
04/01/14 17:10:09 Maximum server connections 31
04/01/14 17:10:09 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns
blocked 1, Plog used 25876, Llog used 33234
04/01/14 17:10:16 Checkpoint Completed: duration was 2 seconds.
I rolled it back this morning
04/02/14 08:09:56 Wed Apr 2 - loguniq 100500, logpos 0x7784018, timestamp:
0xbe15b4c9 Interval: 191077
04/02/14 08:09:56 Maximum server connections 34
04/02/14 08:09:56 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns
blocked 0, Plog used 16420, Llog used 19850
04/02/14 08:11:07 Checkpoint Completed: duration was 1 seconds.
04/02/14 08:11:07 Wed Apr 2 - loguniq 100500, logpos 0xc5e8018, timestamp:
0xbe1b9491 Interval: 191078
04/02/14 08:11:07 Maximum server connections 34
04/02/14 08:11:07 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns
blocked 0, Plog used 19474, Llog used 20332
04/02/14 08:11:42 Value of AUTO_CKPTS has been changed to On.
04/02/14 08:11:50 Value of RTO_SERVER_RESTART has been changed to 0.
04/02/14 08:12:05 Value of CKPTINTVL has been changed to 600.
04/02/14 08:13:49 Logical Log 100500 Complete, timestamp: 0xbe29b8ef.
04/02/14 08:13:49 Logical Log 100500 - Backup Started
04/02/14 08:14:01 Logical Log 100500 - Backup Completed
04/02/14 08:17:36 Logical Log 100501 Complete, timestamp: 0xbe467e42.
04/02/14 08:17:36 Logical Log 100501 - Backup Started
04/02/14 08:17:50 Logical Log 100501 - Backup Completed
04/02/14 08:21:32 Checkpoint Completed: duration was 1 seconds.
04/02/14 08:21:32 Wed Apr 2 - loguniq 100502, logpos 0x148dc018, timestamp:
0xbe5e5076 Interval: 191079
The size of logical log is 195 MB and we have 121 logs. Every day, we use
approx 140 logs, during the peak business hours, we use one log every 2-3
minutes.
I also ran onstat -F -r 1 and noticed that there is one chunk which appears
every time when the instance is busy with checkpoint. This chunk contains
indexes from the most busy tables. Strangely, one index which is on a single
column (which is a unique value for each row for some specific message type)
does maximum disk writes (not buffer writes).
create index "informix".tqh_idx9 on "informix".t_quote_history
(qh_id) using btree in t_quote_indx01;
At the moment, I am just trying to delay the checkpoint by making the interval
equal to almost 2 hours so that trading doesnt get impacted.
regards,
Nitin
1 chunk will one be cleaned by 1 page cleaner thread at checkpoint time.
Spread different 'active' indexes/tables onto more dbspaces.
If that t_quote_history index is getting many inserts than fragment (partition)
the index across multiple dbspaces to also help.
> On 02 April 2014 at 20:21 NITIN MATHUR <nitin_maths@rediffmail.com> wrote:
>
>
> I posted the output after rolling back the change, please see the lines from
> the online log (I also turned OFF AUTO_CKPTS)
>
> 4/01/14 16:48:29 Maximum server connections 31
> 04/01/14 16:48:29 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns
> blocked 0, Plog used 12727, Llog used 25651
>
> 04/01/14 16:53:30 Checkpoint Completed: duration was 0 seconds.
> 04/01/14 16:53:30 Tue Apr 1 - loguniq 100491, logpos 0xdaf0018, timestamp:
> 0xbd378740 Interval: 191005
>
> 04/01/14 16:53:30 Maximum server connections 31
> 04/01/14 16:53:30 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns
> blocked 0, Plog used 13964, Llog used 28492
>
> 04/01/14 16:58:30 Checkpoint Completed: duration was 0 seconds.
> 04/01/14 16:58:30 Tue Apr 1 - loguniq 100491, logpos 0x14f15018, timestamp:
> 0xbd3ff0a7 Interval: 191006
>
> 04/01/14 16:58:30 Maximum server connections 31
> 04/01/14 16:58:30 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns
> blocked 0, Plog used 10918, Llog used 29775
>
> 04/01/14 17:00:06 Logical Log 100491 Complete, timestamp: 0xbd43dd3a.
> 04/01/14 17:00:06 Logical Log 100491 - Backup Started
> 04/01/14 17:00:21 Logical Log 100491 - Backup Completed
> 04/01/14 17:00:58 Value of RTO_SERVER_RESTART has been changed to 1800.
> 04/01/14 17:01:01 Checkpoint Completed: duration was 2 seconds.
> 04/01/14 17:01:01 Tue Apr 1 - loguniq 100492, logpos 0x5cf2138, timestamp:
> 0xbd49dd36 Interval: 191007
>
> 04/01/14 17:01:01 Maximum server connections 31
> 04/01/14 17:01:01 Checkpoint Statistics - Avg. Txn Block Time 0.001, # Txns
> blocked 1, Plog used 63430, Llog used 38520
>
> 04/01/14 17:01:07 Value of AUTO_CKPTS has been changed to Off.
> 04/01/14 17:10:09 Checkpoint Completed: duration was 3 seconds.
> 04/01/14 17:10:09 Tue Apr 1 - loguniq 100492, logpos 0xd8c4198, timestamp:
> 0xbd549679 Interval: 191008
>
> 04/01/14 17:10:09 Maximum server connections 31
> 04/01/14 17:10:09 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns
> blocked 1, Plog used 25876, Llog used 33234
>
> 04/01/14 17:10:16 Checkpoint Completed: duration was 2 seconds.
>
> I rolled it back this morning
>
> 04/02/14 08:09:56 Wed Apr 2 - loguniq 100500, logpos 0x7784018, timestamp:
> 0xbe15b4c9 Interval: 191077
>
> 04/02/14 08:09:56 Maximum server connections 34
> 04/02/14 08:09:56 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns
> blocked 0, Plog used 16420, Llog used 19850
>
> 04/02/14 08:11:07 Checkpoint Completed: duration was 1 seconds.
> 04/02/14 08:11:07 Wed Apr 2 - loguniq 100500, logpos 0xc5e8018, timestamp:
> 0xbe1b9491 Interval: 191078
>
> 04/02/14 08:11:07 Maximum server connections 34
> 04/02/14 08:11:07 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns
> blocked 0, Plog used 19474, Llog used 20332
>
> 04/02/14 08:11:42 Value of AUTO_CKPTS has been changed to On.
> 04/02/14 08:11:50 Value of RTO_SERVER_RESTART has been changed to 0.
> 04/02/14 08:12:05 Value of CKPTINTVL has been changed to 600.
> 04/02/14 08:13:49 Logical Log 100500 Complete, timestamp: 0xbe29b8ef.
> 04/02/14 08:13:49 Logical Log 100500 - Backup Started
> 04/02/14 08:14:01 Logical Log 100500 - Backup Completed
> 04/02/14 08:17:36 Logical Log 100501 Complete, timestamp: 0xbe467e42.
> 04/02/14 08:17:36 Logical Log 100501 - Backup Started
> 04/02/14 08:17:50 Logical Log 100501 - Backup Completed
> 04/02/14 08:21:32 Checkpoint Completed: duration was 1 seconds.
> 04/02/14 08:21:32 Wed Apr 2 - loguniq 100502, logpos 0x148dc018, timestamp:
> 0xbe5e5076 Interval: 191079
>
> The size of logical log is 195 MB and we have 121 logs. Every day, we use
> approx 140 logs, during the peak business hours, we use one log every 2-3
> minutes.
>
> I also ran onstat -F -r 1 and noticed that there is one chunk which appears
> every time when the instance is busy with checkpoint. This chunk contains
> indexes from the most busy tables. Strangely, one index which is on a single
> column (which is a unique value for each row for some specific message type)
> does maximum disk writes (not buffer writes).
>
> create index "informix".tqh_idx9 on "informix".t_quote_history
>
> (qh_id) using btree in t_quote_indx01;
>
> At the moment, I am just trying to delay the checkpoint by making the
interval
> equal to almost 2 hours so that trading doesnt get impacted.
>
> regards,
>
> Nitin
>
>
>
*******************************************************************************
> Forum Note: Use "Reply" to post a response in the discussion forum.
>
Thanks David for the response. Currently we have 7 indexes on this table, which is fragmented by round-robin (4 dbspces), please see the complete schema create table "informix".t_quote_history ( qh_seq serial not null , qh_timestamp datetime year to fraction(3), qh_userid varchar(25), qh_update_type integer, qh_id integer not null , qh_security integer not null , qh_trader integer not null , qh_upd_seqnum integer, qh_montage_rank_seqnum integer, qh_tstamp datetime year to fraction(3), qh_currency varchar(3), qh_bidpricetype varchar(3), qh_bidprice decimal(11,5), qh_bidquantity integer, qh_askpricetype varchar(3), qh_askprice decimal(11,5), qh_askquantity integer, qh_open smallint, qh_unsolicited smallint, qh_lockcross smallint, qh_otcbb smallint, qh_source_node_cd varchar(4), qh_nqbsecid integer not null , qh_symbol varchar(10), qh_shortname varchar(25), qh_trid char(8), qh_mmid char(5), qh_inbid_mmid char(5), qh_inask_mmid char(5), qh_inside_type integer, qh_bidtstamp datetime year to fraction(3) not null , qh_asktstamp datetime year to fraction(3) not null , qh_bid_qap_rt integer default 0, qh_ask_qap_rt integer default 0, qh_publishtime_ts datetime year to fraction(3) default current year to fraction(3), qh_lockcross_occurred_in integer default 0, qh_inside_seqnum integer default 0, qh_origtime_ts datetime year to fraction(3) ) fragment by round robin in t_quote_spc01 , t_quote_spc02 , t_quote_spc03 , t_quote_spc04 extent size 1000000 next size 50000 lock mode row; create unique index "informix".tqh_idx1 on "informix".t_quote_history (qh_timestamp,qh_upd_seqnum) using btree in t_quote_indx01; create index "informix".tqh_idx10 on "informix".t_quote_history (qh_seq) using btree in index1; create index "informix".tqh_idx2 on "informix".t_quote_history (qh_tstamp) using btree in t_quote_indx02; create index "informix".tqh_idx3 on "informix".t_quote_history (qh_mmid,qh_nqbsecid,qh_timestamp) using btree in t_quote_indx02; create index "informix".tqh_idx4 on "informix".t_quote_history (qh_mmid,qh_timestamp) using btree in t_quote_indx02; create index "informix".tqh_idx7 on "informix".t_quote_history (qh_timestamp,qh_nqbsecid,qh_update_type) using btree in t_quote_indx01; create index "informix".tqh_idx9 on "informix".t_quote_history (qh_id) using btree in t_quote_indx01; alter table "informix".t_quote_history add constraint primary key (qh_timestamp,qh_upd_seqnum) constraint "informix".pk_f_tqh Below are the IO numbers for last 2 days (almost) Dbsname Table Or Index Isreads Bufreads Pagreads Iswrites Bufwrites Pagwrites eqs_prod tqh_idx9 86228411 202418104 1782656 26146723 27370023 5883727 eqs_prod tqh_idx3 3487 142789159 3558642 26146653 30035704 3873674 eqs_prod t_quote_history 135337013 403912235 84057636 7076534 8719552 727112 eqs_prod t_quote_history 135340433 404665601 84099548 7076075 8720026 727103 eqs_prod t_quote_history 135338291 404826411 84082794 7075259 8719047 727025 eqs_prod t_quote_history 135325075 405013796 84045494 7073991 8719412 726904 eqs_prod tqh_idx7 0 141466885 3061330 26146723 29025238 569114 eqs_prod tqh_idx2 86228411 224519553 2441969 26146653 27311817 464807 eqs_prod tqh_idx4 86228411 228143077 3281548 26146664 28497666 416872 eqs_prod tqh_idx1 86739423 232305692 7488025 26146723 27980157 367392 eqs_prod tqh_idx10 86228415 197928976 2190271 26145912 27277343 226993 I am planning to isolate tqh_idx9 on a dbspace. Let me know if you can think of something else. regards, Nitin
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