[20210331]Disk file operations IO与exadata.txt

来源：这里教程网时间：2026-03-03 16:33:48 作者：

[20210331]Disk file operations IO与exadata.txt --//实际上这个问题困扰我很久，一直不知道为什么，我们生产系统主要运行在exadata上，遇到这个等待事件，当然不是主要的等待事 --//件。我一直不清楚为什么出现这样的情况，自己无法解析，花一些时间探究这个等待事件。 --//我前面已经测试了文件型数据库以及非exadata的rac数据库，实际上两者的情况类似。 --//以前的链接：http://blog.itpub.net/267265/viewspace-2149957/ =>[20180109]disk file operations.txt --//实际上之所以存在前面的探究，主要问题是我在exadata上遇到的问题，我自己无法理解： 1.环境： SYS@aaa.bb.cc.ddd:1521/zzzz> @ ver1 PORT_STRING VERSION BANNER ------------------------------ -------------- -------------------------------------------------------------------------------- x86_64/Linux 2.4.xx 11.2.0.4.0 Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production 2.问题提出: SYS@aaa.bb.cc.ddd:1521/zzzz> set verify off SYS@aaa.bb.cc.ddd:1521/zzzz> @ ashtop sql_id,p1,p2,p3 "MACHINE<>'IMC' and event='Disk file operations I/O' " trunc(sysdate)-1 trunc(sysdate)+1 Total Seconds AAS %This SQL_ID P1 P2 P3 FIRST_SEEN LAST_SEEN --------- ------- ------- ------------- ---------- ---------- ---------- ------------------- ------------------- 29 .0 55% | 459f3z9u4fb3u 2 29 2 2021-03-28 09:12:18 2021-03-29 09:42:30 14 .0 26% | 2 0 9 2021-03-29 03:09:38 2021-03-29 03:09:57 4 .0 8% | 0j233gt0r70df 2 28 2 2021-03-28 21:50:06 2021-03-29 09:39:17 2 .0 4% | 4 0 9 2021-03-29 03:09:46 2021-03-29 03:09:49 1 .0 2% | 103kaacv094jg 5 0 13 2021-03-29 06:01:02 2021-03-29 06:01:02 1 .0 2% | 2xaxq1vhryghu 5 0 13 2021-03-29 02:53:00 2021-03-29 02:53:00 1 .0 2% | 633r6yjw2810x 5 0 13 2021-03-28 20:08:55 2021-03-28 20:08:55 1 .0 2% | ctf9dvtv2qua0 5 0 13 2021-03-28 23:02:57 2021-03-28 23:02:57 8 rows selected. --//主要集中在sql_id=459f3z9u4fb3u. --//如果我执行如下： SYS@aaa.bb.cc.ddd:1521/zzzz> column SAMPLE_TIME format a30 SYS@aaa.bb.cc.ddd:1521/zzzz> @ ashtop sql_id,p1,p1text,p2,p3,sample_time,event,session_id "sql_id='459f3z9u4fb3u'" trunc(sysdate)-1 trunc(sysdate)+1 Total Seconds AAS %This SQL_ID P1 P1TEXT P2 P3 SAMPLE_TIME EVENT SESSION_ID FIRST_SEEN LAST_SEEN ------- --- ------- ------------- --- ------------- --- --- ----------------------- ------------------------ ---------- ------------------- ------------------- 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 1 2 2021-03-30 03:44:54.579 1979 2021-03-30 03:44:54 2021-03-30 03:44:54 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 1 2 2021-03-30 10:45:41.228 1349 2021-03-30 10:45:41 2021-03-30 10:45:41 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 1 2 2021-03-30 11:03:55.403 6648 2021-03-30 11:03:55 2021-03-30 11:03:55 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 1 2 2021-03-30 17:20:56.547 3011 2021-03-30 17:20:56 2021-03-30 17:20:56 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 1 2 2021-03-30 17:24:03.976 3685 2021-03-30 17:24:03 2021-03-30 17:24:03 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 1 2 2021-03-30 18:54:05.090 566 2021-03-30 18:54:05 2021-03-30 18:54:05 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 1 2 2021-03-30 19:35:46.293 4126 2021-03-30 19:35:46 2021-03-30 19:35:46 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 1 2 2021-03-30 19:53:17.449 5238 2021-03-30 19:53:17 2021-03-30 19:53:17 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 1 2 2021-03-30 21:04:58.352 4744 2021-03-30 21:04:58 2021-03-30 21:04:58 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 1 2 2021-03-30 23:33:28.137 2178 2021-03-30 23:33:28 2021-03-30 23:33:28 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 1 2 2021-03-31 00:29:51.614 6079 2021-03-31 00:29:51 2021-03-31 00:29:51 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 1 2 2021-03-31 03:18:46.191 784 2021-03-31 03:18:46 2021-03-31 03:18:46 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 1 2 2021-03-31 04:28:59.643 1245 2021-03-31 04:28:59 2021-03-31 04:28:59 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 1 2 2021-03-31 04:50:47.602 4583 2021-03-31 04:50:47 2021-03-31 04:50:47 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 1 2 2021-03-31 05:16:12.236 11167 2021-03-31 05:16:12 2021-03-31 05:16:12 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 1 2 2021-03-31 08:34:32.234 7359 2021-03-31 08:34:32 2021-03-31 08:34:32 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 29 2 2021-03-30 14:20:04.287 Disk file operations I/O 4285 2021-03-30 14:20:04 2021-03-30 14:20:04 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 29 2 2021-03-30 14:45:01.513 Disk file operations I/O 4285 2021-03-30 14:45:01 2021-03-30 14:45:01 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 29 2 2021-03-30 16:41:53.500 Disk file operations I/O 5759 2021-03-30 16:41:53 2021-03-30 16:41:53 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 29 2 2021-03-30 17:09:48.712 Disk file operations I/O 11781 2021-03-30 17:09:48 2021-03-30 17:09:48 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 29 2 2021-03-30 17:13:59.545 Disk file operations I/O 743 2021-03-30 17:13:59 2021-03-30 17:13:59 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 29 2 2021-03-30 17:34:39.653 Disk file operations I/O 4066 2021-03-30 17:34:39 2021-03-30 17:34:39 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 29 2 2021-03-30 17:45:34.420 Disk file operations I/O 6133 2021-03-30 17:45:34 2021-03-30 17:45:34 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 29 2 2021-03-30 17:46:03.620 Disk file operations I/O 5203 2021-03-30 17:46:03 2021-03-30 17:46:03 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 29 2 2021-03-30 17:46:24.790 Disk file operations I/O 2023 2021-03-30 17:46:24 2021-03-30 17:46:24 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 29 2 2021-03-30 17:51:52.113 Disk file operations I/O 6603 2021-03-30 17:51:52 2021-03-30 17:51:52 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 29 2 2021-03-30 18:05:07.595 Disk file operations I/O 9543 2021-03-30 18:05:07 2021-03-30 18:05:07 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 29 2 2021-03-30 18:10:18.606 Disk file operations I/O 3564 2021-03-30 18:10:18 2021-03-30 18:10:18 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 29 2 2021-03-30 18:33:16.538 Disk file operations I/O 3171 2021-03-30 18:33:16 2021-03-30 18:33:16 1 .0 1% | 459f3z9u4fb3u 2 FileOperation 29 2 2021-03-30 18:35:04.496 Disk file operations I/O 3825 2021-03-30 18:35:04 2021-03-30 18:35:04 30 rows selected. --//而且实际上在文件1上也有出现，但是在event列上都没有Disk file operations I/O。是时间太短吗？看后面的跟踪ela=2[都是234]. SYS@aaa.bb.cc.ddd:1521/zzzz> set verify off SYS@aaa.bb.cc.ddd:1521/zzzz> @ sqlid 459f3z9u4fb3u SQL_ID SQLTEXT ------------- ------------------------------------------------------- 459f3z9u4fb3u select value$ from props$ where name = 'GLOBAL_DB_NAME' SYS@aaa.bb.cc.ddd:1521/zzzz> select min(rowid),max(rowid) from props$; MIN(ROWID) MAX(ROWID) ------------------ ------------------ AAAABiAABAAAAMhAAA AAAABiAABAAAAMhAAk SYS@aaa.bb.cc.ddd:1521/zzzz> @ rowid AAAABiAABAAAAMhAAA OBJECT FILE BLOCK ROW ROWID_DBA DBA TEXT ---------- ---------- ---------- ---------- -------------------- -------------------- ---------------------------------------- 98 1 801 0 0x400321 1,801 alter system dump datafile 1 block 801 ; SYS@aaa.bb.cc.ddd:1521/zzzz> @ rowid AAAABiAABAAAAMhAAk OBJECT FILE BLOCK ROW ROWID_DBA DBA TEXT ---------- ---------- ---------- ---------- -------------------- -------------------- ---------------------------------------- 98 1 801 36 0x400321 1,801 alter system dump datafile 1 block 801 ; --//你可以发现访问sys.props$表实际上很小，仅仅占1个数据块。dba=1,801. --//很奇怪的是出现Disk file operations I/O时的P1=2,p2=29,P3=2.按照前面的解析： FileOperation Type of file operation fileno File identification number filetype Type of file (for example, log file, data file, and so on) P1=2 Data File P2=29 file number P3=2 file open --//怎么会出现29呢？这个是我的一个疑惑。要出现也应该是1. --//我检查发现: SYS@aaa.bb.cc.ddd:1521/zzzz> select * from v$dbfile where file# in (1,29); FILE# NAME ---------- ------------------------------------------------------------ 1 +DATAC1/zzzz/datafile/system.308.862160493 29 +DATAC1/zzzz/datafile/system01.bdf --//可以发现很明显实施安装oracle数据库建立数据库时，不小心建立了2个数据文件在system表空间。 --//我估计实施安装者copy and paste时引入的。也可以从sysaux表空间推断： SYS@aaa.bb.cc.ddd:1521/zzzz> select * from v$dbfile where name like '%sysaux%'; FILE# NAME ---------- -------------------------------------------------- 2 +DATAC1/zzzz/datafile/sysaux.295.862160493 28 +DATAC1/zzzz/datafile/sysaux01.bdf --//顺便说一下，我曾经在这里差点犯下严重错误,我当时使用asmcmd就发现目录下出现2个system文件，我差点删除system01.bdf。 --//好在我删除前看了一下。 --//我也百度查询select value$ from props$ where name = 'GLOBAL_DB_NAME',发现杨大师的http://blog.itpub.net/4227/viewspace-708276链接。 --//上面提到是连接用户获取权限信息,我测试确实是这样，一般在登录马上就会遇到这样的语句，而且是以sys用户身份执行。 3.先跟踪看看： $ cat a1.txt select sysdate from dual; alter system set events 'sql_trace off'; alter system set events 'sql_trace [sql:sql_id=459f3z9u4fb3u] bind=true, wait=true'; host sleep 10 select sysdate from dual; alter system set events 'sql_trace off'; SYS@aaa.bb.cc.ddd:1521/zzzz> @ a1.txt SYSDATE ------------------- 2021-03-31 08:49:16 System altered. System altered. SYSDATE ------------------- 2021-03-31 08:49:26 System altered. $ ls -ltr *.trc | grep "2021-03-31 08:49:" | awk '{print $NF}' | xargs -IQ grep "Disk file operations I/O" Q | head --//注我修改ls的别名定义，日期显示完整的年月日，符合国人的习惯。使用alias ls='ls --color=auto --time-style=+"%Y-%m-%d %H:%M:%S"' WAIT #140636248136408: nam='Disk file operations I/O' ela= 345 FileOperation=2 fileno=29 filetype=2 obj#=-1 tim=1617151756965089 WAIT #140636248136408: nam='Disk file operations I/O' ela= 4 FileOperation=2 fileno=1 filetype=2 obj#=-1 tim=1617151756965121 WAIT #140679020010200: nam='Disk file operations I/O' ela= 283 FileOperation=2 fileno=29 filetype=2 obj#=-1 tim=1617151757960823 WAIT #140679020010200: nam='Disk file operations I/O' ela= 2 FileOperation=2 fileno=1 filetype=2 obj#=-1 tim=1617151757960850 WAIT #139818365410008: nam='Disk file operations I/O' ela= 161 FileOperation=2 fileno=29 filetype=2 obj#=-1 tim=1617151757743742 WAIT #139818365410008: nam='Disk file operations I/O' ela= 3 FileOperation=2 fileno=1 filetype=2 obj#=-1 tim=1617151757743768 WAIT #140386474318552: nam='Disk file operations I/O' ela= 355 FileOperation=2 fileno=29 filetype=2 obj#=-1 tim=1617151757680111 WAIT #140386474318552: nam='Disk file operations I/O' ela= 4 FileOperation=2 fileno=1 filetype=2 obj#=-1 tim=1617151757680147 WAIT #139786907736792: nam='Disk file operations I/O' ela= 313 FileOperation=2 fileno=29 filetype=2 obj#=-1 tim=1617151757500057 WAIT #139786907736792: nam='Disk file operations I/O' ela= 3 FileOperation=2 fileno=1 filetype=2 obj#=-1 tim=1617151757500089 xargs: grep: terminated by signal 13 --//而且打开fileno=29的ela都是偏大，检测出现最多就正常，但是 --//随便打开一个都可以发现如下： ===================== PARSING IN CURSOR #140105035209432 len=55 dep=1 uid=0 oct=3 lid=0 tim=1617151766107287 hv=1950821498 ad='133af3e800' sqlid='459f3z9u4fb3u' select value$ from props$ where name = 'GLOBAL_DB_NAME' END OF STMT EXEC #140105035209432:c=0,e=27,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=415205717,tim=1617151766107284 WAIT #140105035209432: nam='Disk file operations I/O' ela= 353 FileOperation=2 fileno=29 filetype=2 obj#=-1 tim=1617151766108028 WAIT #140105035209432: nam='Disk file operations I/O' ela= 4 FileOperation=2 fileno=1 filetype=2 obj#=-1 tim=1617151766108072 FETCH #140105035209432:c=1000,e=579,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=415205717,tim=1617151766108220 FETCH #140105035209432:c=0,e=12,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,plh=415205717,tim=1617151766108278 STAT #140105035209432 id=1 cnt=1 pid=0 pos=1 obj=98 op='TABLE ACCESS STORAGE FULL PROPS$ (cr=3 pr=0 pw=0 time=577 us cost=2 size=28 card=1)' --//确实存在2个Disk file operations I/O等待，参数确实有fileno=29。我就是在这里不理解。 $ ls -ltr *.trc | grep "2021-03-31 08:49:" | awk '{print $NF}' | xargs -IQ grep -l "Disk file operations I/O" Q >aa2.txt $ cut -d"_" -f3 aa2.txt | sed 's/.trc$//' | paste -sd, | xargs -IQ ps -fp Q UID PID PPID C STIME TTY TIME CMD oracle 113988 1 1 08:49 ? 00:00:06 oraclezzzz1 (LOCAL=NO) oracle 113994 1 0 08:49 ? 00:00:00 oraclezzzz1 (LOCAL=NO) oracle 113998 1 2 08:49 ? 00:00:12 oraclezzzz1 (LOCAL=NO) oracle 114376 1 0 08:49 ? 00:00:00 oraclezzzz1 (LOCAL=NO) oracle 114449 1 0 08:49 ? 00:00:00 oraclezzzz1 (LOCAL=NO) --//其它进程号已经消失，可以从STIME时间看基本可以确定登录时执行。 $ wc aa2.txt 70 70 1470 aa2.txt SYS@aaa.bb.cc.ddd:1521/zzzz> @ d_buffer 459f3z9u4fb3u 10 1 EXECUTIONS1 BUFFER_GETS1 ELAPSED_TIME1 ROWS_PROCESSED1 每次buffer_gets 每次执行时间平均处理记录数 INST_ID --------------- --------------- --------------- --------------- --------------- --------------- --------------- --------------- 48410064 145238154 28327331461 48412892 3.0001644699334 585.15377011276 1.0000584176051 1 ... sleep 10 , waiting .... EXECUTIONS2 BUFFER_GETS2 ELAPSED_TIME2 ROWS_PROCESSED2 每次buffer_gets 每次执行时间平均处理记录数 INST_ID --------------- --------------- --------------- --------------- --------------- --------------- --------------- --------------- 48410134 145238364 28327375258 48412962 3.0001644696955 585.15382870041 1.0000584175206 1 执行次数总buffer_gets 总执行时间总处理记录数每次buffer_gets 每次执行时间平均处理记录数 --------------- --------------- --------------- --------------- --------------- --------------- --------------- 70 210 43797 70 3 625.67142857143 1 --//可以看出10秒间隔基本执行70次，与前面测试基本一致，这在我们应用程序很正常...^_^。 --//很短一段时间，仅仅还剩下5个连接。注意看STIME也就是刚刚登录连接的程序都会执行这样的语句。 --//仔细看 props$表没有schema部分，用户程序如何递归调用的呢？ --//可以做一个估计因为执行alter system set events 'sql_trace [sql:sql_id=459f3z9u4fb3u] bind=true, wait=true'; --//仅仅对登录的进程后马上执行1次，许多程序已经退出了。从链接介绍的情况http://blog.itpub.net/4227/viewspace-708276 --//也可以断定,这个语句应该是登录后马上执行的语句之一。而这条语句对应的光标已经缓存，并且访问的数据块也在数据缓存。 --//根本不应该出现Disk file operations I/O等待事件，注意看根本没有物理读的情况，这是我最大的困惑。 --//也就是根本不需要打开system数据文件，跟不应该需要打开file#＝29对应的数据文件，为什么？ --//exadata有什么特殊之处吗？再来看看生产系统另外一台非exadata的rac情况： > @ ashtop sql_id,p1,p1text,event "sql_id='459f3z9u4fb3u'" trunc(sysdate)-100 trunc(sysdate)+1 Total Seconds AAS %This SQL_ID P1 P1TEXT EVENT FIRST_SEEN LAST_SEEN --------- ------- ------- ------------- ---------- ------------------------------ ---------------------------------------- ------------------- ------------------- 52 .0 95% | 459f3z9u4fb3u 1413697536 driver id 2021-02-26 14:54:32 2021-03-31 09:09:30 1 .0 2% | 459f3z9u4fb3u 8 FileOperation 2021-03-12 01:31:02 2021-03-12 01:31:02 1 .0 2% | 459f3z9u4fb3u 675562835 driver id 2021-03-31 08:51:34 2021-03-31 08:51:34 1 .0 2% | 459f3z9u4fb3u 1952673792 driver id 2021-02-25 01:57:50 2021-02-25 01:57:50 --//出现的一次是因为我设置10046跟踪出现的情况，而且P1=8.不是2.根本就没有出现Disk file operations I/O。 4.总结： --//这就是我最大的困惑，我不知道为什么.

编辑推荐：

返回列表

[20210331]Disk file operations IO与exadata.txt

编辑推荐：

相关推荐

excel表格怎样在数字前输入0

excel表格里怎么替换数据

excel表格里面如何插入圆形

excel表格里怎么添加表格数据透视表

excel表格中怎么添加线边框

excel表格里怎样设置条件自动排序

excel表格例怎样导入数据库

Excel表格如何设置数据排序

excel表格里怎么选择性粘贴快捷键

excel表格怎么插入分隔符号

excel表格怎么设置多行多列数据内容排序

Excel表格如何设置行和列相互转换

excel表格连接公式怎么使用

excel表格怎样链接到cad中

雷神推出 MIX PRO II 迷你主机：基于 Ultra 200H，玻璃上盖 + ARGB 灯效

制造商 Musnap 推出彩色墨水屏电纸书 Ocean C：支持手写笔、第三方安卓应用

最新软件资讯

热文推荐

天极热推