Re: one hour checkpoints

From: Christo Kutrovsky <kutrovsky.oracle_at_gmail.com>
Date: Thu, 25 Jan 2007 11:31:46 -0500
Message-ID: <52a152eb0701250831s5a2f8c9dy659b33155e24e7d4@mail.gmail.com>

Amonte,

Yes you are right, dbwr does write in batches, whenever possible. So this logic does not apply all the time. It was a maximum number of possible writes.

I think Tanel's explalanation is more accurate with what's happening in your case.

What I was trying to say is that there is no direct relationship between size of redo and amount of time it takes to checkpoint those changes. So sometimes it may take 2 hours to checkpoint 600mb of redo, other times it may take 6 seconds, all depending on how many block changed, and how many ios dbwriter is doing. Note: async IO also plays a big role here. If you have it on, then dbwr will submit a lot of ios to the OS. If you have it off (or not working) it will be 1 io, wait for finish, next io, wait for finish. Of course 1 io could be more then 1 block.

Where did you check the block size?

-- 
Christo Kutrovsky
Senior Database/System Administrator
The Pythian Group - www.pythian.com
I blog at http://www.pythian.com/blogs/

On 1/25/07, amonte <ax.mount_at_gmail.com> wrote:


> Christo

>

> Are you saying checkpoints write a block per I/O? I thought DBWR write

> blocks in batches and not single blocks. Your theory doesnt sound right to

> me. I have another database which generates 24GB redo per hour, if I use

> your calculation 24GB will be 50331648 blocks then my I/O time would be

>

> 1000/(50331648/3600) = 0.0715 ms

>

> Isnt that a bit too fast?

>

> TIA

>

> Alex

>

>

>

>

> On 1/24/07, Christo Kutrovsky < kutrovsky.oracle_at_gmail.com> wrote:

> > Well, in theory, 600mb of redo log could be 1'228'800 blocks changed.

> > That's 629145600 bytes of redo log, with a redo record been 512 bytes.

> >

> > That's only an approximation, since you could have merged records,

> > multiple changes in a single record and etc.

> >

> > Let's assume a typical IO time of 5 ms. That would be 1228800*5ms =

> > 6'144'000 ms = 6'144 seconds = 1.7 hours.

> >

> > So it could've taken 1.7 hours. And that's been optimistic about the

> > 5ms IO. It could've been 10 ms during busy times.

> >

> > It's not as bad as it sounds.

> >

> > --

> > Christo Kutrovsky

> > Senior Database/System Administrator

> > The Pythian Group - www.pythian.com

> > I blog at http://www.pythian.com/blogs/

> >

> >

> > On 1/18/07, amonte <ax.mount_at_gmail.com> wrote:

> > > Hello all

> > >

> > > I have a quite busy Oracle APPS database running in HPUX. Today during

> peak

> > > hour I saw this in alert

> > >

> > > Thu Jan 18 10:19:50 2007

> > > Beginning log switch checkpoint up to RBA [0x17d1.2.10], SCN:

> > > 0x0784.b14a52c1

> > > Thu Jan 18 10:22:09 2007

> > > Beginning log switch checkpoint up to RBA [ 0x17d2.2.10], SCN:

> > > 0x0784.b14a8673

> > > Thu Jan 18 10:26:18 2007

> > > Beginning log switch checkpoint up to RBA [0x17d3.2.10], SCN:

> > > 0x0784.b14aee22

> > > Thu Jan 18 10:51:32 2007

> > > Beginning log switch checkpoint up to RBA [ 0x17d4.2.10], SCN:

> > > 0x0784.b14d0ddb

> > > Thu Jan 18 11:09:24 2007

> > > Beginning log switch checkpoint up to RBA [0x17d5.2.10], SCN:

> > > 0x0784.b14ea5dd

> > > .........................

> > > Thu Jan 18 11:12:04 2007

> > > Completed checkpoint up to RBA [0x17d1.2.10], SCN: 0x0784.b14a52c1

> > > Thu Jan 18 11:16:19 2007

> > > Completed checkpoint up to RBA [0x17d2.2.10], SCN: 0x0784.b14a8673

> > > Thu Jan 18 11:16:45 2007

> > > Completed checkpoint up to RBA [ 0x17d3.2.10], SCN: 0x0784.b14aee22

> > > Thu Jan 18 11:18:22 2007

> > > Completed checkpoint up to RBA [0x17d4.2.10], SCN: 0x0784.b14d0ddb

> > > Thu Jan 18 11:23:56 2007

> > > Completed checkpoint up to RBA [ 0x17d5.2.10 ], SCN: 0x0784.b14ea5dd

> > >

> > >

> > >

> > > From v$log_histroty I see the log switch frequency

> > >

> > > select * from v$log_history

> > > where FIRST_TIME > ('20070118 090000');

> > >

> > >      RECID      STAMP    THREAD#  SEQUENCE#

>  FIRST_CHANGE#

> > > FIRST_TIME          NEXT_CHANGE#

> > > ---------- ---------- ---------- ---------- ----------------------

> > > --------------- ----------------

> > >       6096  612181190          1       6096

> 8266491016370 20070118

> > > 090018    8266491515585

> > >       6097  612181328          1       6097

> 8266491515585 20070118

> > > 101949    8266491528819

> > >       6098  612181578          1       6098

> 8266491528819 20070118

> > > 102208    8266491555362

> > >       6099  612183092          1       6099

> 8266491555362 20070118

> > > 102618    8266491694555

> > >       6100  612184164          1       6100

> 8266491694555 20070118

> > > 105132    8266491799005

> > >       6101  612185404          1       6101

> 8266491799005 20070118

> > > 110923    8266491936643

> > >

> > >

> > > Redo log are 600MB each.

> > >

> > > How can a checkpoint take so long?

> > >

> > >

> > >

> > > Cheers

> > >

> > > Alex

> > >

> > >

> >

> >

> > --

> > Christo Kutrovsky

> > Senior Database/System Administrator

> > The Pythian Group - www.pythian.com

> > I blog at http://www.pythian.com/blogs/

> >

>

>



-- 
Christo Kutrovsky
Senior Database/System Administrator
The Pythian Group - www.pythian.com
I blog at http://www.pythian.com/blogs/
--
http://www.freelists.org/webpage/oracle-l

Received on Thu Jan 25 2007 - 10:31:46 CST