Re: Long Checkpoint - Not Reported in online.log
goodbodyj@my-deja.com wrote:
> 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.
>
Looks OK to me also, around 1.2% at the end.
>
> I am left wondering how I managed to get 220,000 dirty buffers when I
>
Well at 20:29:15 you had 4,540,776 bufwrits and 1,767,960 pagwrits. When
the
checkpoint started, at 20:32:17, you had 4,753,863 bufwrits indicating that
212,909
buffers had been written to, you also had 1,851,960 pagwrits at this
point. By the
end of the checkpoint at 20:37:20 you had 2,084,195 pagwrits indicating
that during
and immediately after the checkpoint 232,235 buffers had been written to
disk.
Now some of the pagwrit activity during a checkpoint is logical and
physical log
buffer pages probably but that still seems to indicate that most of the
212,909 buffers
written to in the 3 minutes and 2 seconds immediately before the checkpoint
were
distinct buffers rather then rewritting of the same page.
> 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?
>
I've never seen it do that, and the onstat evidence seems to indicate some
VERY
active (or runaway) process is the culprit.
Art S. Kagel
>
> 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
> Bloc