[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慢也可能导致该等待事件出现.