Oracle Database Discussions

You need to address the cause and not a symptom.

Step 1: Fire the consultant. In 10g and higher log_buffer is allocated automatically by Oracle in granules, size of granules is derived from size of the SGA. The size of a granule is usually 4 Mb.
Obviously by decreasing the log buffer, IO activity will increase.

Step 2: Call your lawyer. Problems are being caused by the application. You seem to indicate every individual record is committed. This is impacting the log file sync event.
Also 50 percent rollback indicates the application has to be 'refurbished'.

-----------
Sybrand Bakker
Senior Oracle DBA

Is the time lost on this wait event significant ? What is it in relation to total DB Time ? In relation to transactions per second ? As a value of average wait time in milliseconds ?

There will always be a "Top 5" listing. What a human can do better than a computer is to interpret the values.

Hemant K Chitale

Sorry for late reply.. I am not good at interpeting the awr report. Copied below awr report. pls advise....appreciate ur reply.


Begin Snap: 7210 08-Nov-11 17:00:42 406 27.5
End Snap: 7211 08-Nov-11 17:15:43 404 27.6
Elapsed: 15.01 (mins)
DB Time: 2.22 (mins)


Report Summary
Cache Sizes

Begin End
Buffer Cache: 4,096M 4,096M Std Block Size: 8K
Shared Pool Size: 1,856M 1,856M Log Buffer: 54,060K


Load Profile

Per Second Per Transaction Per Exec Per Call
DB Time(s): 0.2 0.0 0.00 0.00
DB CPU(s): 0.0 0.0 0.00 0.00
Redo size: 21,290.1 1,731.9
Logical reads: 1,211.0 98.5
Block changes: 128.1 10.4
Physical reads: 63.6 5.2
Physical writes: 11.8 1.0
User calls: 63.9 5.2
Parses: 16.6 1.4
Hard parses: 0.0 0.0
W/A MB processed: 1,645,766.6 133,878.1
Logons: 0.1 0.0
Executes: 65.0 5.3
Rollbacks: 8.2 0.7
Transactions: 12.3


Instance Efficiency Percentages (Target 100%)

Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 99.69 In-memory Sort %: 100.00
Library Hit %: 99.98 Soft Parse %: 99.96
Execute to Parse %: 74.46 Latch Hit %: 100.00
Parse CPU to Parse Elapsd %: 0.01 % Non-Parse CPU: 99.23


Shared Pool Statistics

Begin End
Memory Usage %: 79.19 79.18
% SQL with executions>1: 97.95 97.14
% Memory for SQL w/exec>1: 95.18 95.97



Top 5 Timed Foreground Events



Event Waits Time(s) Avg wait (ms) % DB time Wait Class
log file sync 3,473 76 22 57.35 Commit
DB CPU 40 30.32
db file sequential read 2,497 10 4 7.64 User I/O






Foreground Wait Events
s - second, ms - millisecond - 1000th of a second
Only events with Total Wait Time (s) >= .001 are shown
ordered by wait time desc, waits desc (idle events last)
%Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0
Event Waits %Time -outs Total Wait Time (s) Avg wait (ms) Waits /txn % DB time
log file sync 3,473 1 76 22 0.31 57.35
db file sequential read 2,497 0 10 4 0.23 7.64
direct path read 514 0 5 9 0.05 3.56
control file sequential read 1,126 0 1 1 0.10 0.50
rdbms ipc reply 1,299 0 1 0 0.12 0.38
db file scattered read 375 0 0 1 0.03 0.30
library cache pin 2 0 0 63 0.00 0.10
library cache lock 2 0 0 56 0.00 0.08
SQL*Net message to client 49,405 0 0 0 4.46 0.04
row cache lock 458 0 0 0 0.04 0.04
enq: KO - fast object checkpoint 1 0 0 49 0.00 0.04
SQL*Net break/reset to client 354 0 0 0 0.03 0.03
SQL*Net more data to client 183 0 0 0 0.02 0.00
SQL*Net message from client 50,016 0 274,459 5487 4.52
Streams AQ: waiting for messages in the queue 330 100 1,290 3910 0.03
wait for unread message on broadcast channel 910 99 901 990 0.08
jobq slave wait 171 99 510 2983 0.02

Back to Wait Events Statistics
Back to Top


Background Wait Events
ordered by wait time desc, waits desc (idle events last)
Only events with Total Wait Time (s) >= .001 are shown
%Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0
Event Waits %Time -outs Total Wait Time (s) Avg wait (ms) Waits /txn % bg time
db file parallel write 2,186 0 49 22 0.20 46.00
control file parallel write 916 0 31 34 0.08 29.60
log file parallel write 3,817 0 14 4 0.34 13.27
control file sequential read 4,511 0 3 1 0.41 2.96
os thread startup 25 0 0 19 0.00 0.44
log file sequential read 19 0 0 14 0.00 0.24
db file sequential read 10 0 0 5 0.00 0.05
direct path write 14 0 0 3 0.00 0.04
log file single write 2 0 0 12 0.00 0.02
Log archive I/O 43 0 0 0 0.00 0.02
rdbms ipc message 20,662 71 25,126 1216 1.87
gcs remote message 42,871 100 1,801 42 3.87
DIAG idle wait 31,596 100 1,799 57 2.85
ges remote message 10,718 100 901 84 0.97
wait for unread message on broadcast channel 900 100 901 1001 0.08
PING 210 33 900 4287 0.02
fbar timer 3 100 900 300004 0.00
pmon timer 331 91 900 2719 0.03
ASM background timer 216 0 895 4143 0.02
Streams AQ: qmn coordinator idle wait 73 42 892 12221 0.01
Streams AQ: qmn slave idle wait 34 0 892 26240 0.00
smon timer 3 67 817 272176 0.00
KSV master wait 558 97 0 0 0.05

Is that a 22 ms average wait time? Maybe your application just commits a lot.

There are three ways to look at it.
a) The server wasn't used much and database time was only 2.22 minutes in an elapsed time of 15minutes. (total time lost on 'log file sync' was 76seconds in 900seconds.)

b) 'log file sync' waits were, on average, 22ms. That is high ! However, 'log file parallel write' waits were 4ms. Normally, one would say that the lost time is because the process was unable to get onto the CPU to communicate. Oracle's CPU time is very low. Do you happen to have some other processes running on the database server that are consuming CPU at a very high rate ? Do you have processes being paged in and out very very frequently ?

c) A transaction rate of 12.3 per second with 21K of redo per second are also high. But if total database time was low, why are these figures, when averaged out over 15minutes, so high ? Do you have very very sharp spikes in transactions -- a sudden surge of commits for 30seconds or 1minute and then idleness for some minutes thereafter ?


Hemant K Chitale

Out of curiosity, is the application using a sequence with a low cache? Or worse, are you using sequences with nocache? Because if this is the case, your DML will cause recursive transactions that will update and commit the new sequence value. So if you insert 100 rows using a sequence with a cache of 20, before you even issue your transaction's commit, there will have been 5 commits to update sequence values.

Could you check your sequences so we can rule this out? It's an often-overlooked cause of performance issues, and it is evidenced by high log file sync waits.

Hi Hemant

Nice way of explaining. I agree with you on all the points mentioned above. However, why should 21K redo per second be treated as 'high'? Am I missing something?

-Aravind