[20180305]手工模擬buffer busy wait.txt

--//一般出現buffer busy wait原因,主要是對熱塊,大量dml操作.
--//一種提法:oracle讀不會阻塞寫,寫不會阻塞讀,實際上寫一定程度會阻塞讀,只不過時間很短罷了.

--//以前vage提到過一種特殊情況導致buffer busy wait,那就是寫日誌緩慢,也會導致這種情況出現,昨天看
--//
--//自己也重新測試看看:

1.環境:
SCOTT@book> @ &r/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

2.測試:
SCOTT@book> @ &r/s
SCOTT@book(41,2229)> @ &r/spid
SID SERIAL# PROCESS SERVER SPID PID P_SERIAL# C50
---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------
41 2229 11184 DEDICATED 11185 27 241 alter system kill session '41,2229' immediate;

--//程式號=11185
SCOTT@book(41,2229)> create table deptx as select * from dept;
Table created.

SCOTT@book(41,2229)> select rowid,deptx.* from deptx where rownum=1;
ROWID DEPTNO DNAME LOC
------------------ ---------- -------------- -------------
AAAWGMAAEAAAAIrAAA 10 ACCOUNTING NEW YORK

SCOTT@book(41,2229)> @ &r/rowid AAAWGMAAEAAAAIrAAA
OBJECT FILE BLOCK ROW ROWID_DBA DBA TEXT
---------- ---------- ---------- ---------- -------------------- -------------------- ----------------------------------------
90508 4 555 0 0x100022B 4,555 alter system dump datafile 4 block 555 ;

--//終端:
gdb $(which oracle) 11185
...

(gdb) b kcrf_commit_force
Breakpoint 1 at 0x96cf4e4

--//session 1:
SCOTT@book(41,2229)> update deptx set dname=lower(dname) where deptno=10;
1 row updated.
SCOTT@book(41,2229)> commit ;
--//掛起!!

--//終端介面:
Breakpoint 1, 0x00000000096cf4e4 in kcrf_commit_force ()

--//session 2:
SCOTT@book> @ &r/s
SCOTT@book(54,1201)> @ &r/spid
SID SERIAL# PROCESS SERVER SPID PID P_SERIAL# C50
---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------
54 1201 11208 DEDICATED 11209 28 38 alter system kill session '54,1201' immediate;

--//程式號=11209
SCOTT@book(54,1201)> @ &r/wait
no rows selected

SCOTT@book(54,1201)> select * from deptx;
--//掛起!!

--//session 3:
SYS@book> @ &r/wait
P1RAW            P2RAW            P3RAW                    P1         P2         P3        SID    SERIAL#       SEQ# EVENT                                    STATUS   STATE               WAIT_TIME_MICRO SECONDS_IN_WAIT WAIT_CLASS
---------------- ---------------- ---------------- ---------- ---------- ---------- ---------- ---------- ---------- ---------------------------------------- -------- ------------------- --------------- --------------- --------------------
0000000062657100 0000000000000001 00               1650815232          1          0         41       2229         85 SQL*Net message from client              ACTIVE   WAITED KNOWN TIME           6655081              21 Idle
0000000000000004 000000000000022B 0000000000000001          4        555          1         54       1201         51 buffer busy waits                        ACTIVE   WAITING                     3121034               3 Concurrency

SYS@book> @ &r/ev_name 'buffer busy waits'
EVENT# EVENT_ID NAME PARAMETER1 PARAMETER2 PARAMETER3 WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS
---------- ---------- ---------------------------------------- -------------------- -------------------- -------------------- ------------- ----------- --------------------
95 2161531084 buffer busy waits file# block# class# 3875070507 4 Concurrency

--//sid=54出現buffer busy waits,奇怪的是sid=41,出現的是SQL*Net message from client.
--//你可以發現buffer busy waits 的P1,P2引數與前面查詢訪問的塊號一致dba=4,555.

