等待事件_buffer_busy_waits_and_read_by_other_session(3)
4,insert/insert引起的buffer busy waits
4.1FLM freelists=1
測試方式:在使用FLM(free list managemnet)時,由於freelists預設為1,在多個程式由於同時使用同一個空閒塊,發生buffer lock爭用.
create tablespace flm_tbs
datafile '/oracle/oradata/ora10ctg/flm_tbs01.dbf'
size 50M autoextend on
extent management local uniform. size 1M
segment space management manual;
drop table test;
create table test(id varchar2(10))
storage (freelists 1)
tablespace flm_tbs;
create or replace procedure do_insert is
l_cursor sys_refcursor;
l_value number;
begin
for x in 1..100000 loop
insert into test values(' ');
end loop;
commit;
end;
/
set serveroutput on
exec session_pkg.get_snap;
declare
l_job number;
begin
for x in 1..10 loop
dbms_job.submit(l_job,'do_insert;');
end loop;
commit;
end;
/
exec do_insert;
exec session_pkg.rpt_stat_event(0);
==>
--------------
Session id:116 Serial#:84 Last sampid:8362483
----session stats---
Name Value
redo size 26,540,060
undo change vector size 9,204,564
session uga memory 1,184,008
session pga memory 786,432
db block changes 202,048
session logical reads 108,844
db block gets 103,751
db block gets from cache 103,751
recursive calls 100,658
redo entries 100,626
execute count 100,144
workarea memory allocated 5,960
consistent gets from cache 5,093
consistent gets 5,093
consistent gets - examination 4,374
active txn count during cleano 4,333
bytes received via SQL*Net fro 2,549
table scan rows gotten 1,925
DB time 1,690
bytes sent via SQL*Net to clie 1,418
free buffer requested 1,310
calls to kcmgas 1,202
redo ordering marks 1,197
sorts (rows) 1,089
concurrency wait time 1,080
cleanout - number of ktugct ca 665
CPU used when call started 527
CPU used by this session 509
calls to kcmgcs 441
recursive cpu usage 424
commit cleanouts 397
commit cleanouts successfully 394
calls to get snapshot scn: kcm 211
no work - consistent read gets 179
buffer is not pinned count 162
enqueue releases 115
enqueue requests 112
parse count (total) 86
session cursor cache hits 73
opened cursors cumulative 71
change write time 68
table fetch by rowid 52
shared hash latch upgrades - n 52
table scan blocks gotten 49
messages sent 42
index scans kdiixs1 40
index fetch by key 40
table scans (short tables) 31
user calls 21
cluster key scan block gets 20
cluster key scans 20
parse count (hard) 17
cursor authentications 14
SQL*Net roundtrips to/from cli 11
table fetch continued row 10
buffer is pinned count 10
enqueue waits 5
consistent changes 3
user commits 3
sorts (memory) 3
redo synch writes 3
commit cleanout failures: bloc 2
heap block compress 2
opened cursors current 2
commit cleanout failures: cann 1
write clones created in foregr 1
cleanouts only - consistent re 1
immediate (CR) block cleanout 1
enqueue conversions 1
commit txn count during cleano 1
----session events---
Wait_Class Event Total_waits Time_waited
Commit log file sync 3 1
Concurrency latch: library cache pin 3 1
Concurrency latch: cache buffers chains 5 1
Concurrency buffer busy waits 1,457 1,079
Configuration enq: HW - contention 9 1
Idle SQL*Net message from client 11 19
Network SQL*Net message to client 11 0
Other events in waitclass Other 7 0
----v$active_session_history---
Wait_class Event count(*) min_samp max_samp
Concurrency buffer busy waits 11 8362489 8362500
分析:
伴隨buffer busy waits(1457次)事件,出現了enq: HW - contention(9次)
p3(class#)為4表示段頭塊,為1表示資料塊.由於使用FLM,多個會話可能同時插入同一個塊,導致資料塊的爭用;為了修改FLM或HighWaterMark,導致段頭塊的爭用.
整個例項在測試期間相關等待如下：
col event format a20
SELECT event, p1, p2, p3,count(*)
FROM v$active_session_history
WHERE sample_id > 8362483
AND event IN ('buffer busy waits', 'read by other session')
GROUP BY event, p1, p2, p3
ORDER BY event, p1, p2, p3;
EVENT P1 P2 P3 COUNT(*)
-------------------- ---------- ---------- ---------- ----------
buffer busy waits 11 399 1 7
buffer busy waits 11 427 1 10
buffer busy waits 11 456 1 5
buffer busy waits 11 593 1 10
buffer busy waits 11 623 1 10
buffer busy waits 11 653 1 10
buffer busy waits 11 684 1 9
buffer busy waits 11 715 1 10
buffer busy waits 11 742 1 18
buffer busy waits 11 745 1 9
buffer busy waits 11 762 1 9
buffer busy waits 11 767 1 7
...
84 rows selected
4.2 FLM freelists=11
drop table test;
create table test(id varchar2(10))
storage (freelists 11)
tablespace flm_tbs;
create or replace procedure do_insert is
l_cursor sys_refcursor;
l_value number;
begin
for x in 1..100000 loop
insert into test values(' ');
end loop;
commit;
end;
/
set serveroutput on
exec session_pkg.get_snap;
declare
l_job number;
begin
for x in 1..10 loop
dbms_job.submit(l_job,'do_insert;');
end loop;
commit;
end;
/
exec do_insert;
exec session_pkg.rpt_stat_event(0);
==>
Session id:116 Serial#:84 Last sampid:8362697
----session stats---
Name Value
redo size 26,562,812
undo change vector size 9,247,508
session uga memory 1,184,008
session pga memory 786,432
db block changes 202,229
session logical reads 108,617
db block gets 107,169
db block gets from cache 107,169
recursive calls 101,974
redo entries 100,802
execute count 100,287
workarea memory allocated 6,008
table scan rows gotten 4,844
DB time 3,464
bytes received via SQL*Net fro 2,549
enqueue releases 2,123
enqueue requests 2,120
consistent gets 1,448
consistent gets from cache 1,448
bytes sent via SQL*Net to clie 1,418
sorts (rows) 1,089
concurrency wait time 963
CPU used when call started 796
free buffer requested 793
CPU used by this session 780
calls to kcmgas 717
calls to get snapshot scn: kcm 701
redo ordering marks 698
recursive cpu usage 662
enqueue conversions 616
change write time 585
no work - consistent read gets 413
consistent gets - examination 359
active txn count during cleano 301
redo log space wait time 286
table scan blocks gotten 248
parse count (total) 229
calls to kcmgcs 226
buffer is not pinned count 222
session cursor cache hits 213
cleanout - number of ktugct ca 212
opened cursors cumulative 207
commit cleanouts 183
commit cleanouts successfully 169
table scans (short tables) 160
table fetch by rowid 76
shared hash latch upgrades - n 62
steps of tune down ret. in spa 62
enqueue waits 58
redo synch time 57
drop segment calls in space pr 55
tune down retentions in space 55
space was found by tune down 55
index scans kdiixs1 52
index fetch by key 42
messages sent 35
redo buffer allocation retries 32
cluster key scan block gets 22
user calls 21
cluster key scans 21
parse count (hard) 21
redo log space requests 18
cursor authentications 18
SQL*Net roundtrips to/from cli 11
table fetch continued row 11
buffer is pinned count 10
commit cleanout failures: buff 9
local undo segment hints were 7
consistent changes 4
commit cleanout failures: call 3
local undo segment hints helpe 3
user commits 3
redo synch writes 3
sorts (memory) 3
write clones created in foregr 3
deferred (CURRENT) block clean 2
commit cleanout failures: bloc 2
opened cursors current 2
parse time cpu 2
heap block compress 2
commit txn count during cleano 1
CR blocks created 1
immediate (CR) block cleanout 1
transaction rollbacks 1
rollbacks only - consistent re 1
global undo segment hints were 1
free buffer inspected 1
parse time elapsed 1
data blocks consistent reads - 1
auto extends on undo tablespac 1
global undo segment hints help 1
cleanouts only - consistent re 1
----session events---
Wait_Class Event Total_waits Time_waited
Commit log file sync 3 54
Concurrency latch: cache buffers chains 1 0
Concurrency latch: library cache 5 25
Concurrency latch: library cache pin 6 28
Concurrency buffer busy waits 569 910
Configuration latch: redo copy 1 19
Configuration log file switch completion 9 128
Configuration log file switch (checkpoint in 9 151
Configuration enq: HW - contention 11 35
Configuration log buffer space 28 371
Configuration undo segment extension 371 104
Idle SQL*Net message from client 11 24
Network SQL*Net message to client 11 0
Other events in waitclass Other 78 360
----v$active_session_history---
Wait_class Event count(*) min_samp max_samp
Concurrency buffer busy waits 7 8362721 8362740
Configuration enq: HW - contention 1 8362741 8362741
Configuration log buffer space 5 8362717 8362733
Configuration log file switch (checkpoint in2 8362737 8362738
Configuration log file switch completion 1 8362715 8362715
Configuration undo segment extension 2 8362726 8362739
Other enq: US - contention 2 8362714 8362736
分析:
與FLM freelists=1相比:buffer busy waits(1457次),enq: HW - contention(9次)
FLM freelists=11時,buffer busy waits(569次)大幅減少，enq: HW - contention(11次)略有增加
當前session執行時間反而增加了，重複測試，還是比場景4.1執行時間長。
整個例項在測試期間相關等待如下：
col event format a20
SELECT event, p1, p2, p3,count(*)
FROM v$active_session_history
WHERE sample_id > 8362697
AND event IN ('buffer busy waits', 'read by other session')
GROUP BY event, p1, p2, p3
ORDER BY event, p1, p2, p3;
EVENT P1 P2 P3 COUNT(*)
-------------------- ---------- ---------- ---------- ----------
buffer busy waits 2 2 13 28
buffer busy waits 2 25 19 3
buffer busy waits 2 41 21 3
buffer busy waits 2 73 25 1
buffer busy waits 2 153 35 1
buffer busy waits 11 2215 1 1
buffer busy waits 11 2312 1 1
buffer busy waits 11 2449 1 1
buffer busy waits 11 2572 1 1
buffer busy waits 11 2748 1 1
buffer busy waits 11 2848 1 1
buffer busy waits 11 2968 1 1
buffer busy waits 11 3003 1 1
buffer busy waits 11 3036 1 1
buffer busy waits 11 3071 1 1
buffer busy waits 11 3146 1 1
buffer busy waits 11 3330 1 2
17 rows selected
4.3 ASSM
create tablespace assm_tbs
datafile '/oracle/oradata/ora10ctg/assm_tbs01.dbf'
size 50M autoextend on
extent management local uniform. size 1M
segment space management auto;
drop table test;
create table test(id varchar2(10))
tablespace assm_tbs;
create or replace procedure do_insert is
l_cursor sys_refcursor;
l_value number;
begin
for x in 1..100000 loop
insert into test values(' ');
end loop;
commit;
end;
/
set serveroutput on
exec session_pkg.get_snap;
declare
l_job number;
begin
for x in 1..10 loop
dbms_job.submit(l_job,'do_insert;');
end loop;
commit;
end;
/
exec do_insert;
exec session_pkg.rpt_stat_event(0);
==>
Session id:116 Serial#:84 Last sampid:8364156
----session stats---
Name Value
redo size 26,549,748
undo change vector size 9,205,856
session uga memory 1,176,520
session pga memory 720,896
db block changes 202,005
session logical reads 105,667
db block gets 104,040
db block gets from cache 104,040
redo entries 100,775
recursive calls 100,707
execute count 100,144
workarea memory allocated 5,990
DB time 2,656
bytes received via SQL*Net fro 2,549
consistent gets 1,627
consistent gets from cache 1,627
table scan rows gotten 1,568
bytes sent via SQL*Net to clie 1,418
consistent gets - examination 1,318
active txn count during cleano 1,258
sorts (rows) 1,089
concurrency wait time 987
CPU used when call started 821
CPU used by this session 803
recursive cpu usage 666
cleanout - number of ktugct ca 404
change write time 389
free buffer requested 290
calls to kcmgcs 275
commit cleanouts 269
commit cleanouts successfully 267
calls to kcmgas 227
buffer is not pinned count 224
redo ordering marks 218
redo log space wait time 213
calls to get snapshot scn: kcm 200
no work - consistent read gets 186
parse count (total) 86
table fetch by rowid 76
session cursor cache hits 70
enqueue releases 66
opened cursors cumulative 64
shared hash latch upgrades - n 63
enqueue requests 63
index scans kdiixs1 52
index fetch by key 43
redo synch time 42
cluster key scan block gets 24
cluster key scans 22
user calls 21
table scan blocks gotten 20
parse count (hard) 20
messages sent 19
redo buffer allocation retries 19
cursor authentications 17
table scans (short tables) 16
SQL*Net roundtrips to/from cli 11
table fetch continued row 11
buffer is pinned count 10
redo log space requests 8
consistent changes 5
enqueue waits 4
redo synch writes 3
deferred (CURRENT) block clean 3
user commits 3
sorts (memory) 3
commit cleanout failures: bloc 2
heap block compress 2
data blocks consistent reads - 2
rollbacks only - consistent re 2
CR blocks created 2
opened cursors current 2
parse time elapsed 1
cleanouts only - consistent re 1
immediate (CR) block cleanout 1
write clones created in foregr 1
commit txn count during cleano 1
----session events---
Wait_Class Event Total_waits Time_waited
Commit log file sync 3 41
Concurrency latch: shared pool 1 0
Concurrency latch: library cache 3 9
Concurrency latch: library cache pin 4 56
Concurrency latch: cache buffers chains 6 35
Concurrency buffer busy waits 453 887
Configuration enq: HW - contention 2 9
Configuration log file switch (checkpoint in 3 106
Configuration log file switch completion 5 102
Configuration log buffer space 17 247
Idle SQL*Net message from client 11 27
Network SQL*Net message to client 11 0
Other events in waitclass Other 8 14
----v$active_session_history---
Wait_class Event count(*) min_samp max_samp
Concurrency buffer busy waits 11 8364190 8364212
Configuration log buffer space 2 8364208 8364209
Configuration log file switch (checkpoint in1 8364206 8364206
Configuration log file switch completion 1 8364205 8364205
PL/SQL procedure successfully completed
分析:
與FLM freelists=1時，buffer busy waits(1457次),enq: HW - contention(9次)
FLM freelists=11時,buffer busy waits(569次)，enq: HW - contention(11次)
ASSM時,buffer busy waits(453次)大幅減少，enq: HW - contention(2次)略有增加
當前session執行時間反而增加了，重複測試，還是比場景4.1執行時間長。
整個例項在測試期間相關等待如下：
col event format a20
SELECT event, p1, p2, p3,count(*)
FROM v$active_session_history
WHERE sample_id > 8364156
AND event IN ('buffer busy waits', 'read by other session')
GROUP BY event, p1, p2, p3
ORDER BY event, p1, p2, p3;
EVENT P1 P2 P3 COUNT(*)
-------------------- ---------- ---------- ---------- ----------
buffer busy waits 2 137 33 1
buffer busy waits 11 87 1 3
buffer busy waits 11 128 1 5
buffer busy waits 11 150 1 1
buffer busy waits 11 154 1 1
buffer busy waits 11 200 1 1
buffer busy waits 11 202 1 2
buffer busy waits 11 210 1 1
buffer busy waits 11 224 1 1
...
88 rows selected
分析：
*P3(class#)為8/9時分別表示L1/L2 BMB(Level1/2 Bitmap Block),L1 BMB管理最下層的leaf block,最容易發生爭用.
*在插入執行過程中可以觀察到p3=8的buffer busy waits,但取樣資料中沒有發現.
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/18922393/viewspace-713230/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- 等待事件_buffer_busy_waits_and_read_by_other_session(1)事件AISession
- 等待事件_buffer_busy_waits_and_read_by_other_session(2)事件AISession
- 等待事件_buffer_busy_waits_and_read_by_other_session(4)事件AISession
- oracle等待事件3構造一個Direct Path write等待事件和構造一個Log File Sync等待事件Oracle事件
- 【等待事件】ORACLE常見等待事件事件Oracle
- 【等待事件】等待事件系列（5.1）--Enqueue(佇列等待)事件ENQ佇列
- 等待事件事件
- 【TUNE_ORACLE】等待事件之等待事件類別Oracle事件
- 等待事件分析事件
- oracle等待事件Oracle事件
- Oracle 等待事件Oracle事件
- px等待事件事件
- 等待事件 二事件
- 【等待事件】等待事件系列（1）--User I/O型別事件型別
- 【效能調整】等待事件(三) 常見等待事件（一）事件
- 【效能調整】等待事件(四) 常見等待事件（二）事件
- Oracle Mutex 等待事件OracleMutex事件
- 等待事件指令碼事件指令碼
- oracle等待事件一Oracle事件
- ASH, AWR , 等待事件事件
- latch free等待事件事件
- 【Oracle概念】-等待事件Oracle事件
- 頂級等待事件：事件
- Oracle 等待事件 一Oracle事件
- Oracle的等待事件Oracle事件
- 常見等待事件事件
- 與IO相關的等待事件troubleshooting-系列3事件
- 【等待事件之二】log 相關的等待事件
- Latch free等待事件(轉)事件
- gc cr request等待事件GC事件
- latch等待事件彙總事件
- log file sync等待事件事件
- 【等待事件】log file sync事件
- ORACLE 常見等待事件Oracle事件
- cursor: mutex S等待事件Mutex事件
- latch 相關等待事件事件
- 【等待事件】Buffer Exterminate事件
- oracle常見等待事件Oracle事件