Informix 12.1 Blocking Checkpoints

Hi, We are using Informix 12.1 and it seems that we are encountering blocking transactions in our installation. From what I've read, blocking transactions should no longer occur during checkpoints. Here are snippets from our online.log From here, you could see that there are a lot of transactions blocked and that they have a long transaction block time. We seem to have sufficient physical and logical logs already and the checkpoints seems to be triggered by regular checkpoints intervals. RTO is already set to 0. 14:34:52 Logical Log 1476993 Complete, timestamp: 0xd6d94c6a. 14:37:18 Checkpoint Completed: duration was 32 seconds. 14:37:18 Mon Nov 6 - loguniq 1476994, logpos 0x370673c, timestamp: 0xd6db4268 Interval: 1026948 14:37:18 Maximum server connections 639 14:37:18 Checkpoint Statistics - Avg. Txn Block Time 0.034, # Txns blocked 9, Plog used 10964, Llog used 40557 14:43:55 Checkpoint Completed: duration was 112 seconds. 14:43:55 Mon Nov 6 - loguniq 1476994, logpos 0x84a45e0, timestamp: 0xd6de881f Interval: 1026949 14:43:55 Maximum server connections 647 14:43:55 Checkpoint Statistics - Avg. Txn Block Time 48.603, # Txns blocked 329, Plog used 6446, Llog used 24145 14:44:24 listener-thread: err = -27001: oserr = 0: errstr = from 172.22.36.46 to server realsite_dr2 : Read error occurred during connection attempt. 14:47:46 Logical Log 1476994 Complete, timestamp: 0xd6e1c4a5. 14:49:26 Checkpoint Completed: duration was 61 seconds. 14:49:26 Mon Nov 6 - loguniq 1476995, logpos 0xbe417c, timestamp: 0xd6e3015b Interval: 1026950 14:49:26 Maximum server connections 730 14:49:26 Checkpoint Statistics - Avg. Txn Block Time 0.506, # Txns blocked 360, Plog used 10010, Llog used 35575 14:55:44 Checkpoint Completed: duration was 113 seconds. 14:55:44 Mon Nov 6 - loguniq 1476995, logpos 0x85095e8, timestamp: 0xd6e7be27 Interval: 1026951 14:55:44 Maximum server connections 736 14:55:44 Checkpoint Statistics - Avg. Txn Block Time 54.331, # Txns blocked 288, Plog used 10710, Llog used 37705 14:59:45 Logical Log 1476995 Complete, timestamp: 0xd6ea504b. 15:00:21 Attempting to free unused operating system segments. This operation may take several minutes. 15:01:58 Checkpoint Completed: duration was 110 seconds. 15:01:58 Mon Nov 6 - loguniq 1476996, logpos 0x8551cc, timestamp: 0xd6ebd41c Interval: 1026952 15:01:58 Maximum server connections 737 15:01:58 Checkpoint Statistics - Avg. Txn Block Time 60.904, # Txns blocked 327, Plog used 9639, Llog used 35658 15:06:31 Checkpoint Completed: duration was 15 seconds. 15:06:31 Mon Nov 6 - loguniq 1476996, logpos 0xa099018, timestamp: 0xd6f21900 Interval: 1026953 15:06:31 Maximum server connections 771 15:06:31 Checkpoint Statistics - Avg. Txn Block Time 0.468, # Txns blocked 14, Plog used 12615, Llog used 42723 15:07:16 Logical Log 1476996 Complete, timestamp: 0xd6f3d1e1. 15:11:44 Checkpoint Completed: duration was 13 seconds. 15:11:44 Mon Nov 6 - loguniq 1476997, logpos 0x8fcc018, timestamp: 0xd6f8c77a Interval: 1026954 15:11:44 Maximum server connections 771 15:11:44 Checkpoint Statistics - Avg. Txn Block Time 0.283, # Txns blocked 5, Plog used 13812, Llog used 56520

Hi, I forgot to note, this site is connected to a DR site. I don't know if there's any relation to the checkpoints. Thanks,