--//終端介面:
(gdb) bt
#0 0x00000000096cf4e4 in kcrf_commit_force ()
#1 0x00000000096cb7bf in kcrfw_redo_gen ()
#2 0x0000000000e3d60b in kcb_commit_main ()
#3 0x0000000000e3c949 in kcb_commit ()
#4 0x0000000000f6412f in ktiCommitCleanout ()
#5 0x0000000000f63806 in kticmt ()
#6 0x0000000000f1e6dc in ktucmt ()
#7 0x00000000094facf5 in ktcCommitTxn ()
#8 0x000000000304023c in ktdcmt ()
#9 0x000000000210f400 in k2lcom ()
#10 0x0000000002128f65 in k2send ()
#11 0x0000000000f05073 in xctctl ()
#12 0x0000000000f03392 in xctCommitTxn ()
#13 0x0000000001ed651b in kksExecuteCommand ()
#14 0x00000000095c8398 in opiexe ()
#15 0x0000000001ba5992 in kpoal8 ()
#16 0x00000000095bbdad in opiodr ()
#17 0x00000000097a629f in ttcpip ()
#18 0x000000000186470e in opitsk ()
#19 0x0000000001869235 in opiino ()
#20 0x00000000095bbdad in opiodr ()
#21 0x00000000018607ac in opidrv ()
#22 0x0000000001e3a48f in sou2o ()
#23 0x0000000000a29265 in opimai_real ()
#24 0x0000000001e407ad in ssthrdmain ()
#25 0x0000000000a291d1 in main ()

--//如果在一個塊內大量的修改與查詢,就很容易出現buffer busy waits,我這裡在commit設定斷點,很明顯
--//要寫redo 快取到redo檔案.如果在應用中出現log file sync+buffer busy wait優先解決log file sync.
--//當然一些dml的熱塊也要注意.

--//轉載:

3.簡單來說這個示例說明了幾點：

OLTP型別的小DML操作一般都會是immediate block cleanout的，這要求在commit之前對block做change kcbchg
在commit kcrf_commit_force完成前都不會釋放對該block buffer的buffer pin
由上述2點造成的buffer pin最終會影響select和其他insert/update/delete 形成buffer busy wait
由於慢的lgwr寫redo log會造成 kcrf_commit_force commit的緩慢，表現在等待事件上就是log file sync
由於block cleanout時pin block buffer且commit 慢，則會導致更長時間的buffer busy wait
若log file sync是由lgwr 寫redo log慢(log file parallel write)引起的，則它的另一個效應就是buffer busy wait增多

若看到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

4.補充:
--//以上測試等一會:
--//session 3:
SYS@book> @ &r/wait
P1RAW            P2RAW            P3RAW                    P1         P2         P3        SID    SERIAL#       SEQ# EVENT                                    STATUS   STATE               WAIT_TIME_MICRO SECONDS_IN_WAIT WAIT_CLASS
---------------- ---------------- ---------------- ---------- ---------- ---------- ---------- ---------- ---------- ---------------------------------------- -------- ------------------- --------------- --------------- --------------------
0000000062657100 0000000000000001 00               1650815232          1          0         41       2229         85 SQL*Net message from client              ACTIVE   WAITED KNOWN TIME           6655081             255 Idle
0000000000000004 000000000000022B 0000000000000001          4        555          1         54       1201         51 buffer busy waits                        ACTIVE   WAITING                   237183753             237 Concurrency
0000000000000003 0000000000000090 0000000000000013          3        144         19        222          1      25198 buffer busy waits                        ACTIVE   WAITING                   225469340             225 Concurrency

SYS@book> @ &r/ev_name 'buffer busy waits'
EVENT# EVENT_ID NAME PARAMETER1 PARAMETER2 PARAMETER3 WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS
---------- ---------- ---------------------------------------- -------------------- -------------------- -------------------- ------------- ----------- --------------------
95 2161531084 buffer busy waits file# block# class# 3875070507 4 Concurrency

--//又出現一個會話阻塞.buffer busy waits的P1,P2的引數是file#,block#.

SYS@book> @ &r/bh 3 144
HLADDR DBARFIL DBABLK CLASS CLASS_TYPE STATE TCH CR_SCN_BAS CR_SCN_WRP CR_UBA_FIL CR_UBA_BLK CR_UBA_SEQ BA OBJECT_NAME
---------------- ------- ----------- ----- ------------------ ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------------- --------------------
0000000084F763C0 3 144 19 xcur 173 0 0 0 0 0 000000007A33C000

