Home » RDBMS Server » Performance Tuning » High System I/O Wait Class on AWR (Oracle 10.2.0.4 EE 64-bit, Solaris 10)
High System I/O Wait Class on AWR [message #573992] Fri, 04 January 2013 19:24 Go to next message
cklh2000
Messages: 8
Registered: January 2013
Junior Member
Hi, I am currently looking into a performance issue on an OLTP database. Here are some statistics from the 60 minutes AWR report.

From the Load Profile, transaction / sec and transaction size is not too extreme.

I cannot figure out why does it take so long for the commit and write to the system.

When looking the system statistics IO wait time is 0.

Can anyone advise what could the issue here?

Thank you very much!!

Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
log file sync                       145,634       5,359     37   74.0     Commit
db file parallel write               40,891       3,324     81   45.9 System I/O
log file parallel write             126,741       2,755     22   38.0 System I/O
CPU time                                          1,887          26.1
control file parallel write           1,613         137     85    1.9 System I/O
          -------------------------------------------------------------

                                                                  Avg
                                       %Time       Total Wait    wait     Waits
Wait Class                      Waits  -outs         Time (s)    (ms)      /txn
-------------------- ---------------- ------ ---------------- ------- ---------
System I/O                    172,667     .0            6,216      36       1.7
Commit                        145,634     .0            5,359      37       1.5
Application                    86,572     .0               21       0       0.9
Network                     2,324,023     .0                8       0      23.2
User I/O                          273     .0                6      21       0.0
Other                           2,645     .0                3       1       0.0
Concurrency                     4,756     .7                2       0       0.0
Configuration                   1,454     .0                1       1       0.0
          -------------------------------------------------------------


Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:             46,782.35              1,688.79
              Logical reads:              5,463.19                197.21
              Block changes:                422.23                 15.24
             Physical reads:                  0.09                  0.00
            Physical writes:                 44.53                  1.61
                 User calls:                827.33                 29.87
                     Parses:                435.42                 15.72
                Hard parses:                  0.00                  0.00
                      Sorts:                 24.11                  0.87
                     Logons:                  0.01                  0.00
                   Executes:                661.11                 23.87
               Transactions:                 27.70

Wait Events                              DB/Inst: USRSE/usrse  Snaps: 465-469
-> s  - second
-> cs - centisecond -     100th of a second
-> ms - millisecond -    1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

                                                                   Avg
                                             %Time  Total Wait    wait     Waits
Event                                 Waits  -outs    Time (s)    (ms)      /txn
---------------------------- -------------- ------ ----------- ------- ---------
log file sync                       145,634     .0       5,359      37       1.5
db file parallel write               40,891     .0       3,324      81       0.4
log file parallel write             126,741     .0       2,755      22       1.3
control file parallel write           1,613     .0         137      85       0.0
SQL*Net break/reset to clien         86,572     .0          21       0       0.9
SQL*Net message to client         2,323,913     .0           8       0      23.2
db file sequential read                 174     .0           6      33       0.0
enq: TX - contention                  1,575     .0           2       1       0.0
os thread startup                         8     .0           1     150       0.0
enq: HW - contention                  1,412     .0           1       1       0.0
control file sequential read          3,422     .0           0       0       0.0
row cache lock                          755     .0           0       1       0.0
buffer busy waits                     3,627     .0           0       0       0.0
rdbms ipc reply                          58     .0           0       7       0.0
cursor: pin S wait on X                  34   91.2           0       9       0.0
latch free                                8     .0           0      28       0.0
enq: SQ - contention                     41     .0           0       1       0.0
latch: cache buffers chains             323     .0           0       0       0.0
LGWR wait for redo copy                 802     .0           0       0       0.0
db file scattered read                   94     .0           0       0       0.0
SQL*Net more data to client              64     .0           0       0       0.0
direct path write                         5     .0           0       1       0.0
latch: In memory undo latch               9     .0           0       0       0.0
cursor: pin S                           202     .0           0       0       0.0
SQL*Net more data from clien             46     .0           0       0       0.0
latch: redo writing                       1     .0           0       0       0.0
SQL*Net message from client       2,323,916     .0     120,921      52      23.2
Streams AQ: qmn slave idle w            129     .0       3,510   27213       0.0
Streams AQ: qmn coordinator             258   50.0       3,510   13606       0.0
Streams AQ: waiting for time              1  100.0       3,469 #######       0.0
class slave wait                          9     .0           0       0       0.0
          -------------------------------------------------------------

Operating System Statistics               DB/Inst: USRSE/usrse  Snaps: 465-469

Statistic                                       Total
-------------------------------- --------------------
AVG_BUSY_TIME                                  41,929
AVG_IDLE_TIME                                 319,218
AVG_IOWAIT_TIME                                     0
AVG_SYS_TIME                                   12,531
AVG_USER_TIME                                  29,288
BUSY_TIME                                     336,295
IDLE_TIME                                   2,554,540
IOWAIT_TIME                                         0
SYS_TIME                                      101,141
USER_TIME                                     235,154
LOAD                                                1
OS_CPU_WAIT_TIME                              164,400
RSRC_MGR_CPU_WAIT_TIME                              0
VM_IN_BYTES                                         0
VM_OUT_BYTES                                        0
PHYSICAL_MEMORY_BYTES                  33,727,037,440
NUM_CPUS                                            8

-------------------------------------------------------------
*BlackSwan added {code} tags & please do so yourself in the future!

[Updated on: Fri, 04 January 2013 19:46] by Moderator

Report message to a moderator

Re: High System I/O Wait Class on AWR [message #573993 is a reply to message #573992] Fri, 04 January 2013 19:45 Go to previous messageGo to next message
BlackSwan
Messages: 23024
Registered: January 2009
Senior Member
Please read and follow the forum guidelines, to enable us to help you:

http://www.orafaq.com/forum/t/88153/0/

> Here are some statistics from the 60 minutes AWR report.

way too long a period

snapshot duration should be 15 or no longer than 30 minutes.

[Updated on: Fri, 04 January 2013 19:48]

Report message to a moderator

Re: High System I/O Wait Class on AWR [message #574007 is a reply to message #573993] Sat, 05 January 2013 01:11 Go to previous messageGo to next message
John Watson
Messages: 4791
Registered: January 2010
Location: Global Village
Senior Member
@BS, I disagree with you (unusual Smile) I find that the one hour default for AWR snapshots is fine, and that often a report spanning a few hours is useful. Then for finer analysis, use ASH. No need to change the snapshot frequency. But of course that is only the way I happen to work.
Re: High System I/O Wait Class on AWR [message #574008 is a reply to message #573992] Sat, 05 January 2013 01:22 Go to previous messageGo to next message
John Watson
Messages: 4791
Registered: January 2010
Location: Global Village
Senior Member
Welcome to the forum.
Can you post the entire report, as an attachment? Then proceed to the first step: do you actually have a problem?
For example: no end user has ever telephoned the help desk to complain that the log file sync wait event is too high. They say things like "a report takes too long; the batch jobs do not complete in time; this form does not respond" that sort of thing. With the complete report and the problem, we can find the SQL whose execution needs to be improved.
Re: High System I/O Wait Class on AWR [message #574011 is a reply to message #573993] Sat, 05 January 2013 02:42 Go to previous messageGo to next message
cklh2000
Messages: 8
Registered: January 2013
Junior Member
Thank you BlackSwan and all.

Currently no users is complainly as the system is not experiencing high request now. I am monitoring the performance of the system and noticed there is a potential IO issue on the db. Now attaching my complete AWR. Please advise.

(NOTE: I have to exclude the top sql from the report because of the confidentiality of the code in the business.)

Thank you again.
Re: High System I/O Wait Class on AWR [message #574012 is a reply to message #574011] Sat, 05 January 2013 03:02 Go to previous messageGo to next message
Michel Cadot
Messages: 59731
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
IO is the purpose of RDBMS.
What is important in your report is the top one:
Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
log file sync                       145,634       5,359     37   74.0     Commit

                                                                   Avg
                                             %Time  Total Wait    wait     Waits
Event                                 Waits  -outs    Time (s)    (ms)      /txn
---------------------------- -------------- ------ ----------- ------- ---------
log file sync                       145,634     .0       5,359      37       1.5

It shows that your log files are far, very far, from the correct size.
How many switch logs have you per hour?
What is the size of your redo log buffer?

Regards
Michel

[Updated on: Sat, 05 January 2013 03:03]

Report message to a moderator

Re: High System I/O Wait Class on AWR [message #574013 is a reply to message #574011] Sat, 05 January 2013 03:06 Go to previous messageGo to next message
John Watson
Messages: 4791
Registered: January 2010
Location: Global Village
Senior Member
You have redacted the information needed: it is difficult to tune SQL that one cannot see. So all one can do is make general recommendations regarding the instance. Two things jump out:
Your log_buffer is too big. I would reduce it from 20M to 5M. That might reduce your log file sync wait events and your system i/o wait events.
You are relying on the default for pga_aggregate_target, it happens to be OK but that is luck. Set it explicitly, I would use 500M.

[Updated on: Sat, 05 January 2013 03:07]

Report message to a moderator

Re: High System I/O Wait Class on AWR [message #574014 is a reply to message #574011] Sat, 05 January 2013 04:01 Go to previous messageGo to next message
LNossov
Messages: 294
Registered: July 2011
Location: Germany
Senior Member
The average duration of one log write is ("redo write time"/"redo writes")*0.01 sec. = (137338 / 54191) * 0.01 = 0.025 sec. It is too slow. You have to check you I/O.
Re: High System I/O Wait Class on AWR [message #574042 is a reply to message #574012] Sun, 06 January 2013 01:03 Go to previous messageGo to next message
cklh2000
Messages: 8
Registered: January 2013
Junior Member
Log size is 536MB, log switch happens every 5 hour or so. Is it because of improper buffer size or IO? Please notes base on the AWR, on the system statistics section, the IO wait is 0. At a moment I suspect the IO is the problem, but there is none IO wait on the AWR and on system sar report. I am confused.

Thank you.
Re: High System I/O Wait Class on AWR [message #574044 is a reply to message #574042] Sun, 06 January 2013 02:01 Go to previous messageGo to next message
John Watson
Messages: 4791
Registered: January 2010
Location: Global Village
Senior Member
I've already told you what I would do.
Re: High System I/O Wait Class on AWR [message #585866 is a reply to message #573992] Thu, 30 May 2013 09:16 Go to previous message
sysdba007
Messages: 28
Registered: November 2012
Junior Member
Hello Michel

First of all sorry to pick this old thread

Could you please suggest what made you conclude that redo logfiles are not sized correctly?

I mean out of the following reasons which is applicable at which symptom for 'log file sync' waits

1) too many commits, say in loop (here we have 27 transactions per seconds, so I guess we eliminated this option, right?)
2) improper log buffer size
3) improper redo log file size
4) redo logs on slower device, RAID etc

Thanks and Regards
sysdba007

Previous Topic: Keep Pool
Next Topic: LogMiner Doubt
Goto Forum:
  


Current Time: Thu Nov 20 16:00:04 CST 2014

Total time taken to generate the page: 0.68936 seconds