Hi, Also, if I may, 14:43:55 Checkpoint Statistics - Avg. Txn Block Time 48.603, # Txns blocked 329, Plog used 6446, Llog used 24145 What does plog used mean and what does llog used mean ? Also, what does the Txns blocked refer to here ? These logs are found in our online.log The physical log size is currently at 760000 in our config. What could have possibly caused blocking checkpoints ? :As per reading different resources on the Internet, checkpoints should not be blocking already for Informix 11 onwards. if plog used and llog used here is the amount used during the checkpoint, then it's way less than the current value that I have. Thanks,

> On 06 November 2017 at 16:56 NATYURAL HORACIO <horacio.natyural@gmail.com> wrote: > > > Hi, > > Also, if I may, > > 14:43:55 Checkpoint Statistics - Avg. Txn Block Time 48.603, # Txns blocked > 329, Plog used 6446, Llog used 24145 > > What does plog used mean and what does llog used mean ? Physical log used and Logical Log Used > Also, what does the Txns blocked refer to here ? > Tranaction which were blocked > These logs are found in our online.log > > The physical log size is currently at 760000 in our config. > > What could have possibly caused blocking checkpoints ? :As per reading > different resources on the Internet, checkpoints should not be blocking > already for Informix 11 onwards. if plog used and llog used here is the amount > used during the checkpoint, then it's way less than the current value that I > have. https://www.ibm.com/developerworks/data/library/techarticle/dm-0703lashley/index .html "IDS, Version 11.10 introduces a new checkpoint algorithm that is virtually non-blocking. Transactional updates are blocked for a very short time (typically, a fraction of one second) while a checkpoint point is started. Then transactions are free to perform updates while the bufferpool containing all the transactional updates is flushed to disk." Transactions are only briefly blocked and are NOT blocking whilst the big flush of pending writes to disk occurs during a checkpoint. Checkpoint reasons can be checked via onstat -g ckp https://www.ibm.com/support/knowledgecenter/en/SSGU8G_11.70.0/com.ibm.adref.doc/ ids_adr_0518.htm Regards, David. > > Thanks, > > > ******************************************************************************* > Forum Note: Use "Reply" to post a response in the discussion forum. >

Hi David, Thanks for this, Any idea on the why the transactions blocked for a longer period of time ? Based on the article that you provided, they should only be briefly locked. And based on your explanation, long blocking time should not have occurred. Thanks

My average txn block time is quite high Avg. Txn Block Time --> 48 seconds. Any idea what might have caused this behavior ? Thanks

Can you post the output of "onstat -g ckp" ? Luis Marques DIT/TCS/DBA - Informix/Postgresql/Mysql/DB2 Database Administration tlf:+351 215018981 / tlm:+351 963135033 / prev:+351 962059165 luis-silvestre-marques@telecom.pt AV JACQUES DELORS EDF INOVACAO 3 TAGUSPARK 2740-122 PORTO SALVO | PORTUGAL meo.pt AVISO DE CONFIDENCIALIDADE Esta mensagem e quaisquer ficheiros anexos a ela contêm informação confidencial, propriedade da PT Portugal e/ou das demais sociedades que com ela se encontrem em relação de domínio, Fundação Portugal Telecom e PT ACS, destinando-se ao uso exclusivo do destinatário. Se não for o destinatário pretendido, não deve usar, distribuir, imprimir ou copiar este e-mail. Se recebeu esta mensagem por engano, por favor informe o emissor e elimine-a imediatamente. Obrigado. -----Original Message----- From: ids-bounces@iiug.org [mailto:ids-bounces@iiug.org] On Behalf Of NATYURAL HORACIO Sent: segunda-feira, 6 de novembro de 2017 17:24 To: ids@iiug.org Subject: Re: Informix 12.1 Blocking Checkpoints [40154] My average txn block time is quite high Avg. Txn Block Time --> 48 seconds. Any idea what might have caused this behavior ? Thanks ******************************************************************************* Forum Note: Use "Reply" to post a response in the discussion forum.

Hi Unfortunately I don’t have access to the system now and the time might have already loses for me to take the command. What usually causes blocking time in checkpoints ? Is it possible that my physics log or Logica log is still missing ? I just want to avoid blocking transactions in checkpoints as much as possible. Thanks

