[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

相關文章