SYS@book> @ &r/bh 4 555
HLADDR           DBARFIL      DBABLK CLASS CLASS_TYPE         STATE             TCH CR_SCN_BAS CR_SCN_WRP CR_UBA_FIL CR_UBA_BLK CR_UBA_SEQ BA               OBJECT_NAME
---------------- ------- ----------- ----- ------------------ ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------------- --------------------
0000000084EB03C8       4         555     1 data block         xcur                2          0          0          0          0          0 00000000648CE000 DEPTX
0000000084EB03C8       4         555     1 data block         cr                  2 392461831          3          0          0          0 00000000648D0000 DEPTX
0000000084EB03C8       4         555     1 data block         cr                  1 392461277          3          0          0          0 00000000733B2000 DEPTX
0000000084EB03C8       4         555     1 data block         free                0          0          0          0          0          0 0000000070730000
--//HLADDR 不一樣,不知道為什麼出現buffer busy waits sid=222.

SYS@book> select PROGRAM,sid,serial#,sql_id from v$session where sid=222;
PROGRAM SID SERIAL# SQL_ID
-------------------------- ---------- ---------- -------------
oracle@gxqyydg4 (MMON) 222 1

SYS@book> select PROGRAM,sid,serial#,sql_id,PREV_SQL_ID from v$session where sid=222;
PROGRAM SID SERIAL# SQL_ID PREV_SQL_ID
-------------------------- ---------- ---------- ------------- -------------
oracle@gxqyydg4 (MMON) 222 1 fsbqktj5vw6n9

SYS@book> @ &r/sql_id fsbqktj5vw6n9
old   1: select sql_id,sql_fulltext sqltext from gv$sqlarea where sql_id='&1'
new   1: select sql_id,sql_fulltext sqltext from gv$sqlarea where sql_id='fsbqktj5vw6n9'
SQL_ID        SQLTEXT
------------- --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
fsbqktj5vw6n9 select next_run_date, obj#, run_job, sch_job from (select decode(bitand(a.flags, 16384), 0, a.next_run_date,                a.last_enabled_time) next_run_date,       a.obj# obj#, decode(bitand(a.flags
              , 16384), 0, 0, 1) run_job, a.sch_job sch_job from (select p.obj# obj#, p.flags flags, p.next_run_date next_run_date,      p.job_status job_status, p.class_oid class_oid,      p.last_enabled_time l
              ast_enabled_time, p.instance_id instance_id,      1 sch_job   from sys.scheduler$_job p   where bitand(p.job_status, 3) = 1    and ((bitand(p.flags, 134217728 + 268435456) = 0) or         (bitand(p.jo
              b_status, 1024) <> 0))    and bitand(p.flags, 4096) = 0    and p.instance_id is NULL    and (p.class_oid is null      or (p.class_oid is not null      and p.class_oid in (select b.obj# from sys.schedu
              ler$_class b                          where b.affinity is null)))   UNION ALL   select q.obj#, q.flags, q.next_run_date, q.job_status, q.class_oid,      q.last_enabled_time, q.instance_id, 1   from sy
              s.scheduler$_lightweight_job q   where bitand(q.job_status, 3) = 1    and ((bitand(q.flags, 134217728 + 268435456) = 0) or         (bitand(q.job_status, 1024) <> 0))    and bitand(q.flags, 4096) = 0
                and q.instance_id is NULL    and (q.class_oid is null      or (q.class_oid is not null      and q.class_oid in (select c.obj# from sys.scheduler$_class c                          where c.affinity is
               null)))   UNION ALL   select j.job, 0, from_tz(cast(j.next_date as timestamp),      to_char(systimestamp,'TZH:TZM')), 1, NULL,      from_tz(cast(j.next_date as timestamp),to_char(systimestamp,'TZH:TZ
              M')),     NULL, 0   from sys.job$ j   where (j.field1 is null or j.field1 = 0)    and j.this_date is null) a   order by 1)   where rownum = 1

--//放棄,不知道為什麼出現後續的buffer busy waits的等待事件.
--//在終端介面上執行:
(gdb) c
Continuing.

Breakpoint 1, 0x00000000096cf4e4 in kcrf_commit_force ()
(gdb) c
Continuing.

--//session 1:
SCOTT@book(41,2229)> commit ;
Commit complete.
--//提交成功.

--//session 2:
SCOTT@book(54,1201)> select * from deptx;
    DEPTNO DNAME          LOC
---------- -------------- -------------
        10 accounting     NEW YORK
        20 RESEARCH       DALLAS
        30 SALES          CHICAGO
        40 OPERATIONS     BOSTON

--//session 3:
SYS@book> @ &r/wait
no rows selected

[20180305]手工模擬buffer busy wait.txt

相關文章