The output of the command: onstat -g ckp will give you historical information: Example below: class interval time trigger LSN time flush block waits dirty pages/sec plog llog 3182 09:22:02 Startup 38:0xcb90c0 0.3 0.2 0.0 0 14 14 15 1 3183 09:22:36 *Backup 38:0x10b4090 0.4 0.2 0.0 1 47 47 280 1,019 3184 09:38:01 CKPTINTVL 38:0x10e1018 0.3 0.1 0.0 0 17 17 38 45 3185 09:53:01 CKPTINTVL 38:0x10ee018 0.2 0.1 0.0 0 14 14 31 13 3186 10:08:01 CKPTINTVL 38:0x10f0018 0.0 0.0 0.0 0 1 1 9 2 3187 10:23:01 CKPTINTVL 38:0x10f2018 0.0 0.0 0.0 0 1 1 2 2 3188 10:38:01 CKPTINTVL 38:0x10f4018 0.0 0.0 0.0 0 1 1 2 2 I think David is looking for this information. David Link -----Original Message----- From: ids-bounces@iiug.org [mailto:ids-bounces@iiug.org] On Behalf Of NATYURAL HORACIO Sent: Monday, November 06, 2017 11:51 AM To: ids@iiug.org Subject: Re: RE: Informix 12.1 Blocking Checkpoints [40156] Hi Unfortunately I don't have access to the system now and the time might have already loses for me to take the command. What usually causes blocking time in checkpoints ? Is it possible that my physics log or Logica log is still missing ? I just want to avoid blocking transactions in checkpoints as much as possible. Thanks ******************************************************************************* Forum Note: Use "Reply" to post a response in the discussion forum.

Hi, Here it is : 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 1027271 15:58:17 CKPTINTVL 1477179:0x7de2018 20.7 17.7 0.0 18 0.0 1.2 2.5 34765 1961 6889 22 19702 64 1027272 16:04:14 CKPTINTVL 1477180:0x28ca018 46.3 44.5 0.0 7 0.0 0.9 1.3 19817 445 6706 20 20341 61 1027273 16:08:48 CKPTINTVL 1477180:0x75242e0 4.4 3.6 0.0 6 0.0 0.3 0.7 14482 4069 7140 22 19877 63 1027274 16:13:53 CKPTINTVL 1477180:0xc44d018 5.8 5.0 0.0 7 0.0 0.4 0.5 16719 3321 7465 24 20571 67 1027275 16:19:38 CKPTINTVL 1477181:0x3392018 45.1 43.1 0.0 10 0.0 0.9 1.8 14921 346 7782 25 25211 82 1027276 16:24:36 CKPTINTVL 1477181:0xa661468 28.9 27.4 0.0 15 0.0 0.6 1.3 17436 636 8603 27 31287 99 1027277 16:29:40 CKPTINTVL 1477182:0xc4e018 4.3 3.5 0.0 2 0.0 0.4 0.5 14007 4055 7643 23 20696 63 1027278 16:36:22 CKPTINTVL 1477182:0x7f72018 103.0 102.6 0.0 0 0.0 0.0 0.0 17725 172 9144 30 36297 119 1027279 16:39:58 CKPTINTVL 1477182:0xd44a018 5.2 4.4 0.0 2 0.0 0.3 0.5 17563 4028 8092 25 22107 70 1027280 16:45:01 CKPTINTVL 1477183:0xa39b018 3.6 3.1 0.0 3 0.0 0.2 0.3 25191 8089 11422 37 47722 156 1027281 16:50:17 CKPTINTVL 1477184:0x69d0cc 16.9 14.4 0.0 13 0.1 1.1 2.2 13874 964 7435 24 21666 71 1027282 16:55:48 CKPTINTVL 1477184:0x748b018 31.1 30.0 0.0 13 0.0 0.7 1.0 21411 714 8747 27 29988 95 1027283 17:02:04 CKPTINTVL 1477185:0x9f278 96.8 95.4 0.0 8 0.0 0.5 1.0 17254 180 9177 29 30386 97 1027284 17:06:58 CKPTINTVL 1477185:0x6016018 74.9 72.8 0.0 14 0.0 1.0 1.5 16851 231 9194 29 29269 92 1027285 17:11:24 CKPTINTVL 1477185:0xe90f524 26.9 25.0 0.0 12 0.0 0.8 1.4 20564 822 10391 33 40336 128 1027286 17:18:23 CKPTINTVL 1477186:0x682f138 116.4 85.4 0.0 326 28.6 15.1 29.8 16459 192 8342 23 30949 86 1027287 17:22:29 CKPTINTVL 1477186:0x8f6e2a8 20.9 17.1 0.0 348 2.0 3.9 5.4 10849 635 5035 16 12260 39 1027288 17:27:52 CKPTINTVL 1477187:0x31d8184 19.4 17.6 0.0 24 0.2 0.9 1.8 27955 1587 13490 41 37744 117 1027289 17:33:12 CKPTINTVL 1477188:0x7f84018 12.8 12.4 0.0 16 0.2 0.4 0.4 27856 2252 19806 60 82764 253 1027290 17:39:07 CKPTINTVL 1477189:0x47801ec 55.3 16.5 0.0 247 35.1 22.2 37.4 23435 1417 12129 34 49628 142 Max Plog Max Llog Max Dskflush Avg Dskflush Avg Dirty Blocked pages/sec pages/sec Time pages/sec pages/sec Time 2927 3850 103 2612 0 0 Based on the current workload, the physical log might be too small to accommodate the time it takes to flush the buffer pool during checkpoint processing. The server might block transactions during checkpoints. If the server blocks transactions, increase the physical log size to at least 807852 KB. Thanks, Carlo

