为什么说log file sync(其实是写redo慢)会造成buffer busy wait?

在《gc buffer busy/gcs log flush sync与log file sync》一文中我介绍了 redo flush慢造成RAC中gc buffer busy争用的原理， 而在《【技术分享】开Oracle调优鹰眼，深入理解AWR性能报告》 中我又介绍了 log file sync(其实本质是lgwr 写redo慢)也会造成单实例single instance环境中的buffer busy wait等待， 这是为什么呢？   我们来做一个演示说明该问题：   示例用表： conn maclean/oracle create table  maclog (t1 int);   打开一个Session A 并获得它的OS进程号 [oracle@vrh8 ~]$ sqlplus / as sysdba SQL*Plus: Release 10.2.0.5.0 - Production on Sat Mar 9 09:32:25 2013 Copyright (c) 1982, 2010, Oracle. All Rights Reserved. Connected to: Oracle Database 10g Enterprise Edition Release 10.2.0.5.0 - 64bit Production With the Partitioning, OLAP, Data Mining and Real Application Testing options     [oracle@vrh8 ~]$ ps -ef|grep LOCAL oracle 18441 18438 0 09:41 ? 00:00:00 oracleG10R25 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq))) oracle 18445 18348 0 09:42 pts/3 00:00:00 grep LOCAL   使用 gdb debug 该18375的前台进程，并指定breakpoint [oracle@vrh8 ~]$ gdb $ORACLE_HOME/bin/oracle 18441 GNU gdb (GDB) Red Hat Enterprise Linux (7.0.1-37.el5) (gdb) b kcrf_commit_force Breakpoint 1 at 0x286519c   之后在session A执行：   SQL> insert into maclog values(1); 1 row created. 若insert hang，则在GDB 中输入多次C  - continue 这样能够继续   输入 commit; ==》 此时session A会hang住   SQL> commit;   ====》HANG   在GDB 中输入bt 可以看到stack call (gdb) bt #0 0x000000000286519c in kcrf_commit_force () #1 0x00000000028620ef in kcrfw_redo_gen () #2 0x00000000010e7dba in kcbchg1_main () #3 0x00000000010e6d99 in kcbchg () #4 0x000000000143f65a in ktucmt () #5 0x00000000013c7a06 in ktcCommitTxn () #6 0x00000000042a559e in ktdcmt () #7 0x00000000024fe09c in k2lcom () #8 0x0000000002418993 in k2send () #9 0x0000000001418b47 in xctctl () #10 0x00000000014174dd in xctcom_with_options () #11 0x000000000211fc26 in kksExecuteCommand () #12 0x00000000030ef87a in opiexe () #13 0x0000000003232d47 in kpoal8 () #14 0x00000000013b7c10 in opiodr () #15 0x0000000003c3c9da in ttcpip () #16 0x00000000013b3144 in opitsk () #17 0x00000000013b60ec in opiino () #18 0x00000000013b7c10 in opiodr () #19 0x00000000013a92f8 in opidrv () #20 0x0000000001fa3936 in sou2o () #21 0x000000000072d40b in opimai_real () #22 0x000000000072d35c in main () 其stack call为ktcCommitTxn=> ktucmt => kcbchg => kcbchg1_main => kcrfw_redo_gen => kcrf_commit_force   kcbchg==> block change ，为什么要发生block change呢？ 因为commit需要对在Buffer Cache里的block做immediate block cleanout 此时开一个session B  查询maclog表 SQL> select * from maclog; ==》阻塞在buffer busy wait上   这样就通过 无法完成的immediate block cleanout 去pin住buffer ，来形成了一个buffer busy wait   做一个system state dump : SQL> oradebug setmypid Statement processed. SQL> SQL> oradebug dump systemstate 266; Statement processed. SQL> oradebug tracefile_name /s01/admin/G10R25/udump/g10r25_ora_18551.trc   分析该systemstate dump   Session B一直在等 buffer busy wait SO: 0xaa42fff8, type: 4, owner: 0xaa3048f8, flag: INIT/-/-/0x00 (session) sid: 164 trans: (nil), creator: 0xaa3048f8, flag: (100051) USR/- BSY/-/-/-/-/- DID: 0001-0008-00000002, short-term DID: 0000-0000-00000000 txn branch: (nil) oct: 0, prv: 0, sql: (nil), psql: (nil), user: 0/SYS service name: SYS$BACKGROUND waiting for 'buffer busy waits' wait_time=0, seconds since wait started=245 file#=2, block#=89, class#=21 blocking sess=0x(nil) seq=12413 Dumping Session Wait History for 'buffer busy waits' count=1 wait_time=0.215431 sec file#=2, block#=89, class#=21 for 'buffer busy waits' count=1 wait_time=0.977438 sec file#=2, block#=89, class#=21 for 'buffer busy waits' count=1 wait_time=0.977538 sec file#=2, block#=89, class#=21 for 'buffer busy waits' count=1 wait_time=0.977512 sec file#=2, block#=89, class#=21 for 'buffer busy waits' count=1 wait_time=0.977480 sec file#=2, block#=89, class#=21 for 'buffer busy waits' count=1 wait_time=0.977488 sec file#=2, block#=89, class#=21 for 'buffer busy waits' count=1 wait_time=0.977639 sec file#=2, block#=89, class#=21 其stack call为： Short stack dump: ksdxfstk()+32<-ksdxcb()+1573<-sspuser()+111<-__restore_rt()+0<-__GI_semtimedop()+10<-sskgpwwait()+265<-skgpwwait()+162<-kslwaitns_timed()+1102<-kskthbwt()+246<-kslwait( )+228<-kcbzwb()+1496<-kcbgtcr()+23190<-ktugct()+588<-ktbgcl1()+4711<-ktrgcm()+1979<-ktrget()+486<-kdst_fetch()+524<-kdstf0000001kmP()+3137<-kdsttgr()+2427<-qertbFetch() +650<-qergsFetch()+444<-opifch2()+2944<-opiall0()+2206<-opikpr()+642<-opiodr()+1184<-rpidrus()+196<-skgmstack()+158<-rpidru()+116<-rpiswu2()+409<-kprball()+1270<-kkescF etch()+83<-kkedsamp()+6304<-kkedsSel()+1495<-kkecdn()+3055<-kkotap()+859<-kkoiqb()+9830<-kkooqb()+904<-kkoqbc()+2093<-apakkoqb()+167<-apaqbdDescendents()+414<-apaqbdLis tReverse()+68<-apadrv()+573<-opitca()+1545<-kksLoadChild()+9714<-kxsGetRuntimeLock()+1454<-kksfbc()+14910<-kkspsc0()+979<-kksParseCursor()+142<-opiosq0()+1641<-kpooprx( )+318<-kpoal8()+964<-opiodr()+1184<-ttcpip()+1226<-opitsk()+1310<-opiino()+1024<-opiodr()+1184<-opidrv()+548<-sou2o()+114<-opimai_real()+163<-main()+116<-__libc_start_m ain()+244<-_start()+41     file=2 block=0x89 即 137 md: EXCL  被  owner: 0xaa30b888  PID=22持有 SO: 0xaadd91d8, type: 24, owner: 0xaa44f240, flag: INIT/-/-/0xc0 (buffer) (CR) PR: 0xaa30c878 FLG: 0x0 class bit: (nil) kcbbfbp: [BH: 0x69fe2948, LINK: 0xaadd9218] (WAITING) where: ktuwh05: ktugct, why: 0 BH (0x69fe2948) file#: 2 rdba: 0x00800089 (2/137) class: 33 ba: 0x69cc6000 set: 3 blksize: 8192 bsi: 0 set-flg: 0 pwbcnt: 0 dbwrid: 0 obj: -1 objn: 0 tsn: 1 afn: 2 hash: [aacc0958,aacc0958] lru: [75fc3228,7eff15a8] obj-flags: object_ckpt_list ckptq: [6ef77368,aadf28f8] fileq: [6ef77378,aadf2938] objq: [a7bdd678,6afdf518] use: [aaddb748,aaddb748] wait: [aaddef10,aadd9218] st: XCURRENT md: EXCL tch: 465 flags: mod_started gotten_in_current_mode block_written_once redo_since_read change state: ACTIVE change count: 1 LRBA: [0x2d5.10d5a.0] HSCN: [0x0.242e76a] HSUB: [1] Using State Objects ---------------------------------------- SO: 0xaaddb708, type: 24, owner: 0xaa454568, flag: INIT/-/-/0x00 (buffer) PR: 0xaa30b888 FLG: 0x1000 class bit: (nil) kcbbfbp: [BH: 0x69fe2948, LINK: 0xaaddb748] where: ktuwh02: ktugus, why: 0 Waiting State Objects ---------------------------------------- SO: 0xaaddeed0, type: 24, owner: 0xaa450598, flag: INIT/-/-/0xc0 (buffer) PR: 0xaa3048f8 FLG: 0x0 class bit: (nil) kcbbfbp: [BH: 0x69fe2948, LINK: 0xaaddef10] (WAITING) where: ktuwh02: ktugus, why: 0   简单来说这个示例说明了几点：

1. OLTP类型的小DML操作一般都会是immediate block cleanout的，这要求在commit之前对block做change kcbchg
2. 在commit kcrf_commit_force完成前都不会释放对该block buffer的buffer pin
3. 由上述2点造成的buffer pin最终会影响select和其他insert/update/delete 形成buffer busy wait
4. 由于慢的lgwr写redo log会造成 kcrf_commit_force commit的缓慢，表现在等待事件上就是log file sync
5. 由于block cleanout时pin block buffer且commit 慢，则会导致更长时间的buffer busy wait
6. 若log file sync是由lgwr 写redo log慢(log file parallel write)引起的，则它的另一个效应就是buffer busy wait增多
7. 若看到AWR中log file sync+buffer busy wait是主要等待事件，则优先解决log file sync ，因为buffer busy wait实际可能是受害者

  AWR中与commit cleanout相关的 Instance activity 有好几个   commit cleanout failures: block lost commit cleanout failures: buffer being written commit cleanout failures: callback failure commit cleanout failures: cannot pin commit cleanouts commit cleanouts successfully completed