This is a continuation of  a previous thread about =91log file sync=92 and
=91log file parallel write=92 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 =91log file sync=92 is on average 10 times the wait
time for the =91log file parallel write=92  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 =91log file sync=92 is 10 times the wait time for a
=91log file parallel write=92.

First I thought that I was hitting bug 2669566.
But then Jonathan Lewis is blog pointed me to Tanel Poder=92s 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 =3D 991468 micro seconds.
This is the case for all the snaps taken by snapper.
So I think that the wait time for the =91log file parallel write time=92
must be more or less correct.

So I still have the question =93Why is the =91log file sync=92 about 10
times the time of the =91log file parallel write=92?=94

Any clues?