Checkpoint duration

Hi I have a checkpoint issue. Most time the checkpoints last between 0 and 3 seconds. Some times I have sequences of 3 or 4 checkpoint when they last much longer, for example 27 seconds. Thats nearly half a minute and is recognized by the users. >From online.log: 1924 08:55:52 6399 buffers dirty 1925 08:55:52 oldest lsn loguniq 881370, logpos 0x15d525c 1926 08:56:08 dskflush() took 5 seconds 1927 08:56:08 wait4critex() took 0 seconds 1928 08:56:08 1947 buffers dirty 1929 08:56:08 oldest lsn loguniq 881370, logpos 0x15d525c 1930 08:56:08 safe_dskflush() took 0 seconds 1931 08:56:20 Fuzzy Checkpoint Completed: duration was 27 seconds, 1897 buffers not flushed. 1932 08:56:20 Checkpoint loguniq 881374, logpos 0x2eb84b8, timestamp: 0xc6c89904 1933 1934 08:56:20 Maximum server connections 2385 1935 08:56:20 Buffer manager: starting coarse downgrades. 1936 08:56:22 Buffer manager: finished coarse downgrades. 1937 Starting threshold adjustments. 1938 08:56:22 Buffer manager: finished threshold adjustments. We see dskflush() took 5 seconds, wait4critex() took 0 seconds, safe_dskflush() took 0 seconds. Any ideas what causes the 27 seconds of the whole fuzzy checkpoint? And what's the difference between dskflush and safe_dskflush? IBM Informix Dynamic Server Version 9.40.FC9W2 -- On-Line -- Up 24 days 19:53:22 -- 7164928 Kbytes, BUFFERS 2,100,000. Chunks are manages withVeritas Volume Manager and physically on SAN devices. Regards, Reinhard.