If I would look at the onstat results, I can see that my block time is 0.0 for almost all checkpoints. Does this mean that my logs are sufficient ? However, in my logs, I'm seeing mention that physical log might not be enough to accomodate current workload. I noticed that the long wait time is in the critical sections wait time. What does that mean ? Based on what I've read, it is the time my threads waited to enter the critical section. I'm quite confused as of the moment on what to do next .. Does this mean that my physical logs and logical logs are sufficient ? FYI, we had this problem long ago way back December 1, 2014. Support asked us to change max_fill_data_pages to 0 and this problem went away for a long time. It is only now that it is happening again. Thanks for all the help

IO rate during the long checkpoints seems to be much lower (long checkpoints are not even the ones with the most dirty buffers). What is the configuration value of the BUFFERPOOL ? What is the configuration value of the CLEANERS ? What is the configuration value of PHYSFILE ? What is the configuration value of LOGFILES and LOGSIZE ? What is the output of "onstat -F" ? What is the output of "onstat -R" ? And finally, the output of "onstat -g ioh", but it can be very verbose, so maybe just check if around the time of the longest timestamps there are any chunks with slower IO rates. Luis Marques -----Original Message----- From: ids-bounces@iiug.org [mailto:ids-bounces@iiug.org] On Behalf Of NATYURAL HORACIO Sent: terça-feira, 7 de novembro de 2017 10:48 To: ids@iiug.org Subject: Re: RE: RE: Informix 12.1 Blocking Checkpoints [40158] Hi, Here it is : 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 1027271 15:58:17 CKPTINTVL 1477179:0x7de2018 20.7 17.7 0.0 18 0.0 1.2 2.5 34765 1961 6889 22 19702 64 1027272 16:04:14 CKPTINTVL 1477180:0x28ca018 46.3 44.5 0.0 7 0.0 0.9 1.3 19817 445 6706 20 20341 61 1027273 16:08:48 CKPTINTVL 1477180:0x75242e0 4.4 3.6 0.0 6 0.0 0.3 0.7 14482 4069 7140 22 19877 63 1027274 16:13:53 CKPTINTVL 1477180:0xc44d018 5.8 5.0 0.0 7 0.0 0.4 0.5 16719 3321 7465 24 20571 67 1027275 16:19:38 CKPTINTVL 1477181:0x3392018 45.1 43.1 0.0 10 0.0 0.9 1.8 14921 346 7782 25 25211 82 1027276 16:24:36 CKPTINTVL 1477181:0xa661468 28.9 27.4 0.0 15 0.0 0.6 1.3 17436 636 8603 27 31287 99 1027277 16:29:40 CKPTINTVL 1477182:0xc4e018 4.3 3.5 0.0 2 0.0 0.4 0.5 14007 4055 7643 23 20696 63 1027278 16:36:22 CKPTINTVL 1477182:0x7f72018 103.0 102.6 0.0 0 0.0 0.0 0.0 17725 172 9144 30 36297 119 1027279 16:39:58 CKPTINTVL 1477182:0xd44a018 5.2 4.4 0.0 2 0.0 0.3 0.5 17563 4028 8092 25 22107 70 1027280 16:45:01 CKPTINTVL 1477183:0xa39b018 3.6 3.1 0.0 3 0.0 0.2 0.3 25191 8089 11422 37 47722 156 1027281 16:50:17 CKPTINTVL 1477184:0x69d0cc 16.9 14.4 0.0 13 0.1 1.1 2.2 13874 964 7435 24 21666 71 1027282 16:55:48 CKPTINTVL 1477184:0x748b018 31.1 30.0 0.0 13 0.0 0.7 1.0 21411 714 8747 27 29988 95 1027283 17:02:04 CKPTINTVL 1477185:0x9f278 96.8 95.4 0.0 8 0.0 0.5 1.0 17254 180 9177 29 30386 97 1027284 17:06:58 CKPTINTVL 1477185:0x6016018 74.9 72.8 0.0 14 0.0 1.0 1.5 16851 231 9194 29 29269 92 1027285 17:11:24 CKPTINTVL 1477185:0xe90f524 26.9 25.0 0.0 12 0.0 0.8 1.4 20564 822 10391 33 40336 128 1027286 17:18:23 CKPTINTVL 1477186:0x682f138 116.4 85.4 0.0 326 28.6 15.1 29.8 16459 192 8342 23 30949 86 1027287 17:22:29 CKPTINTVL 1477186:0x8f6e2a8 20.9 17.1 0.0 348 2.0 3.9 5.4 10849 635 5035 16 12260 39 1027288 17:27:52 CKPTINTVL 1477187:0x31d8184 19.4 17.6 0.0 24 0.2 0.9 1.8 27955 1587 13490 41 37744 117 1027289 17:33:12 CKPTINTVL 1477188:0x7f84018 12.8 12.4 0.0 16 0.2 0.4 0.4 27856 2252 19806 60 82764 253 1027290 17:39:07 CKPTINTVL 1477189:0x47801ec 55.3 16.5 0.0 247 35.1 22.2 37.4 23435 1417 12129 34 49628 142 Max Plog Max Llog Max Dskflush Avg Dskflush Avg Dirty Blocked pages/sec pages/sec Time pages/sec pages/sec Time 2927 3850 103 2612 0 0 Based on the current workload, the physical log might be too small to accommodate the time it takes to flush the buffer pool during checkpoint processing. The server might block transactions during checkpoints. If the server blocks transactions, increase the physical log size to at least 807852 KB. Thanks, Carlo ******************************************************************************* Forum Note: Use "Reply" to post a response in the discussion forum.

