ITPub博客

首页 > 数据库 > Oracle > [20210331]Disk file operations IO与exadata.txt

[20210331]Disk file operations IO与exadata.txt

原创 Oracle 作者:lfree 时间:2021-03-31 09:18:00 0 删除 编辑

[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.总结:
--//这就是我最大的困惑,我不知道为什么.

来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/267265/viewspace-2765814/,如需转载,请注明出处,否则将追究法律责任。

请登录后发表评论 登录
全部评论
熟悉oracle相关技术,擅长sql优化,rman备份与恢复,熟悉linux shell编程。

注册时间:2008-01-03

  • 博文量
    2907
  • 访问量
    6680936