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