Checkpoint blocked by a previous checkpoint

Hi folks. I have a situation that I suspect but can't get IBM to confirm or deny. Thus, I'm requesting a peer review that my logic is correct and a likely explanation of a blocked checkpoint. Solaris 10 IDS 11.50.FC3X5 This is what I think happened: My client's production box has a checkpoint interval of 10 minutes and ~1.5GB physical log. During one such interval there was a violent flurry of table updates, the kind that put many pages into the plog. About 1 minute before the end of the checkpoint interval, the plog reached 75% full and the engine initiated a PLOG-checkpoint. That checkpoint, with about 600,000 dirty pages to flush, the checkpoint lasted about 84 seconds. Whoops! That creeps into the scheduled CKPTINTVL-checkpoint, which tried to start about 14 seconds before the PLOG-checkpoint finished. How did I piece together this scenario? My client called in with a blocked checkpoint. While breaking our heads over it I ran onstat -g ckp and noticed that the last checkpoint that had completed (over an hour ago by this time) was the PLOG and it had lasted 84 seconds, consistent with the last "Checkpoint completed" message in the online log. It had started about 58 seconds before he next schedule CKPTINTVL-checkpoint would have started. What should the engine do if it finds a checkpoint already in progress when it wants to start one? It could either: - Queue itself to the checkpoint latch until the current checkpoint is done, and then run the seconds checkpoint. Perhaps issue a warning in the online log that a checkpoint had to await another. - Cancel the new one, since there's one already running. And issue a warning in online log that it did so. IMO, the latter is the more logical and efficient course. But what did my engine do? (Remember, this is still *my* forensic reconstruction of the story.) The second checkpoint blocked itself and never came out of that state, effectively halting the server. Is this consistent with any bug that someone may know about? My client *is* running an old release. Or is my logic discombobulated? Thanks for clarity here. -- Jacob

Your logic seems sound, Jake. And I agree with your second recommendation: cancel the new checkpoint run and post a warning into the message log. After all, if the PLOG checkpoint had completed in, say, 50 seconds, the regularly scheduled 10-minute checkpoint should have been skipped. Correct? Informix must store "checkpoint start" info somewhere, especially to calculate the elapsed time. Why wouldn't a new checkpoint first verify that a checkpoint isn't currently running? Michael Hoffman

I believe that I have seen the second checkpoint fire(late) after the first checkpoint finishes. This was on 11.70.FC6/8 though not the version of 11.50.xxx you referenced. Possible it was a new(er) feature at the time of that release and had issues that weren't so prevalent that have since been fixed or just don't happen that often?

Original post: Hi folks. I have a situation that I suspect but can't get IBM to confirm or deny. Thus, I'm requesting a peer review that my logic is correct and a likely explanation of a blocked checkpoint. Solaris 10 IDS 11.50.FC3X5 This is what I think happened: My client's production box has a checkpoint interval of 10 minutes and ~1.5GB physical log. During one such interval there was a violent flurry of table updates, the kind that put many pages into the plog. About 1 minute before the end of the checkpoint interval, the plog reached 75% full and the engine initiated a PLOG-checkpoint. That checkpoint, with about 600,000 dirty pages to flush, the checkpoint lasted about 84 seconds. Whoops! That creeps into the scheduled CKPTINTVL-checkpoint, which tried to start about 14 seconds before the PLOG-checkpoint finished. How did I piece together this scenario? My client called in with a blocked checkpoint. While breaking our heads over it I ran onstat -g ckp and noticed that the last checkpoint that had completed (over an hour ago by this time) was the PLOG and it had lasted 84 seconds, consistent with the last "Checkpoint completed" message in the online log. It had started about 58 seconds before he next schedule CKPTINTVL-checkpoint would have started. What should the engine do if it finds a checkpoint already in progress when it wants to start one? It could either: - Queue itself to the checkpoint latch until the current checkpoint is done, and then run the seconds checkpoint. Perhaps issue a warning in the online log that a checkpoint had to await another. - Cancel the new one, since there's one already running. And issue a warning in online log that it did so. IMO, the latter is the more logical and efficient course. But what did my engine do? (Remember, this is still *my* forensic reconstruction of the story.) The second checkpoint blocked itself and never came out of that state, effectively halting the server. Is this consistent with any bug that someone may know about? My client *is* running an old release. Or is my logic discombobulated? Thanks for clarity here. -- Jacob Reply: CKPTINTVL is the amount of time to kick off a checkpoint since the last checkpoint finished (any type of checkpoint not just CKPTINTVL type checkpoints). So when the PLOG checkpoint fired off, there would not be another checkpoint until CKPTINTVL passed after that checkpoint finished. Jacques Renaut IBM Informix Advanced Support APD Team