I'll provide the things you need tomorrow since I don't have access right now. Yes, they do not contain the most buffers. THe IO rate is quite low but also for the other part. Is this indicative that my IO is no longer enough ? Do you think I have enough physical and logical logs ? Is it safe to say that from this, I don't have an Based on my reading, my threadsd took a long time before it was able to enter the critical section. What does this mean ? What are my threads waiting for ? If I have no block time, then what is the wait time waiting for ?

From 'onstat -g ckp' there appear to be two problems which might be related (or one exaggerated by the other), but still should count separately: I tried to format a little more readable, hopefully this remains: 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 1027271 15:58:17 CKPTINTVL 1477179:0x7de2018 20.7 17.7 0.0 18 0.0 1.2 2.5 34765 1961 6889 22 19702 64 1027272 16:04:14 CKPTINTVL 1477180:0x28ca018 46.3 44.5 0.0 7 0.0 0.9 1.3 19817 445 6706 20 20341 61 1027273 16:08:48 CKPTINTVL 1477180:0x75242e0 4.4 3.6 0.0 6 0.0 0.3 0.7 14482 4069 7140 22 19877 63 1027274 16:13:53 CKPTINTVL 1477180:0xc44d018 5.8 5.0 0.0 7 0.0 0.4 0.5 16719 3321 7465 24 20571 67 1027275 16:19:38 CKPTINTVL 1477181:0x3392018 45.1 43.1 0.0 10 0.0 0.9 1.8 14921 346 7782 25 25211 82 1027276 16:24:36 CKPTINTVL 1477181:0xa661468 28.9 27.4 0.0 15 0.0 0.6 1.3 17436 636 8603 27 31287 99 1027277 16:29:40 CKPTINTVL 1477182:0xc4e018 4.3 3.5 0.0 2 0.0 0.4 0.5 14007 4055 7643 23 20696 63 1027278 16:36:22 CKPTINTVL 1477182:0x7f72018 103.0 102.6 0.0 0 0.0 0.0 0.0 17725 172 9144 30 36297 119 1027279 16:39:58 CKPTINTVL 1477182:0xd44a018 5.2 4.4 0.0 2 0.0 0.3 0.5 17563 4028 8092 25 22107 70 1027280 16:45:01 CKPTINTVL 1477183:0xa39b018 3.6 3.1 0.0 3 0.0 0.2 0.3 25191 8089 11422 37 47722 156 1027281 16:50:17 CKPTINTVL 1477184:0x69d0cc 16.9 14.4 0.0 13 0.1 1.1 2.2 13874 964 7435 24 21666 71 1027282 16:55:48 CKPTINTVL 1477184:0x748b018 31.1 30.0 0.0 13 0.0 0.7 1.0 21411 714 8747 27 29988 95 1027283 17:02:04 CKPTINTVL 1477185:0x9f278 96.8 95.4 0.0 8 0.0 0.5 1.0 17254 180 9177 29 30386 97 1027284 17:06:58 CKPTINTVL 1477185:0x6016018 74.9 72.8 0.0 14 0.0 1.0 1.5 16851 231 9194 29 29269 92 1027285 17:11:24 CKPTINTVL 1477185:0xe90f524 26.9 25.0 0.0 12 0.0 0.8 1.4 20564 822 10391 33 40336 128 1027286 17:18:23 CKPTINTVL 1477186:0x682f138 116.4 85.4 0.0 326 28.6 15.1 29.8 16459 192 8342 23 30949 86 1027287 17:22:29 CKPTINTVL 1477186:0x8f6e2a8 20.9 17.1 0.0 348 2.0 3.9 5.4 10849 635 5035 16 12260 39 1027288 17:27:52 CKPTINTVL 1477187:0x31d8184 19.4 17.6 0.0 24 0.2 0.9 1.8 27955 1587 13490 41 37744 117 1027289 17:33:12 CKPTINTVL 1477188:0x7f84018 12.8 12.4 0.0 16 0.2 0.4 0.4 27856 2252 19806 60 82764 253 1027290 17:39:07 CKPTINTVL 1477189:0x47801ec 55.3 16.5 0.0 247 35.1 22.2 37.4 23435 1417 12129 34 49628 142 The good news first: none of these checkpoints is performed as a blocking one. Nonetheless there seem to be circumstances with some of them leading to other sorts of blockage ... The two problems: - occasionally slow disk (write) I/O -> look at first 'Dskflu / Sec' column for how highly variable the flush rates are. - occasionally long 'Ckpt Time' -> this is what would be reported as 'Avg. Txn Block Time' in online.log (a slight misnomer, but this is what we have) The first problem alone might not hurt any user sessions (from checkpoint's perspective), it only would prolong the overall checkpoint duration which doesn't hurt with non-blocking checkpoints. Of course any session activity depending on disk (read) I/O - which usually is similarly affected - would suffer independently from checkpoints. The second problem could have direct blocking impact on user sessions, for and beyond the time the checkpoint has to wait ('Ckpt Time'), longest measured session wait time being 'Long Time', average being 'Wait Time'. All this waiting now leading to 'critical section' which, in plain words, is an operation that needs to complete between checkpoints, so the instance's consistent on-disk image created by a checkpoint is guaranteed to either contain the operation's full result or none of it. Consequentially a 'critical section' cannot start while (a specific part of) a checkpoint is underway, and once at least one 'critical section' operation is underway, a new checkpoint had to wait for them to finish, no other operations are allowed to enter a critical section during such waiting. This waiting by a checkpoint on ongoing 'critical section' operations is 'Ckpt Time'. Of course a critical section normally is a smallish thing, taking micro-seconds rather than many seconds, but there can be conditions for longer ones too. Now if such 'critical section' activity had to perform a lot of disk I/O (usually for reading many pages), you'd see how the two problems could add to each other. One had to catch such long lasting critical section, or a checkpoint having to wait on one, then collect some onstat outputs to learn more. In many cases ensuring decent disk I/O performance already is sufficient for getting things back to satisfactory performance. And of course eliminating unnecessary disk I/O ... e.g. by increasing bufferpool sizes, lowering LRU_MIN/MAX_DIRTY, ... HTH, Andreas From: "NATYURAL HORACIO" <horacio.natyural@gmail.com> To: ids@iiug.org Date: 11/07/2017 05:32 PM Subject: Re: RE: RE: RE: Informix 12.1 Blocking Checkpoints [40161] Sent by: ids-bounces@iiug.org I'll provide the things you need tomorrow since I don't have access right now. Yes, they do not contain the most buffers. THe IO rate is quite low but also for the other part. Is this indicative that my IO is no longer enough ? Do you think I have enough physical and logical logs ? Is it safe to say that from this, I don't have an Based on my reading, my threadsd took a long time before it was able to enter the critical section. What does this mean ? What are my threads waiting for ? If I have no block time, then what is the wait time waiting for ? ******************************************************************************* Forum Note: Use "Reply" to post a response in the discussion forum.

Hi, THnak you for this very detailed explanation regarding the critical checkpoints. It's actually not that easy to catch since it happens very erratically. We have already raised this to IBM support though. The last time that this happened, they made us change a parameter in ononfig file. So there seems to be no issue with the physical and logical log size as the blocking time is non existent. I'd like to know what commands I should throw if ever we encounter this again. Is there anyway that I can know what the threads are particularly waiting for ? Thanks,

> On 7 Nov 2017, at 10:48, NATYURAL HORACIO <horacio.natyural@gmail.com> wrote: > > Hi, > > > Based on the current workload, the physical log might be too small > to accommodate the time it takes to flush the buffer pool during > checkpoint processing. The server might block transactions during checkpoints. > If the server blocks transactions, increase the physical log size to > at least 807852 KB. > And here is your answer Clive

Hi Horacio, just curious: what was the parameter to change, and what was the change? The task at hand would be catching a situation where a thread is seen 'in critical section' for so many seconds. I've quickly sketched a script that might help at this - haven't really tested it, but should at least serve as a starting point. Have it running it in an empty directory, and should it catch something and produce outputs, provide these to tech support. Let us know how this goes. #!/bin/bash # Catch information once threads seen 'in critical section' # (X flag at pos 5 in 'onstat -u' flags column) in two consecutive # onstat -u outputs $min_crit_sect_duration seconds apart.# Doesn't guarantee 'same critical section', but chances are it is. # # Change 'while true' if you don't want this to run for ever, # otherwise it wouuld dump a new onstat -u every $min_crit_sect_duration # seconds and compare with previous one, then collect session and stack # info on threads caught repeatedly, plus full -a, -g stk all and -g ses 0 # for every interval finding at least one repeat. min_crit_sect_duration=3 o=0 while true; do rstcbs0=$rstcbs1 unset rstcbs1 if [ -z $rstcbs0 ]; then onstat -u > o_u0 rstcbs0=$(awk '{if (substr($2,5,1) == "X") print $1}' o_u0)fi sleep $min_crit_sect_duration if [ -z "$rstcbs0" ]; then continue; fi onstat -u > o_u1 rstcbs1=$(awk '{if (substr($2,5,1) == "X") print $1}' o_u1) if [ -z "$rstcbs1" ]; then continue; fi n=0 for r0 in $rstcbs0; do for r1 in $rstcbs1; do if [ $r0 = $r1 ]; then t=$(onstat -g ath | awk '$3 ~/^'$r1'$/ {print $1}') if [ -z $t ]; then continue; fi if [ $n -eq 0 ]; then onstat -a |gzip > o_a_$o.gz onstat -g stk all | gzip > og_stk_all_$o.gz onstat -g ses 0 | gzip > og_ses_0_$o.gz o=$((o+1)) fi onstat -g stk $t >> og_stk_$t s=$(awk '/^'$r1'/ {print $3}' o_u1) onstat -g ses $s >> og_ses_$s n=$((n+1)) fi done done done BR, Andreas From: "NATYURAL HORACIO" <horacio.natyural@gmail.com> To: ids@iiug.org Date: 11/08/2017 05:32 PM Subject: Re: RE: RE: RE: Informix 12.1 Blocking Checkpoints [40163] Sent by: ids-bounces@iiug.org Hi, THnak you for this very detailed explanation regarding the critical checkpoints. It's actually not that easy to catch since it happens very erratically. We have already raised this to IBM support though. The last time that this happened, they made us change a parameter in ononfig file. So there seems to be no issue with the physical and logical log size as the blocking time is non existent. I'd like to know what commands I should throw if ever we encounter this again. Is there anyway that I can know what the threads are particularly waiting for ? Thanks, ******************************************************************************* Forum Note: Use "Reply" to post a response in the discussion forum.

Hi Andreas, Did wonder if it was this one! http://www-01.ibm.com/support/docview.wss?uid=swg1IT16149 Hi NATYURAL HORACIO, Which Informix version are you on? This may not be the issue but if you are sensitive to long checkpoint be aware of: http://www-01.ibm.com/support/docview.wss?uid=swg1IT19990 fixed in 12.10.xC8 Everyone, Please be aware of http://www-01.ibm.com/support/docview.wss?uid=swg1IT14187 !! Fixed in 12.10.xC7. Regards, David. > On 10 November 2017 at 08:51 Andreas Legner1 <Andreas.Legner1@de.ibm.com> wrote: > > > Hi Horacio, > > just curious: what was the parameter to change, and what was the change? > > The task at hand would be catching a situation where a thread is seen 'in > critical section' for so many seconds. > > I've quickly sketched a script that might help at this - haven't really > tested it, but should at least serve as a starting point. > Have it running it in an empty directory, and should it catch something and > produce outputs, provide these to tech support. > > Let us know how this goes. > > #!/bin/bash > > # Catch information once threads seen 'in critical section' > # (X flag at pos 5 in 'onstat -u' flags column) in two consecutive > # onstat -u outputs $min_crit_sect_duration seconds apart.> # Doesn't guarantee 'same critical section', but chances are it is. > # > # Change 'while true' if you don't want this to run for ever, > # otherwise it wouuld dump a new onstat -u every $min_crit_sect_duration > # seconds and compare with previous one, then collect session and stack > # info on threads caught repeatedly, plus full -a, -g stk all and -g ses 0 > # for every interval finding at least one repeat. > > min_crit_sect_duration=3 > > o=0 > while true; do > > rstcbs0=$rstcbs1 > unset rstcbs1 > if [ -z $rstcbs0 ]; then > onstat -u > o_u0 > rstcbs0=$(awk '{if (substr($2,5,1) == "X") print $1}' o_u0)> fi > > sleep $min_crit_sect_duration > > if [ -z "$rstcbs0" ]; then continue; fi > onstat -u > o_u1 > rstcbs1=$(awk '{if (substr($2,5,1) == "X") print $1}' o_u1) > if [ -z "$rstcbs1" ]; then continue; fi> > n=0 > for r0 in $rstcbs0; do > for r1 in $rstcbs1; do > > if [ $r0 = $r1 ]; then > > t=$(onstat -g ath | awk '$3 ~/^'$r1'$/ {print $1}') > > if [ -z $t ]; then continue; fi > > if [ $n -eq 0 ]; then > > onstat -a |gzip > o_a_$o.gz> > onstat -g stk all | gzip > og_stk_all_$o.gz> > onstat -g ses 0 | gzip > og_ses_0_$o.gz> > o=$((o+1)) > > fi > > onstat -g stk $t >> og_stk_$t> > s=$(awk '/^'$r1'/ {print $3}' o_u1) > > onstat -g ses $s >> og_ses_$s> > n=$((n+1)) > > fi > done > done > > done > > BR, > Andreas > > From: "NATYURAL HORACIO" <horacio.natyural@gmail.com> > To: ids@iiug.org > Date: 11/08/2017 05:32 PM > Subject: Re: RE: RE: RE: Informix 12.1 Blocking Checkpoints [40163] > Sent by: ids-bounces@iiug.org > > Hi, > > THnak you for this very detailed explanation regarding the critical > checkpoints. > > It's actually not that easy to catch since it happens very erratically. > We have already raised this to IBM support though. The last time that this > happened, they made us change a parameter in ononfig file. > > So there seems to be no issue with the physical and logical log size as the > > blocking time is non existent. > > I'd like to know what commands I should throw if ever we encounter this > again. > Is there anyway that I can know what the threads are particularly waiting > for > ? > > Thanks, > > > ******************************************************************************* > > Forum Note: Use "Reply" to post a response in the discussion forum. > > > ******************************************************************************* > Forum Note: Use "Reply" to post a response in the discussion forum. >