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

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

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? Received on Wed Nov 05 2008 - 06:54:08 CST