Long Checkpoint - Not Reported in online.log

IDS 7.30FC7, under Tru64 4.0F on an 8 CPU 5/625 Digital (Compaq) Alpha Server. 6Gb RAM. It's long checkpoints again, but with a new twist I think! After happily processing a heavy (CPU 80% busy) OLTP workload for 2 hours, IDS decided to dump large amounts of data from shared memory to disk. The writes start as LRU writes but when the checkpoint timer expires the system locks in a "checkpoint" for about 4 minutes, frantically writing to disk. To add insult to injury the checkpoint is reported as being just a few seconds long in the log file! I know that onstat -R would be handy to investigate this issue, unfortunately I don't have it for this occurrence. My questions are: Does anyone know why IDS decides to dump such a large amount of data from shared memory to disk all of a sudden? Note the previous checkpoint was not long ago so I would have expected the buffers to be fairly clean. Around this time the system was no busier than it had been for the previous couple of hours. Any ideas why the checkpoint is reported as being for just a few seconds, when the cleaners were frantically doing chunk writes for a few minutes? Here's some onstat -F --------- All quiet... Informix Dynamic Server Version 7.30.FC7 -- On- Line (Prim) -- Up 34 days 20:27:14 -- 737280 Kbytes Fg Writes LRU Writes Chunk Writes 0 868729 73788 address flusher state data 4804a6c0 0 I 0 = 0X0 4804ad58 1 I 0 = 0X0 4804b3f0 2 I 0 = 0X0 4804ba88 3 I 0 = 0X0 states: Exit Idle Chunk Lru --------- Cleaning cuts in... Sat 25 Mar 14:02:06 2000 Informix Dynamic Server Version 7.30.FC7 -- On- Line (Prim) -- Up 34 days 20:28:14 -- 737280 Kbytes Fg Writes LRU Writes Chunk Writes 0 893814 73788 address flusher state data 4804a6c0 0 L 33 = 0X21 4804ad58 1 L 11 = 0Xb 4804b3f0 2 I 0 = 0X0 4804ba88 3 L 9 = 0X9 states: Exit Idle Chunk Lru Sat 25 Mar 14:03:07 2000 Informix Dynamic Server Version 7.30.FC7 -- On- Line (Prim) -- Up 34 days 20:29:15 -- 737280 Kbytes --------- AAH, foreground writes... Fg Writes LRU Writes Chunk Writes 38 924042 73788 address flusher state data 4804a6c0 0 L 29 = 0X1d 4804ad58 1 L 4 = 0X4 4804b3f0 2 L 37 = 0X25 4804ba88 3 L 26 = 0X1a states: Exit Idle Chunk Lru Sat 25 Mar 14:04:08 2000 Informix Dynamic Server Version 7.30.FC7 -- On- Line (Prim) -- Up 34 days 20:30:16 -- 737280 Kbytes Fg Writes LRU Writes Chunk Writes 89 947514 73788 address flusher state data 4804a6c0 0 L 29 = 0X1d 4804ad58 1 L 4 = 0X4 4804b3f0 2 L 37 = 0X25 4804ba88 3 L 26 = 0X1a states: Exit Idle Chunk Lru Sat 25 Mar 14:05:08 2000 Informix Dynamic Server Version 7.30.FC7 -- On- Line (Prim) -- Up 34 days 20:31:16 -- 737280 Kbytes Fg Writes LRU Writes Chunk Writes 94 976460 73788 address flusher state data 4804a6c0 0 L 39 = 0X27 4804ad58 1 L 10 = 0Xa 4804b3f0 2 L 25 = 0X19 4804ba88 3 L 18 = 0X12 states: Exit Idle Chunk Lru Sat 25 Mar 14:06:09 2000 Informix Dynamic Server Version 7.30.FC7 -- On- Line (Prim) (CKPT REQ) -- Up 34 days 20:32:17 -- 737280 Kbytes Blocked:CKPT --------- In to the checkpoint... Fg Writes LRU Writes Chunk Writes 94 1000796 74732 address flusher state data 4804a6c0 0 C 2 = 0X2 4804ad58 1 C 3 = 0X3 4804b3f0 2 C 4 = 0X4 4804ba88 3 C 5 = 0X5 states: Exit Idle Chunk Lru Sat 25 Mar 14:07:09 2000 Informix Dynamic Server Version 7.30.FC7 -- On- Line (Prim) (CKPT REQ) -- Up 34 days 20:33:18 -- 737280 Kbytes Blocked:CKPT Fg Writes LRU Writes Chunk Writes 94 1000796 100124 address flusher state data 4804a6c0 0 I 0 = 0X0 4804ad58 1 C 3 = 0X3 4804b3f0 2 C 4 = 0X4 4804ba88 3 C 5 = 0X5 states: Exit Idle Chunk Lru Sat 25 Mar 14:08:10 2000 Informix Dynamic Server Version 7.30.FC7 -- On- Line (Prim) (CKPT REQ) -- Up 34 days 20:34:18 -- 737280 Kbytes Blocked:CKPT Fg Writes LRU Writes Chunk Writes 94 1000796 145820 address flusher state data 4804a6c0 0 I 0 = 0X0 4804ad58 1 C 3 = 0X3 4804b3f0 2 C 4 = 0X4 4804ba88 3 C 5 = 0X5 states: Exit Idle Chunk Lru Sat 25 Mar 14:09:11 2000 Informix Dynamic Server Version 7.30.FC7 -- On- Line (Prim) (CKPT REQ) -- Up 34 days 20:35:19 -- 737280 Kbytes Blocked:CKPT Fg Writes LRU Writes Chunk Writes 94 1000796 195627 address flusher state data 4804a6c0 0 I 0 = 0X0 4804ad58 1 C 3 = 0X3 4804b3f0 2 I 0 = 0X0 4804ba88 3 C 5 = 0X5 states: Exit Idle Chunk Lru Sat 25 Mar 14:10:11 2000 Informix Dynamic Server Version 7.30.FC7 -- On- Line (Prim) (CKPT REQ) -- Up 34 days 20:36:19 -- 737280 Kbytes Blocked:CKPT Fg Writes LRU Writes Chunk Writes 94 1000796 252040 address flusher state data 4804a6c0 0 I 0 = 0X0 4804ad58 1 I 0 = 0X0 4804b3f0 2 I 0 = 0X0 4804ba88 3 C 5 = 0X5 states: Exit Idle Chunk Lru Sat 25 Mar 14:11:12 2000 Informix Dynamic Server Version 7.30.FC7 -- On- Line (Prim) -- Up 34 days 20:37:20 -- 737280 Kbytes --------- All done. Fg Writes LRU Writes Chunk Writes 94 1005001 297183 address flusher state data 4804a6c0 0 I 0 = 0X0 4804ad58 1 I 0 = 0X0@@NL@

