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

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/waitevents003.htm#BGGIBDJI

jg

--
@home.com is bogus.
Ya win some, ya lose some.