My understanding is that the engine cancels the scheduled checkpoint and simply reschedules the next timed checkpoint to start CHKPTINTVL seconds after the completion of the long running checkpoint. Note that PLOG checkpoints are NOT non-blocking so new transactions cannot begin and existing transactions cannot enter a critical section of server code until the physical log finishes flushing to disk at which point the checkpoint reverts to non-blocking and buffer flushes are backgrounded as usual. 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 Tue, Nov 4, 2014 at 12:17 PM, JACQUES RENAUT <jrenaut@us.ibm.com> wrote: > Original post: > > Hi folks. > > I have a situation that I suspect but can't get IBM to confirm or deny. > Thus, > I'm requesting a peer review that my logic is correct and a likely > explanation > of a blocked checkpoint. > > Solaris 10 > IDS 11.50.FC3X5 > > This is what I think happened: > > My client's production box has a checkpoint interval of 10 minutes and > ~1.5GB > physical log. During one such interval there was a violent flurry of table > updates, the kind that put many pages into the plog. About 1 minute before > the > end of the checkpoint interval, the plog reached 75% full and the engine > initiated a PLOG-checkpoint. That checkpoint, with about 600,000 dirty > pages > to flush, the checkpoint lasted about 84 seconds. > > Whoops! That creeps into the scheduled CKPTINTVL-checkpoint, which tried to > start about 14 seconds before the PLOG-checkpoint finished. > > How did I piece together this scenario? > > My client called in with a blocked checkpoint. While breaking our heads > over > it I ran onstat -g ckp and noticed that the last checkpoint that had > completed > (over an hour ago by this time) was the PLOG and it had lasted 84 seconds, > consistent with the last "Checkpoint completed" message in the online log. > It > had started about 58 seconds before he next schedule CKPTINTVL-checkpoint > would have started. > > What should the engine do if it finds a checkpoint already in progress > when it > wants to start one? It could either: > - Queue itself to the checkpoint latch until the current checkpoint is > done, > and then run the seconds checkpoint. Perhaps issue a warning in the online > log > that a checkpoint had to await another. > - Cancel the new one, since there's one already running. And issue a > warning > in online log that it did so. > > IMO, the latter is the more logical and efficient course. But what did my > engine do? (Remember, this is still *my* forensic reconstruction of the > story.) The second checkpoint blocked itself and never came out of that > state, > effectively halting the server. > > Is this consistent with any bug that someone may know about? My client *is* > running an old release. Or is my logic discombobulated? > > Thanks for clarity here. > > -- Jacob > > Reply: > > CKPTINTVL is the amount of time to kick off a checkpoint since the last > checkpoint finished (any type of checkpoint not just CKPTINTVL type > checkpoints). So when the PLOG checkpoint fired off, there would not be > another checkpoint until CKPTINTVL passed after that checkpoint finished. > > Jacques Renaut > IBM Informix Advanced Support > APD Team > > > > ******************************************************************************* > Forum Note: Use "Reply" to post a response in the discussion forum. > > --001a1134562c8404b805070dd005

Thank you all for your responses. And Mike, my logic is almost always impeccable but, when faced with some illogical realities, all it means is that my logic is immune to chicken bites. But I did find out what was really going on. And it had little to do with the internal behavior of overlapping checkpoints. BTW, other symptoms have indicated that, at least on my release, checkpoints kick off to their scheduled 10-minute intervals; I've seen checkpoints blocked and suddenly spew out 10 checkpoints in 1 second - duration was 0 seconds. But here's the story and a caveat: In the VM's on which my servers run, we are using a ZFS file system. A quirk: Rather than the usual suggested 10% free, it seems that if the "pool" (which may host many file systems) is more than 80% full, it begins to trip over its own feet and shoot us in the foot. Once the supertech at the data center explained this, we boosted the size of every blessed pool (z-pool) - once in middle of a blocked checkpoint - and the problem cleared up. And stopped happening. So much for my logic. :)