On May 19, 1:12 am, "Habichtsberg, Reinhard" <RHabichtsb...@arz- emmendingen.de> wrote: > Hi > > I have a checkpoint issue. Most time the checkpoints last between 0 and 3 > seconds. Some times I have sequences of 3 or 4 checkpoint when they last > much longer, for example 27 seconds. Thats nearly half a minute and is > recognized by the users. > > >From online.log: > >   1924  08:55:52  6399 buffers dirty >   1925  08:55:52  oldest lsn loguniq 881370, logpos 0x15d525c >   1926  08:56:08  dskflush() took 5 seconds >   1927  08:56:08  wait4critex() took 0 seconds >   1928  08:56:08  1947 buffers dirty >   1929  08:56:08  oldest lsn loguniq 881370, logpos 0x15d525c >   1930  08:56:08  safe_dskflush() took 0 seconds >   1931  08:56:20  Fuzzy Checkpoint Completed:  duration was 27 seconds, 1897 > buffers not flushed. >   1932  08:56:20  Checkpoint loguniq 881374, logpos 0x2eb84b8, timestamp: > 0xc6c89904 >   1933 >   1934  08:56:20  Maximum server connections 2385 >   1935  08:56:20  Buffer manager: starting coarse downgrades. >   1936  08:56:22  Buffer manager: finished coarse downgrades. >   1937                  Starting threshold adjustments. >   1938  08:56:22  Buffer manager: finished threshold adjustments. > > We see dskflush() took 5 seconds, wait4critex() took 0 seconds, > safe_dskflush() took 0 seconds. Any ideas what causes the 27 seconds of the > whole fuzzy checkpoint? And what's the difference between dskflush and > safe_dskflush? Well it would appear that the most likely place the missing time is a function that searches through all the partition structures in memory, looks for partitions that have been marked dirty, and then makes sure that partition page in the buffer pool is marked dirty so it's flushed in dskflush. The amount of time it takes this function to complete isn't traced. But it is about the only thing that happens between the message logged with the number of dirty buffers (at 08:55:52) and then the dskflush() took 5 seconds message at 08:56:08. So if dskflush took 5 seconds it would have started at 08:56:03 so there's 11 seconds not accounted for between 08:55:52 and 08:56:03 which I think would be this partition flushing function. There appears to be a defect entered that states that a large number of partitions marked as dirty can increase checkpoint duration, but it doesn't look like it was ever fixed in the 9.x family (APAR number IC52316). What doesn't make sense to me is why most your checkpoints would be 0ish seconds unless around the time of your long checkpoints you have some sort of unusual system activity that is marking a much larger portion of your partitions as dirty compared to your other checkpoints. Do you know of any sort of large batch activity that might be happening that would coincide with the checkpoints? You could try and use onstat -t output to see if you see a spike on dirty partitions (you'd have to look at the flgs field for a flag of 0x2 which indicates the partition flagged as dirty). Lastly, the difference between dskflush and safe_dskflush is whether or not we ensure that all modified buffers are flushed. So basically the checkpoint does a dskflush to get the majority of modified buffers flushed to disk, then after waiting for sessions to leave critical sections (and thus no longer able to modify buffers) it does the safe_dskflush to ensure any changes that might have occurred by the users that were in critical sections also then get flushed to disk. Jacques Renaut IBM IDS APD team

Intermittent long checkpoints, especially in 9.40, are often the result of BTREE Scanner activity. Try to run onstat -C at around the time of both long and short checkpoints to see what the scanners are doing. Art Art S. Kagel Oninit (www.oninit.com) IIUG Board of Directors (art@iiug.org) Disclaimer: Please keep in mind that my own opinions are my own opinions and do not reflect on my employer, Oninit, the IIUG, nor any other organization with which I am associated either explicitly or implicitly. 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 Tue, May 19, 2009 at 10:13 AM, <jprenaut@yahoo.com> wrote: > On May 19, 1:12 am, "Habichtsberg, Reinhard" <RHabichtsb...@arz- > emmendingen.de> wrote: > > Hi > > > > I have a checkpoint issue. Most time the checkpoints last between 0 and 3 > > seconds. Some times I have sequences of 3 or 4 checkpoint when they last > > much longer, for example 27 seconds. Thats nearly half a minute and is > > recognized by the users. > > > > >From online.log: > > > > 1924 08:55:52 6399 buffers dirty > > 1925 08:55:52 oldest lsn loguniq 881370, logpos 0x15d525c > > 1926 08:56:08 dskflush() took 5 seconds > > 1927 08:56:08 wait4critex() took 0 seconds > > 1928 08:56:08 1947 buffers dirty > > 1929 08:56:08 oldest lsn loguniq 881370, logpos 0x15d525c > > 1930 08:56:08 safe_dskflush() took 0 seconds > > 1931 08:56:20 Fuzzy Checkpoint Completed: duration was 27 seconds, > 1897 > > buffers not flushed. > > 1932 08:56:20 Checkpoint loguniq 881374, logpos 0x2eb84b8, timestamp: > > 0xc6c89904 > > 1933 > > 1934 08:56:20 Maximum server connections 2385 > > 1935 08:56:20 Buffer manager: starting coarse downgrades. > > 1936 08:56:22 Buffer manager: finished coarse downgrades. > > 1937 Starting threshold adjustments. > > 1938 08:56:22 Buffer manager: finished threshold adjustments. > > > > We see dskflush() took 5 seconds, wait4critex() took 0 seconds, > > safe_dskflush() took 0 seconds. Any ideas what causes the 27 seconds of > the > > whole fuzzy checkpoint? And what's the difference between dskflush and > > safe_dskflush? > > Well it would appear that the most likely place the missing time is a > function that searches through all the partition structures in memory, > looks for partitions that have been marked dirty, and then makes sure > that partition page in the buffer pool is marked dirty so it's flushed > in dskflush. The amount of time it takes this function to complete > isn't traced. But it is about the only thing that happens between the > message logged with the number of dirty buffers (at 08:55:52) and then > the dskflush() took 5 seconds message at 08:56:08. So if dskflush > took 5 seconds it would have started at 08:56:03 so there's 11 seconds > not accounted for between 08:55:52 and 08:56:03 which I think would be > this partition flushing function. > > There appears to be a defect entered that states that a large number > of partitions marked as dirty can increase checkpoint duration, but it > doesn't look like it was ever fixed in the 9.x family (APAR number > IC52316). > > What doesn't make sense to me is why most your checkpoints would be > 0ish seconds unless around the time of your long checkpoints you have > some sort of unusual system activity that is marking a much larger > portion of your partitions as dirty compared to your other > checkpoints. Do you know of any sort of large batch activity that > might be happening that would coincide with the checkpoints? You > could try and use onstat -t output to see if you see a spike on dirty > partitions (you'd have to look at the flgs field for a flag of 0x2 > which indicates the partition flagged as dirty). > > Lastly, the difference between dskflush and safe_dskflush is whether > or not we ensure that all modified buffers are flushed. So basically > the checkpoint does a dskflush to get the majority of modified buffers > flushed to disk, then after waiting for sessions to leave critical > sections (and thus no longer able to modify buffers) it does the > safe_dskflush to ensure any changes that might have occurred by the > users that were in critical sections also then get flushed to disk. > > Jacques Renaut > IBM IDS APD team > _______________________________________________ > Informix-list mailing list > Informix-list@iiug.org > http://www.iiug.org/mailman/listinfo/informix-list >

Art Kagel wrote: > Intermittent long checkpoints, especially in 9.40, are often the result > of BTREE Scanner activity. Try to run onstat -C at around the time of > both long and short checkpoints to see what the scanners are doing. Another possibility is the result of fuzzy checkpoints. With a fuzzy checkpoint, we don't flush all buffers with each checkpoint, but must flush all buffers with the log wrap. It's possible that a 'backlog' of dirty buffers had built up and all of them needed to be flushed because of a log wrap. This is not a problem with IDS 11 because non-blocking checkpoints eliminated fuzzy checkpoints. > > Art > > Art S. Kagel > Oninit (www.oninit.com <http://www.oninit.com>) > IIUG Board of Directors (art@iiug.org <mailto:art@iiug.org>) > > Disclaimer: Please keep in mind that my own opinions are my own opinions > and do not reflect on my employer, Oninit, the IIUG, nor any other > organization with which I am associated either explicitly or implicitly. > 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 Tue, May 19, 2009 at 10:13 AM, <jprenaut@yahoo.com > <mailto:jprenaut@yahoo.com>> wrote: > > On May 19, 1:12 am, "Habichtsberg, Reinhard" <RHabichtsb...@arz- > emmendingen.de <http://emmendingen.de>>; wrote: > > Hi > > > > I have a checkpoint issue. Most time the checkpoints last between > 0 and 3 > > seconds. Some times I have sequences of 3 or 4 checkpoint when > they last > > much longer, for example 27 seconds. Thats nearly half a minute > and is > > recognized by the users. > > > > >From online.log: > > > > 1924 08:55:52 6399 buffers dirty > > 1925 08:55:52 oldest lsn loguniq 881370, logpos 0x15d525c > > 1926 08:56:08 dskflush() took 5 seconds > > 1927 08:56:08 wait4critex() took 0 seconds > > 1928 08:56:08 1947 buffers dirty > > 1929 08:56:08 oldest lsn loguniq 881370, logpos 0x15d525c > > 1930 08:56:08 safe_dskflush() took 0 seconds > > 1931 08:56:20 Fuzzy Checkpoint Completed: duration was 27 > seconds, 1897 > > buffers not flushed. > > 1932 08:56:20 Checkpoint loguniq 881374, logpos 0x2eb84b8, > timestamp: > > 0xc6c89904 > > 1933 > > 1934 08:56:20 Maximum server connections 2385 > > 1935 08:56:20 Buffer manager: starting coarse downgrades. > > 1936 08:56:22 Buffer manager: finished coarse downgrades. > > 1937 Starting threshold adjustments. > > 1938 08:56:22 Buffer manager: finished threshold adjustments. > > > > We see dskflush() took 5 seconds, wait4critex() took 0 seconds, > > safe_dskflush() took 0 seconds. Any ideas what causes the 27 > seconds of the > > whole fuzzy checkpoint? And what's the difference between > dskflush and > > safe_dskflush? > > Well it would appear that the most likely place the missing time is a > function that searches through all the partition structures in memory, > looks for partitions that have been marked dirty, and then makes sure > that partition page in the buffer pool is marked dirty so it's flushed > in dskflush. The amount of time it takes this function to complete > isn't traced. But it is about the only thing that happens between the > message logged with the number of dirty buffers (at 08:55:52) and then > the dskflush() took 5 seconds message at 08:56:08. So if dskflush > took 5 seconds it would have started at 08:56:03 so there's 11 seconds > not accounted for between 08:55:52 and 08:56:03 which I think would be > this partition flushing function. > > There appears to be a defect entered that states that a large number > of partitions marked as dirty can increase checkpoint duration, but it > doesn't look like it was ever fixed in the 9.x family (APAR number > IC52316). > > What doesn't make sense to me is why most your checkpoints would be > 0ish seconds unless around the time of your long checkpoints you have > some sort of unusual system activity that is marking a much larger > portion of your partitions as dirty compared to your other > checkpoints. Do you know of any sort of large batch activity that > might be happening that would coincide with the checkpoints? You > could try and use onstat -t output to see if you see a spike on dirty > partitions (you'd have to look at the flgs field for a flag of 0x2 > which indicates the partition flagged as dirty). > > Lastly, the difference between dskflush and safe_dskflush is whether > or not we ensure that all modified buffers are flushed. So basically > the checkpoint does a dskflush to get the majority of modified buffers > flushed to disk, then after waiting for sessions to leave critical > sections (and thus no longer able to modify buffers) it does the > safe_dskflush to ensure any changes that might have occurred by the > users that were in critical sections also then get flushed to disk. > > Jacques Renaut > IBM IDS APD team > _______________________________________________ > Informix-list mailing list > Informix-list@iiug.org <mailto:Informix-list@iiug.org> > http://www.iiug.org/mailman/listinfo/informix-list > >