[20210326]Disk file operations IO與檔案型資料庫.txt

lfree發表於2021-03-26

[20210326]Disk file operations IO與檔案型資料庫.txt

--//實際上這個問題困擾我很久,一直不知道為什麼,我們生產系統主要執行在exadata上,遇到這個等待事件,當然不是主要的等待事
--//件。我一直不清楚為什麼出現這樣的情況,自己無法解析,花一些時間探究這個等待事件。
--//首先從檔案型資料庫談起,然後再講講使用儲存的rac,最後exadata,在寫這篇blog時,我自己還是不明白我們生產系統為什麼會出
--//現的現象。

1.環境:
SCOTT@book> @ 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.一些簡單介紹:
--//參考連結上的介紹:
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.

--//此事件用於等待磁碟檔案操作(例如,開啟、關閉、查詢和調整大小)。 它還用於各種I/O操作,如塊轉儲和密碼檔案訪問。

FileOperation   Type of file operation
fileno          File identification number
filetype        Type of file (for example, log file, data file, and so on)

SCOTT@book> set verify off
SCOTT@book> @ ev_name "Disk file operations I/O"
EVENT#   EVENT_ID NAME                     PARAMETER1    PARAMETER2 PARAMETER3 WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS
------ ---------- ------------------------ ------------- ---------- ---------- ------------- ----------- ----------
    11  166678035 Disk file operations I/O FileOperation fileno     filetype      1740759767           8 User I/O

So mainly FileOperation type 2 and filetype 2.
What are the file types? Not sure, but thanks to Andy Klock on Oracle-L  this looks like a possibility:

SCOTT@book> 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
12 rows selected.
--//補充:上面不是很全,我記憶裡13是spfile,沒有列出。

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

3.分析一:
--//正如上面介紹的此事件用於等待磁碟檔案操作(例如,開啟、關閉、查詢和調整大小)。 它還用於各種I/O操作,如塊轉儲和密碼檔案
--//訪問。可以看出主要應該出現在讀取開啟關閉尋道調整大小事時各種oracle相關檔案出現這個等待事件。

--//可以看出對應檔案型資料庫最多應該出現在控制檔案,引數檔案以及其它相關oracle檔案,而出現在資料檔案的可能性相對較小,因為
--//資料塊會進入快取,這樣使用者程式訪問該塊並不需要開啟對應資料檔案控制程式碼。而且對應程式一旦開啟檔案控制程式碼不會關閉,除非退出。
--//下面我透過測試說明我對這個問題的理解:

--//session 1:
SCOTT@book(30,1893)> @ spid
       SID    SERIAL# PROCESS                  SERVER    SPID       PID  P_SERIAL# C50
---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------
        30       1893 2186                     DEDICATED 2187        26        104 alter system kill session '30,1893' immediate;
--//程式號2187,sid=30

--//session 2:
SYS@book(44,2183)> select * from v$session_wait_history where sid=30 and event='Disk file operations I/O';
no rows selected
--//沒有出現Disk file operations I/O等待事件。注意使用v$session_wait_history分析相對簡單一些。

--//session 1:
SCOTT@book(30,1893)> SELECT value c20  FROM v$spparameter WHERE name = 'standby_file_management' AND sid='*';
C20
--------------------
auto

--//session 2:
SYS@book(44,2183)> select * from v$session_wait_history where sid=30 and event='Disk file operations I/O';
SID SEQ# EVENT# EVENT                    P1TEXT        P1 P2TEXT   P2 P3TEXT     P3  WAIT_TIME WAIT_TIME_MICRO TIME_SINCE_LAST_WAIT_MICRO
--- ---- ------ ------------------------ ------------- -- -------- -- --------- --- ---------- --------------- --------------------------
 30    3     11 Disk file operations I/O FileOperation  5 fileno    0 filetype   13          0              11                          8
 30    6     11 Disk file operations I/O FileOperation  2 fileno    0 filetype   13          0             450                         50
--//出現Disk file operations I/O等待事件。注意P1=5按照上面介紹對應file close。P1=2對應file open。
--//而P3=13 很明顯是spfile檔案。

