[20191126]探究等待事件的本源2.txt

[20191126]探究等待事件的本源2.txt

--//做一個測試,驗證如果寫入控制檔案慢也會影響提交效能.

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

SCOTT@book> create table t ( a number ) ;
Table created.

SCOTT@book> insert into t values (1);
1 row created.

SCOTT@book> commit ;
Commit complete.

$ ps -ef | grep lgw[r]
oracle   62683     1  0 Nov25 ?        00:00:09 ora_lgwr_book
--//pid=62683.

$ ls -l /proc/62683/fd/25[67]
lrwx------ 1 oracle oinstall 64 2019-11-26 08:53:07 /proc/62683/fd/256 -> /mnt/ramdisk/book/control01.ctl
lrwx------ 1 oracle oinstall 64 2019-11-26 08:53:07 /proc/62683/fd/257 -> /mnt/ramdisk/book/control02.ctl
--//控制檔案控制程式碼是256,257.

$ cat pw.gdb
break *pwrite if $rdi==256
c
--//如果檔案控制程式碼256存在寫入,中斷執行.

2.啟動gdb,測試:
--//session 1:
SCOTT@book> select sysdate from dual ;
SYSDATE
-------------------
2019-11-26 08:54:14

--//session 2:
$ gdb -p 62683 -x  pw.gdb
...

Breakpoint 1, 0x000000379a00e600 in pwrite64 () from /lib64/libpthread.so.0
(gdb)

--//session 3:
SYS@book> alter system switch logfile ;
--//掛起!!

--//session 1:
SCOTT@book> @ wait
P1RAW            P2RAW            P3RAW                    P1         P2         P3        SID    SERIAL#       SEQ# EVENT                                    STATUS   STATE               WAIT_TIME_MICRO SECONDS_IN_WAIT WAIT_CLASS
---------------- ---------------- ---------------- ---------- ---------- ---------- ---------- ---------- ---------- ---------------------------------------- -------- ------------------- --------------- --------------- --------------------
00               00               00                        0          0          0         86        559         17 switch logfile command                   ACTIVE   WAITING                     9280572               9 Administrative
0000000000000002 0000000000000015 0000000000000002          2         21          2        183          1      20011 control file parallel write              ACTIVE   WAITING                     9280236               9 System I/O
--//可以發現當前是日誌切換,寫入控制檔案時設定斷點,導致session 3掛起!!

SCOTT@book> insert into t values (3);
1 row created.

SCOTT@book> commit ;
--//掛起!!

--//session 4:
SYS@book> @ wait
P1RAW            P2RAW            P3RAW                    P1         P2         P3        SID    SERIAL#       SEQ# EVENT                                    STATUS   STATE               WAIT_TIME_MICRO SECONDS_IN_WAIT WAIT_CLASS
---------------- ---------------- ---------------- ---------- ---------- ---------- ---------- ---------- ---------- ---------------------------------------- -------- ------------------- --------------- --------------- --------------------
00               00               00                        0          0          0         86        559         17 switch logfile command                   ACTIVE   WAITING                    82559695              83 Administrative
00000000000001C8 0000000088E4CF71 00                      456 2296696689          0        128        523       2582 log file sync                            ACTIVE   WAITING                    44688489              45 Commit
0000000000000002 0000000000000015 0000000000000002          2         21          2        183          1      20011 control file parallel write              ACTIVE   WAITING                    82559359              83 System I/O
--//可以發現出現log file sync等待事件.

--//session 2,不斷按c繼續執行.最後session 1,提交ok.
--//session 1:
SCOTT@book> commit ;
Commit complete.

SCOTT@book> select sysdate from dual ;
SYSDATE
-------------------
2019-11-26 08:59:17

--//session 2,不斷按c繼續執行,最後session 3切換日誌ok.
--//session 3:
SYS@book> alter system switch logfile ;
System altered.

--//session 2:
--//按ctrl+c強制中斷,退出gdb介面.

SCOTT@book> @ tpt/ash/dash_wait_chains program2||event2 1=1 trunc(sysdate)+8/24+54/1440+14/86400  trunc(sysdate)+8/24+59/1440+17/86400
-- Display ASH Wait Chain Signatures script v0.2 BETA by Tanel Poder ( http://blog.tanelpoder.com )
%This     SECONDS        AAS WAIT_CHAIN
------ ---------- ---------- --------------------------------------------------------------------------
  34%         210         .7 -> (sqlplus) switch logfile command  -> (LGWR) control file parallel write
  34%         210         .7 -> (LGWR) control file parallel write
  23%         140         .5 -> (sqlplus) log file sync  -> (LGWR) control file parallel write
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~  
  10%          60         .2 -> (MMON) enq: CF - contention  -> (LGWR) control file parallel write

--//你可以發現產生log file sync的原因是control file parallel write寫太慢.

SCOTT@book> @ spid
       SID    SERIAL# PROCESS                  SERVER    SPID       PID  P_SERIAL# C50
---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------
       128        523 4879                     DEDICATED 4880        33        218 alter system kill session '128,523' immediate;

SCOTT@book> @ tpt/ash/dash_wait_chains program2||event2 session_id=128 trunc(sysdate)+8/24+54/1440+14/86400  trunc(sysdate)+8/24+59/1440+17/86400
-- Display ASH Wait Chain Signatures script v0.2 BETA by Tanel Poder ( http://blog.tanelpoder.com )
%This     SECONDS        AAS WAIT_CHAIN
------ ---------- ---------- -----------------------------------------------------------------
 100%         140         .5 -> (sqlplus) log file sync  -> (LGWR) control file parallel write

3.總結:
--//不要一看到log file sync等待事件就以為是redo寫入慢,實際上control file parallel write慢也可能導致該等待事件出現.