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