--//使用strace跟蹤,重複執行看看:
$ strace -f -p 2187 -e open,close,pread,fcntl
Process 2187 attached - interrupt to quit
open("/u01/app/oracle/product/11.2.0.4/dbhome_1/dbs", O_RDONLY) = 8
close(8)                                = 0
open("/etc/mtab", O_RDONLY)             = 8
close(8)                                = 0
open("/etc/mtab", O_RDONLY)             = 8
close(8)                                = 0
open("/etc/mtab", O_RDONLY)             = 8
close(8)                                = 0
open("/u01/app/oracle/product/11.2.0.4/dbhome_1/dbs/spfilebook.ora", O_RDONLY) = 8
close(8)                                = 0
open("/u01/app/oracle/product/11.2.0.4/dbhome_1/dbs/spfilebook.ora", O_RDONLY) = 8
close(8)                                = 0
open("/u01/app/oracle/product/11.2.0.4/dbhome_1/dbs/spfilebook.ora", O_RDWR|O_SYNC) = 8
fcntl(8, F_DUPFD, 256)                  = 259
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
close(8)                                = 0
fcntl(259, F_SETFD, FD_CLOEXEC)         = 0
fcntl(259, F_GETFL)                     = 0x9002 (flags O_RDWR|O_SYNC|O_LARGEFILE)
fcntl(259, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=0, len=0}) = 0
pread(259, "C\"\0\0\1\0\0\0\0\0\0\0\0\0\1\4vJ\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 0) = 512
pread(259, "C\"\0\0\2\0\0\0\0\0\0\0\0\0\1\4qi\0\0book.__db_ca"..., 2560, 512) = 2560
fcntl(259, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
close(259)                              = 0
open("/u01/app/oracle/product/11.2.0.4/dbhome_1/oracore/mesg/lrmus.msb", O_RDONLY) = 8
fcntl(8, F_SETFD, FD_CLOEXEC)           = 0
close(8)                                = 0

--//你可以看到開啟3次引數檔案,有點奇怪的讀的檔案控制程式碼是259,如果你注意下劃線fcntl函式將它定向到檔案控制程式碼259,然後close(8).
--//仔細看strace跟蹤還可以發現open,close出現多次。
--//做一次10046跟蹤看看:
SCOTT@book(30,1893)> @ 10046on 12
Session altered.

SCOTT@book(30,1893)> SELECT value c20  FROM v$spparameter WHERE name = 'standby_file_management' AND sid='*';
C20
--------------------
auto

SCOTT@book(30,1893)> @ 10046off
Session altered.

$ grep "Disk file operations I/O" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_2187.trc
WAIT #139793450719904: nam='Disk file operations I/O' ela= 294 FileOperation=2 fileno=0 filetype=13 obj#=547 tim=1616721166803246
WAIT #139793450719904: nam='Disk file operations I/O' ela= 10 FileOperation=5 fileno=0 filetype=13 obj#=547 tim=1616721166803366
--//僅僅出現2次。obj#=547表示什麼。

SYS@book(44,2183)> select * from dba_objects where object_id=547 or data_object_id=547
  2  @ prxx
==============================
OWNER                         : SYS
OBJECT_NAME                   : KOTTB$
SUBOBJECT_NAME                :
OBJECT_ID                     : 547
DATA_OBJECT_ID                : 547
OBJECT_TYPE                   : TABLE
CREATED                       : 2013-08-24 11:37:43
LAST_DDL_TIME                 : 2013-08-24 11:37:43
TIMESTAMP                     : 2013-08-24:11:37:43
STATUS                        : VALID
TEMPORARY                     : N
GENERATED                     : N
SECONDARY                     : N
NAMESPACE                     : 1
EDITION_NAME                  :
PL/SQL procedure successfully completed.

--//這個表KOTTB$很奇特,我估計用來載入引數檔案資訊的。
SYS@book(44,2183)> select * from KOTTB$;
select * from KOTTB$
              *
ERROR at line 1:
ORA-30732: table contains no user-visible columns

SYS@book(44,2183)> @ ddl sys.KOTTB$;
C100
----------------------------------------------------------------------------------------------------
  CREATE TABLE "SYS"."KOTTB$" OF "SYS"."KOTTB"
 OIDINDEX  ( PCTFREE 10 INITRANS 2 MAXTRANS 255
  STORAGE(INITIAL 65536 NEXT 1048576 MINEXTENTS 1 MAXEXTENTS 2147483645
  PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1
  BUFFER_POOL DEFAULT FLASH_CACHE DEFAULT CELL_FLASH_CACHE DEFAULT)
  TABLESPACE "SYSTEM" )
 PCTFREE 10 PCTUSED 40 INITRANS 1 MAXTRANS 255
 NOCOMPRESS LOGGING
  STORAGE(INITIAL 65536 NEXT 1048576 MINEXTENTS 1 MAXEXTENTS 2147483645
  PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1
  BUFFER_POOL DEFAULT FLASH_CACHE DEFAULT CELL_FLASH_CACHE DEFAULT)
  TABLESPACE "SYSTEM" ;

--//可以發現執行類似的語句讀引數檔案,出現Disk file operations IO應該是正常的,一點不奇怪。因為每次都重複open,pread,close。
--//並且引數檔案資訊並不會進入資料快取,每次執行都要重新讀取引數檔案。
--//所以將對於檔案性資料庫,讀取引數檔案每次都出現Disk file operations IO是正常的情況。

3.分析二:
--//控制檔案呢?控制檔案有一點點不同,看看下面我的分析:
--//session 3:
SCOTT@book(58,2019)> @ spid
       SID    SERIAL# PROCESS                  SERVER    SPID       PID  P_SERIAL# C50
---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------
        58       2019 2411                     DEDICATED 2412        28         50 alter system kill session '58,2019' immediate;

$ ls -l /proc/2412/fd
total 0
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 0 -> /dev/null
l-wx------ 1 oracle oinstall 64 2021-03-26 09:29:23 1 -> /dev/null
l-wx------ 1 oracle oinstall 64 2021-03-26 09:29:23 10 -> pipe:[3628263]
l-wx------ 1 oracle oinstall 64 2021-03-26 09:29:23 2 -> /dev/null
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 3 -> /dev/null
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 4 -> /u01/app/oracle/product/11.2.0.4/dbhome_1/rdbms/mesg/oraus.msb
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 5 -> /proc/2412/fd
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 6 -> /dev/zero
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 7 -> pipe:[3628262]
--//並沒有開啟控制檔案的控制程式碼。

SCOTT@book(58,2019)> @ 10046on 12
Session altered.

SCOTT@book(58,2019)> select * from v$database;
--//注:這條語句許多資訊來源於控制檔案。也就是要訪問控制檔案。

SCOTT@book(58,2019)> @ 10046off
Session altered.

$ ls -l /proc/2412/fd
total 0
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 0 -> /dev/null
l-wx------ 1 oracle oinstall 64 2021-03-26 09:29:23 1 -> /dev/null
l-wx------ 1 oracle oinstall 64 2021-03-26 09:29:23 10 -> pipe:[3628263]
l-wx------ 1 oracle oinstall 64 2021-03-26 09:29:23 2 -> /dev/null
lrwx------ 1 oracle oinstall 64 2021-03-26 09:31:40 256 -> /mnt/ramdisk/book/control01.ctl
lrwx------ 1 oracle oinstall 64 2021-03-26 09:31:40 257 -> /mnt/ramdisk/book/control02.ctl
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 3 -> /dev/null
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 4 -> /u01/app/oracle/product/11.2.0.4/dbhome_1/rdbms/mesg/oraus.msb
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 5 -> /proc/2412/fd
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 6 -> /dev/zero
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 7 -> pipe:[3628262]
l-wx------ 1 oracle oinstall 64 2021-03-26 09:31:40 8 -> /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_2412.trc
l-wx------ 1 oracle oinstall 64 2021-03-26 09:31:40 9 -> /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_2412.trm
--//你可以發現執行完後開啟了控制檔案的控制程式碼256,257.

$ grep 'Disk file operations I/O'  /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_2412.trc
WAIT #139739009568744: nam='Disk file operations I/O' ela= 80 FileOperation=2 fileno=0 filetype=1 obj#=-1 tim=1616722218802285
WAIT #139739009568744: nam='Disk file operations I/O' ela= 16 FileOperation=2 fileno=1 filetype=1 obj#=-1 tim=1616722218802333
--//filetype=1  對應的就是control file。你還可以注意一個小小的細節,就是沒有close(FileOperation=5)。
--//這點可以從上面的ls -l /proc/2412/fd顯示可以確定,控制檔案的控制程式碼沒有關閉。
--//這樣如果該會話再次訪問控制檔案,就不再會出現Disk file operations I/O等待事件了。

SCOTT@book(58,2019)> @ 10046on 12
Session altered.

SCOTT@book(58,2019)> select * from v$database;

SCOTT@book(58,2019)> @ 10046off
Session altered.

$ grep 'Disk file operations I/O'  /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_2412.trc
WAIT #139739009568744: nam='Disk file operations I/O' ela= 80 FileOperation=2 fileno=0 filetype=1 obj#=-1 tim=1616722218802285
WAIT #139739009568744: nam='Disk file operations I/O' ela= 16 FileOperation=2 fileno=1 filetype=1 obj#=-1 tim=1616722218802333
--//依舊僅僅看到2條。
--//補充還有一點點細節,第2行出現fileno=1,而前面的ls -l /proc/2412/fd 並沒有顯示開啟system資料檔案,也就是oracle把P2解析
--//為File identification number,我估計在這裡指第2個控制檔案(/mnt/ramdisk/book/control02.ctl)。

4.分析三:
--//訪問資料庫裡面的資料塊呢?情況有有所不同,oracle有資料快取,有可能你訪問的資料塊已經在資料快取了。
--//這樣在訪問時不需要開啟對應資料檔案的檔案控制程式碼就可以透過資料快取讀取到該塊,也就是這樣不會出現
--//Disk file operations I/O。
--//還有一種可能就是該程式下對應資料檔案的控制程式碼已經開啟了,這樣即使資料塊不在快取,也不會出現Disk file operations I/O。
--//session 3:
SCOTT@book(58,2019)> @ spid
       SID    SERIAL# PROCESS                  SERVER    SPID       PID  P_SERIAL# C50
---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------
        58       2019 2411                     DEDICATED 2412        28         50 alter system kill session '58,2019' immediate;

$  ls -l /proc/2412/fd
total 0
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 0 -> /dev/null
l-wx------ 1 oracle oinstall 64 2021-03-26 09:29:23 1 -> /dev/null
l-wx------ 1 oracle oinstall 64 2021-03-26 09:29:23 10 -> pipe:[3628263]
l-wx------ 1 oracle oinstall 64 2021-03-26 09:29:23 2 -> /dev/null
lrwx------ 1 oracle oinstall 64 2021-03-26 09:31:40 256 -> /mnt/ramdisk/book/control01.ctl
lrwx------ 1 oracle oinstall 64 2021-03-26 09:31:40 257 -> /mnt/ramdisk/book/control02.ctl
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 3 -> /dev/null
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 4 -> /u01/app/oracle/product/11.2.0.4/dbhome_1/rdbms/mesg/oraus.msb
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 5 -> /proc/2412/fd
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 6 -> /dev/zero
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 7 -> pipe:[3628262]

--//session 2:
SYS@book(44,2183)> alter system flush buffer_cache;
System altered.

--//session 1:
SCOTT@book(58,2019)> @ 10046on 12
Session altered.

SCOTT@book(58,2019)> select * from dept where rownum=1;
    DEPTNO DNAME          LOC
---------- -------------- -------------
        10 ACCOUNTING     NEW YORK

SCOTT@book(58,2019)> @ 10046off
Session altered.

$ grep 'Disk file operations I/O'  /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_2412.trc
WAIT #139739009568744: nam='Disk file operations I/O' ela= 80 FileOperation=2 fileno=0 filetype=1 obj#=-1 tim=1616722218802285
WAIT #139739009568744: nam='Disk file operations I/O' ela= 16 FileOperation=2 fileno=1 filetype=1 obj#=-1 tim=1616722218802333
WAIT #139739010661336: nam='Disk file operations I/O' ela= 42 FileOperation=2 fileno=1 filetype=2 obj#=37 tim=1616723599517954
WAIT #139739010956368: nam='Disk file operations I/O' ela= 28 FileOperation=2 fileno=4 filetype=2 obj#=87106 tim=1616723599571393

--//注:我沒有刪除前面看到的2行。可以發現出現2次。
--//filetype=2 對應Data File,這樣fileno=1,4對應檔案號。
SYS@book(44,2183)> select * from v$dbfile where file# in (1,4);
     FILE# NAME
---------- ----------------------------------------
         4 /mnt/ramdisk/book/users01.dbf
         1 /mnt/ramdisk/book/system01.dbf

$  ls -l /proc/2412/fd
total 0
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 0 -> /dev/null
l-wx------ 1 oracle oinstall 64 2021-03-26 09:29:23 1 -> /dev/null
l-wx------ 1 oracle oinstall 64 2021-03-26 09:29:23 10 -> pipe:[3628263]
l-wx------ 1 oracle oinstall 64 2021-03-26 09:29:23 2 -> /dev/null
lrwx------ 1 oracle oinstall 64 2021-03-26 09:31:40 256 -> /mnt/ramdisk/book/control01.ctl
lrwx------ 1 oracle oinstall 64 2021-03-26 09:31:40 257 -> /mnt/ramdisk/book/control02.ctl
lrwx------ 1 oracle oinstall 64 2021-03-26 09:57:38 258 -> /mnt/ramdisk/book/system01.dbf
lrwx------ 1 oracle oinstall 64 2021-03-26 09:57:38 259 -> /mnt/ramdisk/book/users01.dbf
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 3 -> /dev/null
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 4 -> /u01/app/oracle/product/11.2.0.4/dbhome_1/rdbms/mesg/oraus.msb
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 5 -> /proc/2412/fd
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 6 -> /dev/zero
lr-x------ 1 oracle oinstall 64 2021-03-26 09:29:23 7 -> pipe:[3628262]
l-wx------ 1 oracle oinstall 64 2021-03-26 09:31:40 8 -> /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_2412.trc
l-wx------ 1 oracle oinstall 64 2021-03-26 09:31:40 9 -> /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_2412.trm

--//可以發現對應程式下多開啟了/mnt/ramdisk/book/system01.dbf,/mnt/ramdisk/book/users01.dbf。
--//如果這個時候其它會話訪問dept表塊,因為該塊已經在資料快取裡面了,也不用開啟對應檔案控制程式碼訪問該塊,這樣不會出現Disk
--//file operations I/O。

--//session 1:
SCOTT@book(30,1893)> @ spid
       SID    SERIAL# PROCESS                  SERVER    SPID       PID  P_SERIAL# C50
---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------
        30       1893 2186                     DEDICATED 2187        26        104 alter system kill session '30,1893' immediate;

$ ll /proc/2187/fd
total 0
lr-x------ 1 oracle oinstall 64 2021-03-26 08:56:58 0 -> /dev/null
l-wx------ 1 oracle oinstall 64 2021-03-26 08:56:58 1 -> /dev/null
l-wx------ 1 oracle oinstall 64 2021-03-26 08:56:58 10 -> pipe:[3628207]
l-wx------ 1 oracle oinstall 64 2021-03-26 08:56:58 2 -> /dev/null
lrwx------ 1 oracle oinstall 64 2021-03-26 08:56:58 256 -> /mnt/ramdisk/book/system01.dbf
lrwx------ 1 oracle oinstall 64 2021-03-26 08:58:14 257 -> /mnt/ramdisk/book/control01.ctl
lrwx------ 1 oracle oinstall 64 2021-03-26 08:58:14 258 -> /mnt/ramdisk/book/control02.ctl
lr-x------ 1 oracle oinstall 64 2021-03-26 08:56:58 3 -> /dev/null
lr-x------ 1 oracle oinstall 64 2021-03-26 08:56:58 4 -> /u01/app/oracle/product/11.2.0.4/dbhome_1/rdbms/mesg/oraus.msb
lr-x------ 1 oracle oinstall 64 2021-03-26 08:56:58 5 -> /proc/2187/fd
lr-x------ 1 oracle oinstall 64 2021-03-26 08:56:58 6 -> /dev/zero
lr-x------ 1 oracle oinstall 64 2021-03-26 08:56:58 7 -> pipe:[3628206]
--//沒有開啟/mnt/ramdisk/book/users01.dbf。

--//session 1:
SCOTT@book(30,1893)> @ 10046on 12
Session altered.

SCOTT@book(30,1893)> select * from dept where rownum=1;
    DEPTNO DNAME          LOC
---------- -------------- -------------
        10 ACCOUNTING     NEW YORK

SCOTT@book(30,1893)> @ 10046off
Session altered.

$ grep 'Disk file operations I/O'  /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_2187.trc
WAIT #139793450719904: nam='Disk file operations I/O' ela= 294 FileOperation=2 fileno=0 filetype=13 obj#=547 tim=1616721166803246
WAIT #139793450719904: nam='Disk file operations I/O' ela= 10 FileOperation=5 fileno=0 filetype=13 obj#=547 tim=1616721166803366
--//注我沒有刪除前面看到的2行,從filetype=13可以看出沒有出現Disk file operations I/O。

$ ll /proc/2187/fd
total 0
lr-x------ 1 oracle oinstall 64 2021-03-26 08:56:58 0 -> /dev/null
l-wx------ 1 oracle oinstall 64 2021-03-26 08:56:58 1 -> /dev/null
l-wx------ 1 oracle oinstall 64 2021-03-26 08:56:58 10 -> pipe:[3628207]
l-wx------ 1 oracle oinstall 64 2021-03-26 08:56:58 2 -> /dev/null
lrwx------ 1 oracle oinstall 64 2021-03-26 08:56:58 256 -> /mnt/ramdisk/book/system01.dbf
lrwx------ 1 oracle oinstall 64 2021-03-26 08:58:14 257 -> /mnt/ramdisk/book/control01.ctl
lrwx------ 1 oracle oinstall 64 2021-03-26 08:58:14 258 -> /mnt/ramdisk/book/control02.ctl
lr-x------ 1 oracle oinstall 64 2021-03-26 08:56:58 3 -> /dev/null
lr-x------ 1 oracle oinstall 64 2021-03-26 08:56:58 4 -> /u01/app/oracle/product/11.2.0.4/dbhome_1/rdbms/mesg/oraus.msb
lr-x------ 1 oracle oinstall 64 2021-03-26 08:56:58 5 -> /proc/2187/fd
lr-x------ 1 oracle oinstall 64 2021-03-26 08:56:58 6 -> /dev/zero
lr-x------ 1 oracle oinstall 64 2021-03-26 08:56:58 7 -> pipe:[3628206]
l-wx------ 1 oracle oinstall 64 2021-03-26 09:47:39 8 -> /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_2187.trc
l-wx------ 1 oracle oinstall 64 2021-03-26 09:47:39 9 -> /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_2187.trm
--//沒有開啟/mnt/ramdisk/book/users01.dbf檔案控制程式碼。
--//如果你重新整理資料快取呢?
--//session 2:
SYS@book(44,2183)> alter system flush buffer_cache;
System altered.
--//注最好選擇其它會話重新整理資料快取,避免意外開啟對應的檔案控制程式碼。

--//session 1:
SCOTT@book(30,1893)> @ 10046on 12
Session altered.

SCOTT@book(30,1893)> select * from dept where rownum=1;
    DEPTNO DNAME          LOC
---------- -------------- -------------
        10 ACCOUNTING     NEW YORK

SCOTT@book(30,1893)> @ 10046off
Session altered.

$ ls -l /proc/2187/fd
total 0
lr-x------ 1 oracle oinstall 64 2021-03-26 08:56:58 0 -> /dev/null
l-wx------ 1 oracle oinstall 64 2021-03-26 08:56:58 1 -> /dev/null
l-wx------ 1 oracle oinstall 64 2021-03-26 08:56:58 10 -> pipe:[3628207]
l-wx------ 1 oracle oinstall 64 2021-03-26 08:56:58 2 -> /dev/null
lrwx------ 1 oracle oinstall 64 2021-03-26 08:56:58 256 -> /mnt/ramdisk/book/system01.dbf
lrwx------ 1 oracle oinstall 64 2021-03-26 08:58:14 257 -> /mnt/ramdisk/book/control01.ctl
lrwx------ 1 oracle oinstall 64 2021-03-26 08:58:14 258 -> /mnt/ramdisk/book/control02.ctl
lrwx------ 1 oracle oinstall 64 2021-03-26 10:08:45 259 -> /mnt/ramdisk/book/users01.dbf
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
lr-x------ 1 oracle oinstall 64 2021-03-26 08:56:58 3 -> /dev/null
lr-x------ 1 oracle oinstall 64 2021-03-26 08:56:58 4 -> /u01/app/oracle/product/11.2.0.4/dbhome_1/rdbms/mesg/oraus.msb
lr-x------ 1 oracle oinstall 64 2021-03-26 08:56:58 5 -> /proc/2187/fd
lr-x------ 1 oracle oinstall 64 2021-03-26 08:56:58 6 -> /dev/zero
lr-x------ 1 oracle oinstall 64 2021-03-26 08:56:58 7 -> pipe:[3628206]
l-wx------ 1 oracle oinstall 64 2021-03-26 09:47:39 8 -> /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_2187.trc
l-wx------ 1 oracle oinstall 64 2021-03-26 09:47:39 9 -> /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_2187.trm
--//開啟/mnt/ramdisk/book/users01.dbf檔案控制程式碼。

$ grep 'Disk file operations I/O'  /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_2187.trc
WAIT #139793450719904: nam='Disk file operations I/O' ela= 294 FileOperation=2 fileno=0 filetype=13 obj#=547 tim=1616721166803246
WAIT #139793450719904: nam='Disk file operations I/O' ela= 10 FileOperation=5 fileno=0 filetype=13 obj#=547 tim=1616721166803366
WAIT #139793449072216: nam='Disk file operations I/O' ela= 46 FileOperation=2 fileno=4 filetype=2 obj#=87106 tim=1616724500940194
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
--//出現了Disk file operations I/O.FileOperation=2 fileno=4 filetype=2.

--//如果再次重新整理,session 1再次重複測試,因為對應檔案控制程式碼已經開啟,應該也不會出現Disk file operations I/O。
--//session 2:
SYS@book(44,2183)> alter system flush buffer_cache;
System altered.

--//session 1:
SCOTT@book(30,1893)> @ 10046on 12
Session altered.

SCOTT@book(30,1893)> select * from dept where rownum=1;
    DEPTNO DNAME          LOC
---------- -------------- -------------
        10 ACCOUNTING     NEW YORK

SCOTT@book(30,1893)> @ 10046off
Session altered.

$ grep 'Disk file operations I/O'  /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_2187.trc
WAIT #139793450719904: nam='Disk file operations I/O' ela= 294 FileOperation=2 fileno=0 filetype=13 obj#=547 tim=1616721166803246
WAIT #139793450719904: nam='Disk file operations I/O' ela= 10 FileOperation=5 fileno=0 filetype=13 obj#=547 tim=1616721166803366
WAIT #139793449072216: nam='Disk file operations I/O' ela= 46 FileOperation=2 fileno=4 filetype=2 obj#=87106 tim=1616724500940194
--//依舊是3行。沒有再次出現Disk file operations I/O。

--//可以看出對於資料塊是否出現Disk file operations I/O,主要有幾種情況需要考慮:
--//資料塊是否快取,相應程式是否開啟對應的檔案控制程式碼。另外注意一點一旦開啟不會關閉對應的檔案控制程式碼,除非退出。

5.分析四:
--//如果執行計劃直接路徑讀呢?測試參考連結http://blog.itpub.net/267265/viewspace-2143334/。
--//直接路徑讀繞過了資料快取,直接讀取資料塊進入PGA,透過上面的特例測試。
--//session 3:
SCOTT@book(58,2019)> select rowid,dept.* from dept ;
ROWID                  DEPTNO DNAME          LOC
------------------ ---------- -------------- -------------
AAAVRCAAEAAAACHAAA         10 ACCOUNTING     NEW YORK
AAAVRCAAEAAAACHAAB         20 RESEARCH       DALLAS
AAAVRCAAEAAAACHAAC         30 SALES          CHICAGO
AAAVRCAAEAAAACHAAD         40 OPERATIONS     BOSTON

--//session 2:
SYS@book(44,2183)> alter system flush buffer_cache;
System altered.

--//session 3:
SCOTT@book(58,2019)> select rowid,dept.* from dept where rowid='AAAVRCAAEAAAACHAAA';
ROWID                  DEPTNO DNAME          LOC
------------------ ---------- -------------- -------------
AAAVRCAAEAAAACHAAA         10 ACCOUNTING     NEW YORK

--//session 2:
SYS@book(44,2183)> @ rowid AAAVRCAAEAAAACHAAA
    OBJECT       FILE      BLOCK        ROW ROWID_DBA            DBA                  TEXT
---------- ---------- ---------- ---------- -------------------- -------------------- ----------------------------------------
     87106          4        135          0  0x1000087           4,135                alter system dump datafile 4 block 135 ;

SYS@book(44,2183)> @ bh 4 135
   INST_ID HLADDR              DBARFIL     DBABLK      CLASS CLASS_TYPE         STATE             TCH CR_SCN_BAS CR_SCN_WRP CR_UBA_FIL CR_UBA_BLK CR_UBA_SEQ BA               LE_ADDR          OBJECT_NAME
---------- ---------------- ---------- ---------- ---------- ------------------ ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------------- ---------------- --------------------
         1 0000000084D25320          4        135          1 data block         xcur                1          0          0          0          0          0 00000000654FC000 00               DEPT
--//這樣該塊進入資料快取。不放心可以執行多次。

--//session 3:
SCOTT@book(58,2019)> alter session set statistics_level=all;
Session altered.

select * from dept where rowid between 'AAAVRCAAEAAAACHAAA' and 'AAAVRCAAEAAAACHAAB';
--//注執行多次檢視執行計劃可以發現存在物理讀。我這裡不測試了。

--//session 4:
SCOTT@book(72,1179)> @ spid
       SID    SERIAL# PROCESS                  SERVER    SPID       PID  P_SERIAL# C50
---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------
        72       1179 2796                     DEDICATED 2797        29          6 alter system kill session '72,1179' immediate;

$ ll /proc/2797/fd
total 0
lr-x------ 1 oracle oinstall 64 2021-03-26 10:40:40 0 -> /dev/null
l-wx------ 1 oracle oinstall 64 2021-03-26 10:40:40 1 -> /dev/null
l-wx------ 1 oracle oinstall 64 2021-03-26 10:40:40 10 -> pipe:[3628369]
l-wx------ 1 oracle oinstall 64 2021-03-26 10:40:40 2 -> /dev/null
lrwx------ 1 oracle oinstall 64 2021-03-26 10:40:40 256 -> /mnt/ramdisk/book/system01.dbf
lr-x------ 1 oracle oinstall 64 2021-03-26 10:40:40 3 -> /dev/null
lr-x------ 1 oracle oinstall 64 2021-03-26 10:40:40 4 -> /u01/app/oracle/product/11.2.0.4/dbhome_1/rdbms/mesg/oraus.msb
lr-x------ 1 oracle oinstall 64 2021-03-26 10:40:40 5 -> /proc/2797/fd
lr-x------ 1 oracle oinstall 64 2021-03-26 10:40:40 6 -> /dev/zero
lr-x------ 1 oracle oinstall 64 2021-03-26 10:40:40 7 -> pipe:[3628368]
--//沒有開啟/mnt/ramdisk/book/user01.dbf檔案控制程式碼。

SCOTT@book(72,1179)> @ 10046on 12
Session altered.

select * from dept where rowid between 'AAAVRCAAEAAAACHAAA' and 'AAAVRCAAEAAAACHAAB';
select * from dept where rowid between 'AAAVRCAAEAAAACHAAA' and 'AAAVRCAAEAAAACHAAB';
        
SCOTT@book(72,1179)> @ 10046off
Session altered.

$ ll /proc/2797/fd
total 0
lr-x------ 1 oracle oinstall 64 2021-03-26 10:40:40 0 -> /dev/null
l-wx------ 1 oracle oinstall 64 2021-03-26 10:40:40 1 -> /dev/null
l-wx------ 1 oracle oinstall 64 2021-03-26 10:40:40 10 -> pipe:[3628369]
l-wx------ 1 oracle oinstall 64 2021-03-26 10:40:40 2 -> /dev/null
lrwx------ 1 oracle oinstall 64 2021-03-26 10:40:40 256 -> /mnt/ramdisk/book/system01.dbf
lrwx------ 1 oracle oinstall 64 2021-03-26 10:41:46 257 -> /mnt/ramdisk/book/users01.dbf
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
lr-x------ 1 oracle oinstall 64 2021-03-26 10:40:40 3 -> /dev/null
lr-x------ 1 oracle oinstall 64 2021-03-26 10:40:40 4 -> /u01/app/oracle/product/11.2.0.4/dbhome_1/rdbms/mesg/oraus.msb
lr-x------ 1 oracle oinstall 64 2021-03-26 10:40:40 5 -> /proc/2797/fd
lr-x------ 1 oracle oinstall 64 2021-03-26 10:40:40 6 -> /dev/zero
lr-x------ 1 oracle oinstall 64 2021-03-26 10:40:40 7 -> pipe:[3628368]
l-wx------ 1 oracle oinstall 64 2021-03-26 10:41:46 8 -> /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_2797.trc
l-wx------ 1 oracle oinstall 64 2021-03-26 10:41:46 9 -> /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_2797.trm
--//開啟/mnt/ramdisk/book/user01.dbf檔案控制程式碼。

$ grep 'Disk file operations I/O'  /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_2797.trc
WAIT #139753629750824: nam='Disk file operations I/O' ela= 38 FileOperation=2 fileno=4 filetype=2 obj#=87106 tim=1616726471319299
--//出現了Disk file operations I/O.注意僅僅出現1次。
--//也就是一旦開啟對應文控制程式碼就不會出現Disk file operations I/O。

6.總結:
--//不小心又寫的很長。
--//對於檔案型資料庫,如果語句涉及讀取引數檔案,一定會遇到Disk file operations I/O。
--//而像控制檔案如果會話第一次執行訪問控制檔案的語句,一定會遇到Disk file operations I/O,以後就不會出現。
--//可以看出對於資料塊是否出現Disk file operations I/O,主要有幾種情況需要考慮:
--//資料塊是否快取,相應程式是否開啟對應的檔案控制程式碼。另外注意一點一旦開啟不會關閉對應的檔案控制程式碼,除非退出。
--//直接路徑讀情況有一點點特殊,即使在有資料快取,一定相應程式開啟對應的檔案控制程式碼才不會出現Disk file operations I/O。
--//仔細想想我的測試直接路徑讀還是有1點點瑕疵,因為那個特性利用段頭不在資料快取的情況下才能測出。
--//而且訪問段頭就需要開啟相應資料檔案。

7.補充一些無法解析的情況:
--//session 2:
SYS@book(44,2183)> @ spid
       SID    SERIAL# PROCESS                  SERVER    SPID       PID  P_SERIAL# C50
---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------
        44       2183 2189                     DEDICATED 2190        27        104 alter system kill session '44,2183' immediate;

$ ll /proc/2190/fd | egrep "dbf|ctl"
lrwx------ 1 oracle oinstall 64 2021-03-26 10:06:54 256 -> /mnt/ramdisk/book/system01.dbf
lrwx------ 1 oracle oinstall 64 2021-03-26 10:06:54 257 -> /mnt/ramdisk/book/temp01.dbf
lrwx------ 1 oracle oinstall 64 2021-03-26 10:06:54 258 -> /mnt/ramdisk/book/sysaux01.dbf
lrwx------ 1 oracle oinstall 64 2021-03-26 10:06:54 259 -> /mnt/ramdisk/book/control01.ctl
lrwx------ 1 oracle oinstall 64 2021-03-26 10:06:54 260 -> /mnt/ramdisk/book/control02.ctl
--//沒有開啟/mnt/ramdisk/book/users01.dbf

--//session 1:
--//產生一些髒塊。
SCOTT@book(30,1893)> update empx set ename=lower(ename);
14 rows updated.

SCOTT@book(30,1893)> commit ;
Commit complete.

--//session 2:
SYS@book(44,2183)> @ 10046on 12
Session altered.

SYS@book(44,2183)> alter system flush buffer_cache;
System altered.

SYS@book(44,2183)> @ 10046off
Session altered.

$ grep 'Disk file operations I/O'  /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_2190.trc
WAIT #140012911193480: nam='Disk file operations I/O' ela= 50 FileOperation=8 fileno=0 filetype=8 obj#=18 tim=1616727922986804
WAIT #140012911194728: nam='Disk file operations I/O' ela= 76 FileOperation=8 fileno=0 filetype=8 obj#=18 tim=1616727925479330
--//不理解FileOperation=8 fileno=0 filetype=8
$ strace -f -p 2190 -e open,close,pread,fcntl
Process 2190 attached - interrupt to quit
open("/u01/app/oracle/diag/rdbms/book/book/alert/log.xml", O_WRONLY|O_CREAT|O_APPEND, 0660) = 14
fcntl(14, F_SETFD, FD_CLOEXEC)          = 0
close(14)                               = 0
open("/u01/app/oracle/diag/rdbms/book/book/trace/alert_book.log", O_WRONLY|O_CREAT|O_APPEND, 0660) = 14
fcntl(14, F_SETFD, FD_CLOEXEC)          = 0
close(14)                               = 0
^CProcess 2190 detached
--//視乎是指aler檔案。

SCOTT@book(30,1893)> select * from dba_objects where object_id=18
  2  @ prxx
==============================
OWNER                         : SYS
OBJECT_NAME                   : OBJ$
SUBOBJECT_NAME                :
OBJECT_ID                     : 18
DATA_OBJECT_ID                : 18
OBJECT_TYPE                   : TABLE
CREATED                       : 2013-08-24 11:37:35
LAST_DDL_TIME                 : 2013-08-24 11:59:25
TIMESTAMP                     : 2013-08-24:11:37:35
STATUS                        : VALID
TEMPORARY                     : N
GENERATED                     : N
SECONDARY                     : N
NAMESPACE                     : 1
EDITION_NAME                  :
PL/SQL procedure successfully completed.

$ ll /proc/2190/fd | egrep "dbf|ctl"
lrwx------ 1 oracle oinstall 64 2021-03-26 10:06:54 256 -> /mnt/ramdisk/book/system01.dbf
lrwx------ 1 oracle oinstall 64 2021-03-26 10:06:54 257 -> /mnt/ramdisk/book/temp01.dbf
lrwx------ 1 oracle oinstall 64 2021-03-26 10:06:54 258 -> /mnt/ramdisk/book/sysaux01.dbf
lrwx------ 1 oracle oinstall 64 2021-03-26 10:06:54 259 -> /mnt/ramdisk/book/control01.ctl
lrwx------ 1 oracle oinstall 64 2021-03-26 10:06:54 260 -> /mnt/ramdisk/book/control02.ctl


8.貼一個生產系統的情況:
> @ ver1
PORT_STRING                    VERSION        BANNER
------------------------------ -------------- --------------------------------------------------------------------------------
x86_64/Linux 2.4.xx            11.2.0.3.0     Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production

> @ ashtop sql_id,p1,p2,p3,session_id "MACHINE<>'IMC' and event='Disk file operations I/O'"  trunc(sysdate)-100 trunc(sysdate)+1
  Total
Seconds     AAS %This   SQL_ID         P1  P2  P3 SESSION_ID FIRST_SEEN          LAST_SEEN
------- ------- ------- ------------- --- --- --- ---------- ------------------- -------------------
      8      .0   15% | ctf9dvtv2qua0   2   0  13       1249 2021-03-23 21:59:12 2021-03-26 10:29:13
      7      .0   13% | dnk8dw55sjz3h   2   0  13       1249 2021-03-23 16:48:07 2021-03-26 01:20:03
      6      .0   11% | 633r6yjw2810x   2   0  13       1249 2021-03-23 15:59:06 2021-03-26 10:16:12
      5      .0    9% | 2tp6sujs7jxhp   2   0  13       1249 2021-03-24 11:26:25 2021-03-26 12:31:15
      5      .0    9% |                 4   0   9         19 2021-03-25 01:22:24 2021-03-25 01:22:34
      4      .0    7% | 2xaxq1vhryghu   2   0  13       1249 2021-03-23 13:15:03 2021-03-26 04:43:07
      3      .0    5% | 9wj2g5x2ggpya   2   0  13       1249 2021-03-24 20:07:34 2021-03-25 06:11:44
      3      .0    5% | cr7mmwh94tz9a   2   0  13       1249 2021-03-24 00:00:14 2021-03-26 05:11:07
      3      .0    5% |                 4   0   4         19 2021-03-25 01:22:32 2021-03-25 01:22:37
      2      .0    4% |                 1   1   9        428 2021-03-25 01:11:06 2021-03-25 01:22:16
      2      .0    4% |                 1   1   9        855 2021-03-25 01:13:15 2021-03-25 01:13:18
      1      .0    2% | 4nw903nu8qxkc   2   3   2        444 2021-03-25 08:25:15 2021-03-25 08:25:15
      1      .0    2% | 4pcnjr43r5rt2   2   0  13       1249 2021-03-23 14:47:05 2021-03-23 14:47:05
      1      .0    2% | 7mgr3uwydqq8j   2   0   1         34 2021-03-25 05:51:26 2021-03-25 05:51:26
      1      .0    2% |                 1   0   4        834 2021-03-26 08:22:58 2021-03-26 08:22:58
      1      .0    2% |                 1   0   4       1251 2021-03-25 10:53:03 2021-03-25 10:53:03
      1      .0    2% |                 2   0   3       1252 2021-03-26 09:42:06 2021-03-26 09:42:06
      1      .0    2% |                 2   7   2        430 2021-03-25 22:12:19 2021-03-25 22:12:19
18 rows selected.
--//注意看基本都是session_id=124執行的。p3=13值引數檔案。其它基本很少出現。

> @ sqlid ctf9dvtv2qua0
SQL_ID        SQLTEXT
------------- ------------------------------------------------------------------------------------
ctf9dvtv2qua0 SELECT value FROM v$spparameter WHERE name = 'log_file_name_convert' and ordinal = 1
--//檢視的正是引數檔案。

> @ sid 1249
sid = 1249
SPID   PID  SID    SERIAL# CLIENT_INFO PNAME  TRACEFILE                                                           PROGRAM                TERMINAL     SQL_ID STATUS   C50
------ --- ---- ---------- ----------- ------ ------------------------------------------------------------------- ---------------------- ------------ ------ -------- --------------------------------------------------
3650    23 1249          1             RSM0   /u01/app/oracle/diag/rdbms/hrp430/hrp430/trace/hrp430_rsm0_3650.trc oracle@xhserver (RSM0) UNKNOWN             ACTIVE   alter system kill session '1249,1' immediate;

SYS@192.168.31.8:1521/hrp430> @ bg rsm
ADDR                 PID SPID   PROGRAM
---------------- ------- ------ ----------------------------------------
00000000BD7A83A0      23 3650   oracle@xhserver (RSM0)
--//都是後臺程式RSM0(broker resource manager),這個程式是執行dg broken相關的程式。

來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/267265/viewspace-2765123/,如需轉載,請註明出處,否則將追究法律責任。

相關文章