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