I see two problems. You have 300,000 buffers (220,000 of which were dirty when the checkpoint came up) in only 24 LRUS with only 4 CLEANERS. First problem, not enough LRU queues. I'd be willing to bet that your Bufwaits Ratio is above 10%. I would want 128 LRUS with that many BUFFERS (and indeed that's what we use). Second problem, not enough CLEANERS to clean the LRUS you have quickly enough. This is one cause of the extended checkpoint and also of the FG writes. The slow flushing did not release buffers for reuse before they were needed again. Rule of thumb CLEANERS >= LRUS. Are you using KAIO? If not you do not have enough AIO VPS. Art S. Kagel goodbodyj@my-deja.com wrote: > > IDS 7.30FC7, under Tru64 4.0F on an 8 CPU 5/625 > Digital (Compaq) Alpha Server. 6Gb RAM. > > It’s long checkpoints again, but with a new twist > I think! > > After happily processing a heavy (CPU 80% busy) > OLTP workload for 2 hours, IDS decided to dump > large amounts of data from shared memory to > disk. The writes start as LRU writes but when > the checkpoint timer expires the system locks in > a "checkpoint" for about 4 minutes, frantically > writing to disk. To add insult to injury the > checkpoint is reported as being just a few > seconds long in the log file! > > I know that onstat -R would be handy to > investigate this issue, unfortunately I don’t > have it for this occurrence. > > My questions are: > > Does anyone know why IDS decides to dump such a > large amount of data from shared memory to disk > all of a sudden? Note the previous checkpoint > was not long ago so I would have expected the > buffers to be fairly clean. Around this time the > system was no busier than it had been for the > previous couple of hours. > > Any ideas why the checkpoint is reported as being > for just a few seconds, when the cleaners were > frantically doing chunk writes for a few minutes? > > Here’s some onstat -F > > --------- All quiet... > > Informix Dynamic Server Version 7.30.FC7 -- On- > Line (Prim) -- Up 34 days 20:27:14 -- 737280 > Kbytes > > Fg Writes LRU Writes Chunk Writes > 0 868729 73788 > > address flusher state data > 4804a6c0 0 I 0 = > 0X0 > 4804ad58 1 I 0 = > 0X0 > 4804b3f0 2 I 0 = > 0X0 > 4804ba88 3 I 0 = > 0X0 > states: Exit Idle Chunk Lru > > --------- Cleaning cuts in... > > Sat 25 Mar 14:02:06 2000 > > Informix Dynamic Server Version 7.30.FC7 -- On- > Line (Prim) -- Up 34 days 20:28:14 -- 737280 > Kbytes > > Fg Writes LRU Writes Chunk Writes > 0 893814 73788 > > address flusher state data > 4804a6c0 0 L 33 = > 0X21 > 4804ad58 1 L 11 = > 0Xb > 4804b3f0 2 I 0 = > 0X0 > 4804ba88 3 L 9 = > 0X9 > states: Exit Idle Chunk Lru > > Sat 25 Mar 14:03:07 2000 > > Informix Dynamic Server Version 7.30.FC7 -- On- > Line (Prim) -- Up 34 days 20:29:15 -- 737280 > Kbytes > > --------- AAH, foreground writes... > > Fg Writes LRU Writes Chunk Writes > 38 924042 73788 > > address flusher state data > 4804a6c0 0 L 29 = > 0X1d > 4804ad58 1 L 4 = > 0X4 > 4804b3f0 2 L 37 = > 0X25 > 4804ba88 3 L 26 = > 0X1a > states: Exit Idle Chunk Lru > > Sat 25 Mar 14:04:08 2000 > > Informix Dynamic Server Version 7.30.FC7 -- On- > Line (Prim) -- Up 34 days 20:30:16 -- 737280 > Kbytes > > Fg Writes LRU Writes Chunk Writes > 89 947514 73788 > > address flusher state data > 4804a6c0 0 L 29 = > 0X1d > 4804ad58 1 L 4 = > 0X4 > 4804b3f0 2 L 37 = > 0X25 > 4804ba88 3 L 26 = > 0X1a > states: Exit Idle Chunk Lru > > Sat 25 Mar 14:05:08 2000 > > Informix Dynamic Server Version 7.30.FC7 -- On- > Line (Prim) -- Up 34 days 20:31:16 -- 737280 > Kbytes > > Fg Writes LRU Writes Chunk Writes > 94 976460 73788 > > address flusher state data > 4804a6c0 0 L 39 = > 0X27 > 4804ad58 1 L 10 = > 0Xa > 4804b3f0 2 L 25 = > 0X19 > 4804ba88 3 L 18 = > 0X12 > states: Exit Idle Chunk Lru > > Sat 25 Mar 14:06:09 2000 > > Informix Dynamic Server Version 7.30.FC7 -- On- > Line (Prim) (CKPT REQ) -- Up 34 days 20:32:17 -- > 737280 Kbytes > Blocked:CKPT > > --------- In to the checkpoint... > > Fg Writes LRU Writes Chunk Writes > 94 1000796 74732 > > address flusher state data > 4804a6c0 0 C 2 = > 0X2 > 4804ad58 1 C 3 = > 0X3 > 4804b3f0 2 C 4 = > 0X4 > 4804ba88 3 C 5 = > 0X5 > states: Exit Idle Chunk Lru > > Sat 25 Mar 14:07:09 2000 > > Informix Dynamic Server Version 7.30.FC7 -- On- > Line (Prim) (CKPT REQ) -- Up 34 days 20:33:18 -- > 737280 Kbytes > Blocked:CKPT > > Fg Writes LRU Writes Chunk Writes > 94 1000796 100124 > > address flusher state data > 4804a6c0 0 I 0 = > 0X0 > 4804ad58 1 C 3 = > 0X3 > 4804b3f0 2 C 4 = > 0X4 > 4804ba88 3 C 5 = > 0X5 > states: Exit Idle Chunk Lru > > Sat 25 Mar 14:08:10 2000 > > Informix Dynamic Server Version 7.30.FC7 -- On- > Line (Prim) (CKPT REQ) -- Up 34 days 20:34:18 -- > 737280 Kbytes > Blocked:CKPT > > Fg Writes LRU Writes Chunk Writes > 94 1000796 145820 > > address flusher state data > 4804a6c0 0 I 0 = > 0X0 > 4804ad58 1 C 3 = > 0X3 > 4804b3f0 2 C 4 = > 0X4 > 4804ba88 3 C 5 = > 0X5 > states: Exit Idle Chunk Lru > > Sat 25 Mar 14:09:11 2000 > > Informix Dynamic Server Version 7.30.FC7 -- On- > Line (Prim) (CKPT REQ) -- Up 34 days 20:35:19 -- > 737280 Kbytes > Blocked:CKPT > > Fg Writes LRU Writes Chunk Writes > 94 1000796 195627 > > address flusher state data > 4804a6c0 0 I 0 = > 0X0 > 4804ad58 1 C 3 = > 0X3 > 4804b3f0 2 I 0

