Buffer Busy Waits and Disk file operations I/O
Database is getting high waits on buffer busy waits. Here is an example period where 5 sessions are completely blocked on buffer busy waits for 4 minutes:
select
to_char(min(sample_time),'HH24:MI') maxst,
to_char(max(sample_time),'HH24:MI') minst,
count(*),
session_id,
ash.p1,
ash.p2,
ash.SQL_ID,
blocking_session bsid
from DBA_HIST_ACTIVE_SESS_HISTORY ash
where event='buffer busy waits'
and session_state='WAITING'
group by
session_id
,sql_id
,blocking_session
,ash.p1
,ash.p2
Order by 1
/
gives
MAXST MINST COUNT(*) SESSION_ID P1 P2 SQL_ID BSID ----- ----- ---------- ---------- ---------- ---------- ------------- ------- 21:54 21:58 26 1526 1812 278732 3gbsbw6w8jdb3 11 21:54 21:58 25 528 1812 278732 3gbsbw6w8jdb3 11 21:54 21:58 25 1514 1812 278732 3gbsbw6w8jdb3 11 21:54 21:58 26 777 1812 278732 3gbsbw6w8jdb3 11 21:54 21:58 25 33 1812 278732 3gbsbw6w8jdb3 11
All are waiting on the same file and block held by one session and all are executing the same statement which is a select for update
The blocker is executing the same SQL statement and spends those 4 minutes waiting for “Disk file operations I/O”:
select
min(to_char(sample_time,'HH24:MI')) minst,
max(to_char(sample_time,'HH24:MI')) maxst,
session_id,
substr(event,0,30) event,
count(*),
ash.SQL_ID,
blocking_session bsid
from DBA_HIST_ACTIVE_SESS_HISTORY ash
where
session_id in ( 11)
group by
event,sql_id,session_id, blocking_session
order by 1
/
gives
MINST MAXST EVENT COUNT(*) SQL_ID BSID ----- ----- ------------------------------ ---------- ------------- ------- 21:54 21:58 Disk file operations I/O 26 3gbsbw6w8jdb3
What are “Disk file operations I/O”?
From the docs , http://docs.oracle.com/cd/E18283_01/server.112/e17110/waitevents003.htm#insertedID40
Disk file operations I/O
This event is used to wait for disk file operations (for example, open, close, seek, and resize). It is also used for miscellaneous I/O operations such as block dumps and password file accesses.
| FileOperation | Type of file operation |
| fileno | File identification number |
| filetype | Type of file (for example, log file, data file, and so on) |
select p1,p3, count(*) from
dba_hist_active_sess_history
where event ='Disk file operations I/O'
group by p1,p3
/
P1 P3 COUNT(*)
---------- ---------- ----------
2 1 193
2 3 14
4 4 1
2 2 4459
3 4 160
1 18 103
select distinct filetype_id, filetype_name from DBA_HIST_IOSTAT_FILETYPE order by 1; FILETYPE_ID FILETYPE_NAME ----------- ------------------------------ 0 Other 1 Control File 2 Data File 3 Log File 4 Archive Log 6 Temp File 9 Data File Backup 10 Data File Incremental Backup 11 Archive Log Backup 12 Data File Copy 17 Flashback Log 18 Data Pump Dump File
What about FileOperation=2? After a call to Oracle support, it looks like on this version, 11.2.0.3 the values are:
1 file creation
2 file open
3 file resize
4 file deletion
5 file close
6 wait for all aio requests to finish
7 write verification
8 wait for miscellaneous io (ftp, block dump, passwd file)
9 read from snapshot files
putting this together gives a script like:
ol file_type for a20
col file_operation for a20
select
decode(p3,0 ,'Other',
1 ,'Control File',
2 ,'Data File',
3 ,'Log File',
4 ,'Archive Log',
6 ,'Temp File',
9 ,'Data File Backup',
10,'Data File Incremental Backup',
11,'Archive Log Backup',
12,'Data File Copy',
17,'Flashback Log',
18,'Data Pump Dump File',
'unknown '||p1) file_type,
decode(p1,1 ,'file creation',
2 ,'file open',
3 ,'file resize',
4 ,'file deletion',
5 ,'file close',
6 ,'wait for all aio requests to finish',
7 ,'write verification',
8 ,'wait for miscellaneous io (ftp, block dump, passwd file)',
9 ,'read from snapshot files',
'unknown '||p3) file_operation,
decode(p3,2,-1,p2) file#,
count(*)
from dba_hist_active_sess_history
where event ='Disk file operations I/O'
group by p1,p3,
decode(p3,2,-1,p2)
/
with output like
FILE_TYPE FILE_OPERATION FILE# COUNT(*) -------------------- -------------------- ---------- ---------- Control File file open 0 193 Data File file open -1 4460 Archive Log file deletion 0 1 Log File file open 0 14 Data Pump Dump File file creation 0 103 Archive Log file resize 8 160
The “-1” for datafiles is to group all the datafiles in one line, otherwise in the above case there were over 200 lines of output
For the datafiles what are the I/O latencies looking like compared to the Disk file operations I/O ?
BHOU EVENT_NAME AVG_MS CT ---- ------------------------------ --------- ------------ 1054 Disk file operations I/O 2.00 13,547 1130 Disk file operations I/O 1.52 10,658 1200 Disk file operations I/O 1.57 9,846 1230 Disk file operations I/O 2.45 8,704 1300 Disk file operations I/O 3.84 9,526 1330 Disk file operations I/O 2.39 11,989 1400 Disk file operations I/O 1.68 14,698 1430 Disk file operations I/O 2.89 14,863 1500 Disk file operations I/O 860.85 10,577 1530 Disk file operations I/O 12.97 11,783 1600 Disk file operations I/O 623.88 10,902 1630 Disk file operations I/O 357.75 12,428 1700 Disk file operations I/O 294.84 10,543 1730 Disk file operations I/O 12.97 10,623 1800 Disk file operations I/O 461.91 14,443 1830 Disk file operations I/O 12.83 18,504 1900 Disk file operations I/O 443.37 9,563 1930 Disk file operations I/O 237.39 11,737 2000 Disk file operations I/O 542.44 13,027 2033 Disk file operations I/O 6.11 8,389 2100 Disk file operations I/O 16.85 10,561 2130 Disk file operations I/O 306.17 9,873 2200 Disk file operations I/O 20.83 11,335 2230 Disk file operations I/O 12.92 10,158 2300 Disk file operations I/O 13.42 11,025 2330 Disk file operations I/O 15.01 10,883 0000 Disk file operations I/O 5.33 8,533 1054 db file scattered read 1.50 92,394 1130 db file scattered read 1.33 73,243 1200 db file scattered read 1.82 122,988 1230 db file scattered read 2.53 255,474 1300 db file scattered read 4.26 288,144 1330 db file scattered read 2.47 308,045 1400 db file scattered read 2.60 91,684 1430 db file scattered read 3.56 176,324 1500 db file scattered read 4.95 621,658 1530 db file scattered read 5.11 227,565 1600 db file scattered read 5.86 472,804 1630 db file scattered read 9.44 224,984 1700 db file scattered read 9.40 165,238 1730 db file scattered read 7.78 349,003 1800 db file scattered read 6.93 252,761 1830 db file scattered read 7.79 151,760 1900 db file scattered read 5.48 165,369 1930 db file scattered read 3.09 200,868 2000 db file scattered read 3.45 136,647 2033 db file scattered read 5.17 136,330 2100 db file scattered read 11.16 103,799 2130 db file scattered read 10.44 118,025 2200 db file scattered read 20.02 127,638 2230 db file scattered read 13.66 157,210 2300 db file scattered read 10.95 98,493 2330 db file scattered read 8.39 149,606 0000 db file scattered read 4.16 230,075 1054 db file sequential read 3.04 1,152,102 1130 db file sequential read 7.75 165,262 1200 db file sequential read 6.74 23,876 1230 db file sequential read 5.30 10,026 1300 db file sequential read 3.34 496,681 1330 db file sequential read 1.58 1,253,208 1400 db file sequential read 8.86 239,247 1430 db file sequential read 12.91 191,376 1500 db file sequential read 19.97 73,061 1530 db file sequential read 17.80 43,662 1600 db file sequential read 12.41 144,741 1630 db file sequential read 8.99 411,254 1700 db file sequential read 8.03 540,138 1730 db file sequential read 9.26 422,317 1800 db file sequential read 19.16 155,787 1830 db file sequential read 6.01 641,517 1900 db file sequential read 4.79 573,674 1930 db file sequential read 2.72 824,991 2000 db file sequential read 1.59 504,650 2033 db file sequential read 1.88 324,741 2100 db file sequential read 24.32 74,026 2130 db file sequential read 16.05 67,545 2200 db file sequential read 15.52 219,928 2230 db file sequential read 9.87 259,956 2300 db file sequential read 15.18 122,362 2330 db file sequential read 9.97 94,124 0000 db file sequential read 14.19 50,264
Tough to see what is going on
Let’s lay it out in a bubble chart. Latency in ms is on the Y-Axis, time on the X-Axis (AWR snapshots every half hour) and size of the ball is the amount of requests:
The Disk file operations I/O doesn’t seem to correlate with disk activity nor latency. When disk activity is high, on the left, with much data coming off spindle (ie 8ms average) Disk file operations I/O is fast, ie 2ms. But at 20:00, there is medium I/O activity but much of it is coming from cache, ie 2ms average and the Disk file operations are slow.
The database is not using ASM. The number of datafiles is 900. Open file descriptors is set at 8192.
Might be time to run some DTrace on the file operations to get a better idea of what is going on.
.
UPDATE:
Full disclosure: this database was running over NFS on Delphix OS which supports DTrace. I ran DTrace on all the NFS operations and none took over 2 seconds, which is far from the 4 minutes reported by the database.
Ended writing a script to run pstack on sessions that were waiting for Disk file operation I/O for more than 10 seconds. When the pstack was taken the first time, there is no guarentee the process was still on the same wait, but if a second pstack was taken for the same process, then it guarenteed that the first pstack was during the wait. All such waiters that had 2 pstacks were waiting in the first pstack for
_close_sys()
So, although Oracle looks to be reporting slow file open operations, the pstacks are showing problems on close file.
Googling for on HP ( the database was running on HP), I found a couple of links, but nothing definitive
http://www.unix.com/hp-ux/30396-socket-close-hangs-cpu-go-100-a.html http://h30499.www3.hp.com/t5/Networking/CPU-usage-is-100-when-close-sys-call-is-made/td-p/4609196
Oracle reports a few bugs with the wait event “Disk file operation I/O” but none see applicable to this install
Bug 10361651 – File open may hang/spin forever if dNFS is unresponsive [ID 10361651.8]
This bug is suppose to be fixed on 11.2.0.3 and applies to dNFS, though the issues sounds like it would fit – if an I/O operation takes “long” then Oracle’s wait times get corrupted and the process waits much much too long on the event.
Oracle L
Trackbacks
Comments
This is only my speculation and may be a dead end, but… :)
Take a look at some constants defined in /usr/include/fcnttl.h. Providing this is a correct assumption, FileOperation=2 would indicate _FWRITE operation and filetype=2 (data file). Possibly DBWR blocks other sessions.
…
#define _FREAD 0x00000001
#define _FWRITE 0x00000002
#define _FNONBLOCK 0x00000004
#define _FAPPEND 0x00000008
#define _FSYNC 0x00000010
#define _FEXEC 0x00000020
#define _FSNAPSHOT 0x00000040
#define _FCIO 0x00000080
#define _FCREAT 0x00000100
#define _FTRUNC 0x00000200
#define _FEXCL 0x00000400
#define _FNOCTTY 0x00000800
#define _FRSHARE 0x00001000
#define _FDEFER 0x00002000
#define _FDELAY 0x00004000
#define _FNDELAY 0x00008000
#define _FNSHARE 0x00010000
#define _FASYNC 0x00020000
#define _FMOUNT 0x00040000
#define _FSYNCALL 0x00080000
#define _FNOCACHE 0x00100000
#define _FREADSYNC 0x00200000
#define _FDATASYNC 0x00400000
#define _FDEFERIND 0x00800000
#define _FDATAFLUSH 0x01000000
#define _FCLREAD 0x02000000
#define _FLARGEFILE 0x04000000
#define _FDIRECT 0x08000000
#define _FDOCLONE 0x10000000
#define _FALT 0x20000000
#define _FKERNEL 0x40000000
#define _FMSYNC 0x80000000
…
Instead of DBA_HIST_IOSTAT_FILETYPE (thanks to Andy Klock), why not DBA_HIST_IOSTAT_FILETYPE_NAME?
@Yong Huang: thanks , looks encouraging:
FUNCTION_ID FUNCTION_NAME
———– ——————————
0 RMAN
1 DBWR
2 LGWR
3 ARCH
4 XDB
5 Streams AQ
6 Data Pump
7 Recovery
8 Buffer Cache Reads
9 Direct Reads
10 Direct Writes
11 Smart Scan
12 Archive Manager
13 Others
which would make it an issue of LGWR on a DATAFILE.
Will look into LGWR issues and follow up.
Thanks
@Kyle Hailey
Same issue here.
Any news on your side ?
Regards,
Vincent.
@Vincent: what version of Oracle are you on? What database host O/S are you using? Are you using dNFS?
Would be interested to hear more about what you are seeing.
– Kyle
Not sure if you found the root cause for your situation. We had similar problem and found out that Linux 6.3 Transparent Huge page Compaction “feature” caused intermittent freezes in the database manifesting as “Disk file operations I/O” wait event.
@guest
Yes, we never tracked down the root cause, so many thanks for posting your experiences and a possible cause. Good info to have.
Considering the scenario: an Oracle database server with 10 CPUs and a workload of 10 Oracle sessions waiting for IO. In the Enterprise Manager performance page we will see the server at “limit” with 10 average active sessions. But does not asyncronous IO change this? These processes could be scheduled out of running queue by operating system. Could not they? Or always will a process/session wait until an IO request to end?
Your blog is great. Please keep doing.
@Johnny: yes, async I/O can mess up the analysis, not so much because the analysis method is wrong but because of what would be considered bugs in the instrumentation.
There is a great presentation by Frits Hoogland who shows that some reads are not instrumented in the wait interface.
Other anomalies I’ve seen are some async I/O showing up in ASH as CPU state instead of I/O state, but this is a bug.
I think Tanel Poder has a similar example of a read of an external file showing up as CPU state in ASH.
I have meant to analyse the situations where async I/O shows up as CPU state in ASH instead of I/O but haven’t had a chance yet.
There are some interesting new strategies that may require changing the way we think about AAS for async I/O. Now in some situations direct path reads in async mode can issue multiple concurrent direct path reads. Frits Hoogland talks about that as well.
Now should an session that is waiting for one outstanding async I/O be represented the same as a session waiting for 8 concurrent async direct path read I/Os? My reaction is probably yes, and that such differences should be represented in other statistics that can be correlated with AAS
Does anyone know of this new oracle “feature”? An extra open call to make sure the file is open.
http://ranjitnagi.blogspot.com/2012/07/disk-file-operations-io-wait-event-on.html
Thanks for the link to Ragit’s blog.