Re: log file sync vs log file parallel write probably not bug 2669566

From: HansP <hans-peter.sloot_at_atosorigin.com>
Date: Thu, 6 Nov 2008 01:10:41 -0800 (PST)
Message-ID: <57c00d87-3d29-49dd-8142-228736fda357@s9g2000prg.googlegroups.com>

On 5 nov, 19:57, joel garry <joel-ga..._at_home.com> wrote:
> On Nov 5, 4:54 am, HansP <hans-peter.sl..._at_atosorigin.com> wrote:
>
>
>
> > This is a continuation of  a previous thread about ‘log file sync’ and
> > ‘log file parallel write’ events.
>
> > Version       :  9.2.0.8
> > Platform      : Solaris
> > Application : Oracle Apps
>
> > The number of commits per second ranges between 10 and 30.
>
> > When querying statspack performance data the calculated average wait
> > time on  the event ‘log file sync’ is on average 10 times the wait
> > time for the ‘log file parallel write’  event.
> > Below just 2 samples where the ratio is even about 20.
>
> > "snap_time"         " log file parallel write avg"  "log file sync
> > avg"       "ratio
> > 11/05/2008 10:38:26     8,142
> > 156,343                19.20
> > 11/05/2008 10:08:23             8,434
> > 201,915                23.94
>
> > So the wait time for a ‘log file sync’ is 10 times the wait time for a
> > ‘log file parallel write’.
>
> > First I thought that I was hitting bug 2669566.
> > But then Jonathan Lewis is blog pointed me to Tanel Poder’s snapper
> > tool.
> > And I think that it proves that I am NOT hitting this bug.
>
> > Below is a sample of  the output for the log writer.
>
> > --  End of snap 3
> > HEAD,SID, SNAPSHOT START ,SECONDS,TYPE,STATISTIC                ,
> > DELTA, DELTA/SEC,  HDELTA, HDELTA/SEC
> > DATA, 4, 20081105 10:35:41, 30, STAT, messages sent               ,
> > 1712,     57,        1.71k,       57.07
> > DATA, 4, 20081105 10:35:41, 30, STAT, messages received         ,
> > 866,     29,         866,         28.87
> > DATA, 4, 20081105 10:35:41, 30, STAT, background timeouts       ,
> > 10,      0,           10,           .33
> > DATA, 4, 20081105 10:35:41, 30, STAT, redo wastage                  ,
> > 212820,   7094,      212.82k,   7.09k
> > DATA, 4, 20081105 10:35:41, 30, STAT, redo writer latching
> > time   ,       2,      0,            2,            .07
> > DATA, 4, 20081105 10:35:41, 30, STAT, redo
> > writes                     ,     867,     29,          867,
> > 28.9
> > DATA, 4, 20081105 10:35:41, 30, STAT, redo blocks written          ,
> > 33805,   1127,      33.81k,    1.13k
> > DATA, 4, 20081105 10:35:41, 30, STAT, redo write
> > time                ,     652,     22,          652,        21.73
> > DATA, 4, 20081105 10:35:41, 30, WAIT, rdbms ipc message         ,
> > 23431084, 781036,     23.43s,  781.04ms
> > DATA, 4, 20081105 10:35:41, 30, WAIT, log file parallel
> > write          , 6312957, 210432,     6.31s,   210.43ms
> > DATA, 4, 20081105 10:35:41, 30, WAIT, LGWR wait for redo copy  ,
> > 18749,    625,      18.75ms, 624.97us
>
> > When adding the DELTA/SEC (which is in micro seconds) for the wait
> > events it always roughly adds up to a million micro seconds.
> > In the example above 781036 + 210432 = 991468 micro seconds.
> > This is the case for all the snaps taken by snapper.
> > So I think that the wait time for the ‘log file parallel write time’
> > must be more or less correct.
>
> > So I still have the question “Why is the ‘log file sync’ about 10
> > times the time of the ‘log file parallel write’?”
>
> > Any clues?
>
> This is a wild guess, based on the 10g docs, which may or may not
> apply or work the same:
>
> The log file parallel write includes the I/O time only.  The log file
> sync includes the time the log writer has to wait for the db writer
> to
> tell the log writer the redo is done (all those "private strand flush
> incomplete" notifications in the 10g alert log), as well as all the
> other
> overhead of the interprocess communication.
>
> http://download.oracle.com/docs/cd/B19306_01/server.102/b14237/waitev...
>
> jg
> --
> @home.com is bogus.
> Ya win some, ya lose some.

Hello Joel

Perhaps you are interested in the query on statspack.

select snap_id

       , snap_time
       , event
       , time_waited_micro
       , (time_waited_micro - p_time_waited_micro)/((snap_time -
p_snap_time) * 24) corrected_wait_time_h
       , total_waits
       , (total_waits - p_total_waits)/((snap_time - p_snap_time) *
24) corrected_waits_h
       , (total_waits - p_total_waits)/((snap_time - p_snap_time) *
24)/3600 corrected_waits_s
       , trunc(((time_waited_micro - p_time_waited_micro)/((snap_time

- p_snap_time) * 24))/((total_waits - p_total_waits)/((snap_time - p_snap_time) * 24))) average
from (

   select sn.snap_id, sn.snap_time, se.event, se.time_waited_micro, se.total_waits,

                   lag(sn.snap_id) over (partition by se.event order
by sn.snap_id) p_snap_id,
                   lag(sn.snap_time) over (partition by se.event order
by sn.snap_time) p_snap_time,
                   lag(se.time_waited_micro) over (partition by
se.event order by sn.snap_id) p_time_waited_micro,
                   lag(se.total_waits) over (partition by se.event
order by sn.snap_id) p_total_waits,
                   row_number() over (partition by event order by

sn.snap_id) r

   from perfstat.stats$system_event se, perfstat.stats$snapshot sn    where se.SNAP_ID = sn.SNAP_ID
   and se.EVENT = '&event'
   order by snap_id, event
  )
where time_waited_micro - p_time_waited_micro > 0 order by snap_id desc Received on Thu Nov 06 2008 - 03:10:41 CST