Checkpoint: Txn Block Time

Hello All, IDS 11.50.FC8W2 on HP-Unix In my message.log I do see the following: Checkpoint Statistics - Avg. Txn Block Time 46116722178.785, # Txns blocked 107, Is this some kinda reported bug that the Txn Block Time is this big number? other checkpoints hover around 30 sec but in between I see this big ones. Regards, Vikas

Please ignore this post as there are 2 entries for the same post(got posted 2 times) =========================================================================== Hello All, IDS 11.50.FC8W2 on HP-Unix In my message.log I do see the following: Checkpoint Statistics - Avg. Txn Block Time 46116722178.785, # Txns blocked 107, Is this some kinda reported bug that the Txn Block Time is this big number? other checkpoints hover around 30 sec but in between I see this big ones. Regards, Vikas

It has to be a reporting bug of some kind. That value is 1,465 years of block time. 8^o Art Art S. Kagel Advanced DataTools (www.advancedatatools.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 my employer, Advanced DataTools, 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, Sep 7, 2011 at 1:16 AM, VIKAS HIVARKAR <vikas.hivarkar@gmail.com>wrote: > Hello All, > > IDS 11.50.FC8W2 on HP-Unix > > In my message.log I do see the following: > > Checkpoint Statistics - Avg. Txn Block Time 46116722178.785, # Txns blocked > 107, > > Is this some kinda reported bug that the Txn Block Time is this big number? > other checkpoints hover around 30 sec but in between I see this big ones. > > Regards, > Vikas > > > > ******************************************************************************* > Forum Note: Use "Reply" to post a response in the discussion forum. > > --90e6ba613bf0b42eac04ac56964c

Wow, what is the uptime on the server... :-) On Sep 7, 2011 7:30 PM, "Art Kagel" <art.kagel@gmail.com> wrote: > It has to be a reporting bug of some kind. That value is 1,465 years of > block time. 8^o > > Art > > Art S. Kagel > Advanced DataTools (www.advancedatatools.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 my employer, Advanced DataTools, 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, Sep 7, 2011 at 1:16 AM, VIKAS HIVARKAR > <vikas.hivarkar@gmail.com>wrote: > >> Hello All, >> >> IDS 11.50.FC8W2 on HP-Unix >> >> In my message.log I do see the following: >> >> Checkpoint Statistics - Avg. Txn Block Time 46116722178.785, # Txns blocked >> 107, >> >> Is this some kinda reported bug that the Txn Block Time is this big number? >> other checkpoints hover around 30 sec but in between I see this big ones. >> >> Regards, >> Vikas >> >> >> >> > ******************************************************************************* >> Forum Note: Use "Reply" to post a response in the discussion forum. >> >> > > --90e6ba613bf0b42eac04ac56964c > > > ******************************************************************************* > Forum Note: Use "Reply" to post a response in the discussion forum. > --000e0cd3ae80278bf604ac569e0d

Vikas, Given the load jobs you mention in another post, issue an onstat -g ckp and see if you get a performane advisory. I have a suspcion your phy log may be sized way too small and the engine is triggering blocking checkpoints as a result and these may be overlapping causing some weird reporting results.

Original Post: Hello All, IDS 11.50.FC8W2 on HP-Unix In my message.log I do see the following: Checkpoint Statistics - Avg. Txn Block Time 46116722178.785, # Txns blocked 107, Is this some kinda reported bug that the Txn Block Time is this big number? other checkpoints hover around 30 sec but in between I see this big ones. Regards, Vikas Response: When you see those big numbers in the message.log file, if you look at that checkpoint's statistics via onstat -g ckp do you also see the same large number? If not, then I suspect there is some small problem with the message printing code since those 2 values should be the same (in the -g ckp output that value would be the ckpt time column), but are printed out in slightly different ways. If you do see the same large number, it still could be a reporting issue (and even though we are using slightly different methods to display the number in those 2 places), or it could also possibly be some problem with how that variable is getting set/computed. Jacques Renaut IBM Informix Advanced Support APD Team

Hello, All the big time checkpoints are triggered by RTO onstat -g ckp:AUTO_CKPTS=Off RTO_SERVER_RESTART=90 seconds Estimated recovery time 51 seconds 148721 04:56:24 RTO 175208:0x19798018 54.6 53.5 0.0 63 46116716757.8 148725 07:13:43 RTO 175214:0x745f018 42.4 46.0 0.0 41 46116733590.4 148730 09:08:51 RTO 175218:0x5541018 39.4 35.1 0.0 35 46116738086.8 Max Plog Max Llog Max Dskflush Avg Dskflush Avg Dirty Blocked pages/sec pages/sec Time pages/sec pages/sec Time 1002735 87732 93 8870 2 0 Advisory-- The physical log size is smaller than the recommended size for a server configured with RTO_SERVER_RESTART. Fast recovery performance might not be optimal. For best fast recovery performance when RTO_SERVER_RESTART is enabled, increase the physical log size to at least 42240000 KB. For servers configured with a large buffer pool, this might not be necessary. See the Administrator's Guide for more information. 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 136132704 KB. onstat -c |grep ^BUFFERBUFFERPOOL size=2K,buffers=7200000,lrus=512,lru_min_dirty=1.000000,lru_max_dirty=5.000000 BUFFERPOOL size=4K,buffers=3000000,lrus=512,lru_min_dirty=10.000000,lru_max_dirty=20.000000 BUFFERPOOL size=16K,buffers=750000,lrus=512,lru_min_dirty=10.000000,lru_max_dirty=20.000000 CKPTINTVL 600 PHYSFILE 39990000 PHYSBUFF 1024 Not sure if the physical log size really needs to be increased further Regards, Vikas ******************************************************************************** ****** Vikas, Given the load jobs you mention in another post, issue an onstat -g ckp and see if you get a performane advisory. I have a suspcion your phy log may be sized way too small and the engine is triggering blocking checkpoints as a result and these may be overlapping causing some weird reporting results. ******************************************************************************** ****** Hello All, IDS 11.50.FC8W2 on HP-Unix In my message.log I do see the following: Checkpoint Statistics - Avg. Txn Block Time 46116722178.785, # Txns blocked 107, Is this some kinda reported bug that the Txn Block Time is this big number? other checkpoints hover around 30 sec but in between I see this big ones. Regards, Vikas

Original Post: Hello All, IDS 11.50.FC8W2 on HP-Unix In my message.log I do see the following: Checkpoint Statistics - Avg. Txn Block Time 46116722178.785, # Txns blocked 107, Is this some kinda reported bug that the Txn Block Time is this big number? other checkpoints hover around 30 sec but in between I see this big ones. Regards, Vikas Response: When you see those big numbers in the message.log file, if you look at that checkpoint's statistics via onstat -g ckp do you also see the same large number? If not, then I suspect there is some small problem with the message printing code since those 2 values should be the same (in the -g ckp output that value would be the ckpt time column), but are printed out in slightly different ways. If you do see the same large number, it still could be a reporting issue (and even though we are using slightly different methods to display the number in those 2 places), or it could also possibly be some problem with how that variable is getting set/computed. Jacques Renaut IBM Informix Advanced Support APD Team Response: Hello Jacques, Yes, I see the same(almost) large number in onstat -g ckp 150413 10:50:48 RTO 175551:0xe72a018 10.1 13.0 0.0 45 46116588900.0 onstat -m10:50:49 Checkpoint Statistics - Avg. Txn Block Time 46116588899.994, # Txns blocked 45, Plog used 590125, Llog used 150086 I hope this is just a displaying issue or problem with how that variable is getting set/computed as you have mention and not a problem with my instance performance? Regards, Vikas

Original Post: Hello Jacques, Yes, I see the same(almost) large number in onstat -g ckp 150413 10:50:48 RTO 175551:0xe72a018 10.1 13.0 0.0 45 46116588900.0 onstat -m10:50:49 Checkpoint Statistics - Avg. Txn Block Time 46116588899.994, # Txns blocked 45, Plog used 590125, Llog used 150086 I hope this is just a displaying issue or problem with how that variable is getting set/computed as you have mention and not a problem with my instance performance? Regards, Vikas Response: Since you are seeing the time in the onstat -g ckp output then it has to be how we are computing the time difference. It has to be a cosmetic bug because it's impossible for that phase of the checkpoint to take that much time, it would still be in that checkpoint. I would not worry about it at all. In general, I would say any value that you see for that column that is > then the "total time" column would be junk because the "total time" column should be inclusive of that "Ckpt Time" column. Jacques Renaut IBM Informix Advanced Support APD Team