Great, thanks very much Art. See below for some onstat -p output around this time. Correct me if I'm wrong, but bufwaits look OK to me until I hit the bad patch from around 14:05. I am left wondering how I managed to get 220,000 dirty buffers when I had a checkpoint just a few minutes earlier. I appreciate this is more of an application issue than an Informix one. However, the application appears to have been doing a similar load of work to what had been done for the last two hours. Could Informix get confused and suddenly mark buffers as dirty which are really clean? The LRUs and cleaners should help, but with the data tables striped over only 4 mirrored pairs, if I get 220,000 dirty buffers I think the disks are going to max-out pretty easily. Thanks again for your response and all the other useful ones I've learnt from! John. Sat 25 Mar 14:03:07 2000 Informix Dynamic Server Version 7.30.FC7 -- On-Line (Prim) -- Up 34 days 20:29:15 -- 737280 Kbytes Profile dskreads pagreads bufreads %cached dskwrits pagwrits bufwrits %cached 124813 126457 120039477 99.90 1246269 1767960 4540776 72.55 isamtot open start read write rewrite delete commit rollbk 99258491 10299233 11870032 42335601 627956 548555 9 223882 36 gp_read gp_write gp_rewrt gp_del gp_alloc gp_free gp_curs 0 0 0 0 0 0 0 ovlock ovuserthread ovbuff usercpu syscpu numckpts flushes 0 0 38 26235.02 1130.75 26 54 ----- bufwaits OK here? bufwaits lokwaits lockreqs deadlks dltouts ckpwaits compress seqscans 7711 40178 98886539 36 0 221 66347 2224 ixda-RA idx-RA da-RA RA-pgsused lchwaits 235 0 7702 5984 206999 Sat 25 Mar 14:04:08 2000 Informix Dynamic Server Version 7.30.FC7 -- On-Line (Prim) -- Up 34 days 20:30:16 -- 737280 Kbytes Profile dskreads pagreads bufreads %cached dskwrits pagwrits bufwrits %cached 133669 136011 120707975 99.89 1272289 1795982 4739884 73.16 isamtot open start read write rewrite delete commit rollbk 99535772 10323195 11907511 42434903 639051 549867 9 229842 36 gp_read gp_write gp_rewrt gp_del gp_alloc gp_free gp_curs 0 0 0 0 0 0 0 ovlock ovuserthread ovbuff usercpu syscpu numckpts flushes 0 0 89 26295.57 1139.25 26 54 -- bufwaits increasing faster then usual... bufwaits lokwaits lockreqs deadlks dltouts ckpwaits compress seqscans 8757 40247 99118918 36 0 221 66407 2261 ixda-RA idx-RA da-RA RA-pgsused lchwaits 1609 0 12607 11414 207146 Sat 25 Mar 14:05:09 2000 Informix Dynamic Server Version 7.30.FC7 -- On-Line (Prim) -- Up 34 days 20:31:17 -- 737280 Kbytes Profile dskreads pagreads bufreads %cached dskwrits pagwrits bufwrits %cached 137381 140356 121047576 99.89 1299784 1825632 4748770 72.63 isamtot open start read write rewrite delete commit rollbk 99825577 10353370 11942546 42557602 640658 551448 9 230392 36 gp_read gp_write gp_rewrt gp_del gp_alloc gp_free gp_curs 0 0 0 0 0 0 0 ovlock ovuserthread ovbuff usercpu syscpu numckpts flushes 0 0 94 26363.38 1148.30 26 54 bufwaits lokwaits lockreqs deadlks dltouts ckpwaits compress seqscans 10075 40375 99406064 36 0 221 66476 2262 ixda-RA idx-RA da-RA RA-pgsused lchwaits 3592 0 12607 13265 207355 Sat 25 Mar 14:06:09 2000 Informix Dynamic Server Version 7.30.FC7 -- On-Line (Prim) (CKPT REQ) -- Up 34 days 20:32:17 -- 737280 Kbytes Blocked:CKPT Profile dskreads pagreads bufreads %cached dskwrits pagwrits bufwrits %cached 140679 143808 121256319 99.88 1325417 1851960 4753863 72.12 isamtot open start read write rewrite delete commit rollbk 100004720 10371078 11963852 42634290 641569 552357 9 230702 36 gp_read gp_write gp_rewrt gp_del gp_alloc gp_free gp_curs 0 0 0 0 0 0 0 ovlock ovuserthread ovbuff usercpu syscpu numckpts flushes 0 0 94 26404.20 1155.27 26 55 bufwaits lokwaits lockreqs deadlks dltouts ckpwaits compress seqscans 11633 40453 99581413 36 0 229 66513 2263 ixda-RA idx-RA da-RA RA-pgsused lchwaits 6136 0 12607 15776 207423 Sat 25 Mar 14:07:10 2000 Informix Dynamic Server Version 7.30.FC7 -- On-Line (Prim) (CKPT REQ) -- Up 34 days 20:33:18 -- 737280 Kbytes Blocked:CKPT Profile dskreads pagreads bufreads %cached dskwrits pagwrits bufwrits %cached 145301 148711 121314429 99.88 1350793 1877074 4753863 71.59 isamtot open start read write rewrite delete commit rollbk 100056248 10371511 11969549 42662159 641569 552361 9 230702 36 gp_read gp_write gp_rewrt gp_del gp_alloc gp_free gp_curs 0 0 0 0 0 0 0 ovlock ovuserthread ovbuff usercpu syscpu numckpts flushes 0 0 94 26409.30 1158.82 26 55 ------ bufwaits now getting really nasty... bufwaits lokwaits lockreqs deadlks dltouts ckpwaits compress seqscans 14334 40454 99621551 36 0 235 66513 2276 ixda-RA idx-RA da-RA RA-pgsused lchwaits 10605 0 12607 20226 207448 Sat 25 Mar 14:08:10 2000 Informix Dynamic Server Version 7.30.FC7 -- On-Line (Prim) (CKPT REQ) -- Up 34 days 20:34:18 -- 737280 Kbytes Blocked:CKPT Profile dskreads pagreads bufreads %cached dskwrits pagwrits bufwrits %cached 145301 148711 121318891 99.88 1396489 1922976 4753863 70.62 isamtot open start read write rewrite delete commit rollbk 100059788 10371875 11969908 42663543 641569 552361 9 230702 36 gp_read gp_write gp_rewrt gp_del gp_alloc gp_free gp_curs 0 0 0 0 0 0 0 ovlock ovuserthread ovbuff usercpu syscpu numckpts flushes 0 0 94 26412.32 1162.83 26 55 ------ Some minutes of bufwait calm... bufwaits lokwaits lockreqs deadlks dltouts ckpwaits compress seqscans 14334 40456 99624484 36 0 235 66513 2277 ixda-RA idx-RA da-RA RA-pgsused lchwaits 10605 0 12607 20226 207472 Sat 25 Mar 14:09:11 2000 Informix Dynamic Server Version 7.30.FC7 -- On-Line (Prim) (CKPT REQ) -- Up 34 days 20:35:19 -- 737280 Kbytes Blocked:CKPT Profile dskreads pagreads bufreads %cached dskwrits pagwrits bufwrits %cached 145341 148802 121348741 99.88 1446280 1972935 4753863 69.58 isamtot open start read write rewrite delete commit rollbk 1000