Suspicious slow I/O actually may not be an issue

OS: AIX 7.1
DB: Oracle 11.2.0.3 single instance
Multipath: MPIO

LGWR trace file was complaining slow LGWR:

*** 2016-08-05 22:08:21.187
Warning: log write elapsed time 103557ms, size 229KB

*** 2016-08-05 22:09:49.053
Warning: log write elapsed time 87866ms, size 181KB

bps is extremely low (smaller than 1M) although I/O utility has reached almost 100%

iostat -D hdisk1 1 
hdisk1         xfer:  %tm_act      bps      tps      bread      bwrtn    
                        98.0    720.9K    88.0        0.0      720.9K
               read:      rps  avgserv  minserv  maxserv   timeouts      fails
                         0.0      0.0      0.0      0.0           0          0
              write:      wps  avgserv  minserv  maxserv   timeouts      fails
                        88.0     11.2      5.0     40.0           0          0
              queue:  avgtime  mintime  maxtime  avgwqsz    avgsqsz     sqfull
                         0.0      0.0      0.0      0.0        1.0         0.0

LGWR was waiting on “log file paralle write”.

SQL> select sid, serial#, event, blocking_session, WAIT_TIME_MICRO
from v$session
where program like '%LGWR%'; 

       SID    SERIAL# EVENT                                                            BLOCKING_SESSION WAIT_TIME_MICRO
---------- ---------- ---------------------------------------------------------------- ---------------- ---------------
       183          1 log file parallel write                                                                   1294373

CKPT was waiting on “control file parallel write”:

SQL> select sid, serial#, event, blocking_session, WAIT_TIME_MICRO
from v$session
where program like '%CKPT%';  2    3  

       SID    SERIAL# EVENT                                                            BLOCKING_SESSION WAIT_TIME_MICRO
---------- ---------- ---------------------------------------------------------------- ---------------- ---------------
       196          1 control file parallel write                                                            1465703832

At first glance, you may suspect that this is a I/O issue. Strangely, all the storage paths are healthy and I/O speed could reach about 100MB/s intermittently. After rebouncing the instance, I did the following test and found that the above symptoms may NOT be an issue ( they’re just consequences of intense DML workload ). Another pice of information is that we put online log and data files under the same directory, which you could assume that there would be significant I/O contention between LGWR and DBWR under such circumstances.

create table test(a varchar2(32));

declare
done boolean := true;
begin
	while done loop
	 update test set a='dwofdkssfdsdfsfs';
	 commit;
	 --dbms_lock.sleep(0.2);
	end loop;		
end;
/

In oratop, AVG_MS for ‘log file parallel write’ is about 4ms, which is acceptable. However, you DO need to pay attention to vmo and network parameters according to 1318709.1.

EVENT (RT)                                                        TOTAL WAITS   TIME(s)  AVG_MS  PCT                    WAIT_CLASS
DB CPU                                                                              137            3                                       
db file parallel write                                                   6900      2793     4.0   57                    System I/O         
log file parallel write                                                 21574      1097     0.5   22                    System I/O    

Reference:

AIX: Long “log file sync” Wait Time in 11.2.: Things to Check (Doc ID 1318709.1)

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s