Hi,
I am trying to improve performance of a 10.2.0.5 database that is suffering from high log file sync waits. AWR reports show that it practically never drops below 20% of database time, normally it's 20-30%, and it's constantly top non-idle wait event. For many sessions it's taking 80-90% time or even more.
Log file parallel write is an order of magnitude lower, so it's probably not an I/O issue. The database is performing about 100 commits per second, the user-call-to-commit ratio is about 20, redo generated 500k/s, log buffer is 14Mb big. There are about 6-7 log file switches per hour on the average.
There are several oddities about log file sync waits here and I would appreciate any help sorting them out:
1) there are almost two log file sync wait events per a commit on the average (the number of log file parallel waits is roughly same as the number of commits). Why?
2) according to ASH, about half of log file sync waits take close to 97.7 ms. Is there anything particular reason for such a sharp peak?
3) about 0.5% of log file sync waits captured by ASH show multisecond wait times. Any idea where these might come from and/or how to diagnose this kind of a problem?
Selected portions of an AWR report are found below, please let me know if anything else is needed.
Best regards,
Nikolay
Cache Sizes
~~~~~~~~~~~ Begin End
---------- ----------
Buffer Cache: 44,592M 44,672M Std Block Size: 16K
Shared Pool Size: 3,104M 3,024M Log Buffer: 14,288K
Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 545,833.77 6,659.29
Logical reads: 225,711.23 2,753.73
Block changes: 1,788.11 21.82
Physical reads: 1,195.98 14.59
Physical writes: 119.02 1.45
User calls: 2,368.64 28.90
Parses: 737.35 9.00
Hard parses: 94.58 1.15
Sorts: 261.75 3.19
Logons: 5.93 0.07
Executes: 1,796.12 21.91
Transactions: 81.97
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time 23,580 19.8
log file sync 491,840 21,976 45 18.5 Commit
db file sequential read 1,902,069 12,604 7 10.6 User I/O
read by other session 743,414 4,159 6 3.5 User I/O
log file parallel write 220,772 3,069 14 2.6 System I/O
-------------------------------------------------------------
Instance Activity Stats ******************
Statistic Total per Second per Trans
-------------------------------- ------------------ -------------- -------------
Cached Commit SCN referenced 11,130 3.1 0.0
Commit SCN cached 3 0.0 0.0
DB time 12,547,531 3,483.3 42.5
DBWR checkpoint buffers written 145,437 40.4 0.5
DBWR checkpoints 6 0.0 0.0
...
IMU CR rollbacks 2,566 0.7 0.0
IMU Flushes 36,411 10.1 0.1
IMU Redo allocation size 187,480,124 52,045.3 635.0
IMU commits 255,350 70.9 0.9
IMU contention 11,998 3.3 0.0
IMU ktichg flush 11 0.0 0.0
IMU pool not allocated 4,295 1.2 0.0
IMU recursive-transaction flush 175 0.1 0.0
IMU undo allocation size 2,029,937,952 563,519.5 6,875.1
IMU- failed to get a private str 4,295 1.2 0.0
...
background checkpoints completed 6 0.0 0.0
background checkpoints started 6 0.0 0.0
background timeouts 11,400 3.2 0.0
...
change write time 9,398 2.6 0.0
cleanout - number of ktugct call 54,233 15.1 0.2
cleanouts and rollbacks - consis 9,436 2.6 0.0
cleanouts only - consistent read 2,028 0.6 0.0
...
Instance Activity Stats *******************
Statistic Total per Second per Trans
-------------------------------- ------------------ -------------- -------------
commit batch performed 61 0.0 0.0
commit batch requested 61 0.0 0.0
commit batch/immediate performed 94 0.0 0.0
commit batch/immediate requested 94 0.0 0.0
commit cleanout failures: block 51 0.0 0.0
commit cleanout failures: buffer 14 0.0 0.0
commit cleanout failures: callba 8,632 2.4 0.0
commit cleanout failures: cannot 10,575 2.9 0.0
commit cleanouts 991,186 275.2 3.4
commit cleanouts successfully co 971,914 269.8 3.3
commit immediate performed 33 0.0 0.0
commit immediate requested 33 0.0 0.0
commit txn count during cleanout 61,737 17.1 0.2
...
redo blocks written 4,078,889 1,132.3 13.8
redo buffer allocation retries 177 0.1 0.0
redo entries 1,924,106 534.1 6.5
redo log space requests 174 0.1 0.0
redo log space wait time 2,333 0.7 0.0
redo ordering marks 4,553 1.3 0.0
redo size 1,966,229,700 545,833.8 6,659.3
redo subscn max counts 38,227 10.6 0.1
redo synch time 2,233,166 619.9 7.6
redo synch writes 352,935 98.0 1.2
redo wastage 56,259,980 15,618.0 190.5
redo write time 316,495 87.9 1.1
redo writer latching time 19 0.0 0.0
redo writes 220,866 61.3 0.8
rollback changes - undo records 134 0.0 0.0
rollbacks only - consistent read 11,242 3.1 0.0
...
...
transaction rollbacks 94 0.0 0.0
transaction tables consistent re 25 0.0 0.0
transaction tables consistent re 8,704 2.4 0.0
undo change vector size 1,176,156,772 326,506.2 3,983.5
user I/O wait time 2,039,881 566.3 6.9
user calls 8,532,422 2,368.6 28.9
user commits 295,139 81.9 1.0
user rollbacks 122 0.0 0.0
...
-------------------------------------------------------------