等待事件_buffer_busy_waits_and_read_by_other_session(4)
5 insert/insert引起的buffer busy waits
多個會話同時更新資料塊內的不同行時,會發生buffer lock爭用.
5.1 基準測試
drop table test;
--8k block,每個block存放10行
drop table test;
create table test(id number,name char(700)) tablespace assm_tbs;
begin
for x in 1..100 loop
insert into test values(x,' ');
end loop;
commit;
end;
/
select id,dbms_rowid.rowid_block_number(rowid) as block_no
from test;
ID BLOCK_NO
---------- ----------
1 3617
...
11 3621
...
21 3625
...
31 3629
...
41 3633
...
51 3637
...
61 3641
...
71 3645
...
81 3649
...
91 3653
...
100 3653
100 rows selected
create or replace procedure do_update(p_id in number) is
begin
for x in 1..1000 loop
for y in 1..10 loop
update test set name=' ' where id=10*(y-1)+p_id;
commit;
end loop;
end loop;
commit;
end;
/
set serveroutput on
exec session_pkg.get_snap;
declare
l_job number;
begin
for x in 1..9 loop
dbms_job.submit(l_job,'do_update('||x||');');
end loop;
commit;
end;
/
exec do_update(10);
exec session_pkg.rpt_stat_event(0);
==>
Session id:116 Serial#:84 Last sampid:8366973
----session stats---
Name Value
redo size 20,225,776
undo change vector size 8,788,324
session uga memory 1,481,376
session pga memory 1,048,576
table scan rows gotten 1,000,718
session logical reads 585,881
consistent gets 554,462
consistent gets from cache 554,462
table scan blocks gotten 480,107
no work - consistent read gets 473,257
calls to get snapshot scn: kcm 70,233
db block changes 42,750
db block gets 31,419
db block gets from cache 31,419
recursive calls 30,545
calls to kcmgas 25,720
consistent gets - examination 24,178
redo entries 22,682
consistent changes 20,908
data blocks consistent reads - 20,445
enqueue releases 20,104
enqueue requests 20,101
free buffer requested 16,329
execute count 10,124
table scans (short tables) 10,035
commit cleanouts 10,006
user commits 10,002
commit cleanouts successfully 9,687
switch current to new buffer 9,137
deferred (CURRENT) block clean 6,672
CR blocks created 6,355
workarea memory allocated 6,265
messages sent 5,812
rollbacks only - consistent re 3,917
active txn count during cleano 3,297
cleanout - number of ktugct ca 3,032
immediate (CR) block cleanout 2,995
cleanouts and rollbacks - cons 2,870
bytes received via SQL*Net fro 2,562
DB time 1,903
bytes sent via SQL*Net to clie 1,418
concurrency wait time 943
CPU used when call started 687
CPU used by this session 671
recursive cpu usage 644
redo ordering marks 633
free buffer inspected 450
commit txn count during cleano 400
sorts (rows) 363
commit cleanout failures: cann 312
change write time 143
cleanouts only - consistent re 125
shared hash latch upgrades - n 119
parse count (total) 73
opened cursors cumulative 72
buffer is not pinned count 56
session cursor cache hits 46
index fetch by key 37
index scans kdiixs1 23
user calls 21
cluster key scan block gets 18
cluster key scans 18
parse count (hard) 16
transaction tables consistent 15
redo synch time 13
table fetch by rowid 12
SQL*Net roundtrips to/from cli 11
buffer is pinned count 9
redo buffer allocation retries 7
commit cleanout failures: call 5
redo log space requests 5
parse time elapsed 5
shared hash latch upgrades - w 4
redo log space wait time 3
redo synch writes 3
opened cursors current 3
parse time cpu 2
transaction tables consistent 2
commit cleanout failures: bloc 2
cursor authentications 2
heap block compress 1
enqueue waits 1
sorts (memory) 1
----session events---
Wait_Class Event Total_waits Time_waited
Commit log file sync 3 13
Concurrency latch: cache buffers chains 95 209
Concurrency buffer busy waits 756 734
Configuration enq: HW - contention 1 1
Configuration log file switch completion 5 2
Configuration log buffer space 6 95
Idle SQL*Net message from client 11 28
Network SQL*Net message to client 11 0
Other events in waitclass Other 11 12
----v$active_session_history---
Wait_class Event count(*) min_samp max_samp
Concurrency buffer busy waits 8 8367432 8367443
Concurrency latch: cache buffers chains 3 8367429 8367438
PL/SQL procedure successfully completed
SQL> SELECT event, p1, p2, p3,count(*)
2 FROM v$active_session_history
3 WHERE sample_id > 8366973
4 AND event IN ('buffer busy waits', 'read by other session')
5 GROUP BY event, p1, p2, p3
6 ORDER BY event, p1, p2, p3;
EVENT P1 P2 P3 COUNT(*)
-------------------- ---------- ---------- ---------- ----------
buffer busy waits 2 25 19 1
buffer busy waits 2 73 25 1
buffer busy waits 2 105 29 2
buffer busy waits 2 121 31 1
buffer busy waits 2 153 35 1
buffer busy waits 2 272 34 1
buffer busy waits 2 6524 22 1
buffer busy waits 11 3617 1 20
buffer busy waits 11 3621 1 10
buffer busy waits 11 3625 1 7
buffer busy waits 11 3629 1 8
buffer busy waits 11 3633 1 14
buffer busy waits 11 3637 1 4
buffer busy waits 11 3641 1 3
buffer busy waits 11 3645 1 11
buffer busy waits 11 3649 1 6
buffer busy waits 11 3653 1 7
17 rows selected
分析:
*場景5.1:DB Time:19sec,buffer busy waits:756/7.3sec,latch cache buffers chains:95/2sec,enq HW - contention 1/0sec
*透過p3=1可知，在資料塊上發生大量的buffer busy waits，這是由於多個會話同時修改同一塊造成；在索引葉結點資料更加密集，這種情況爭用更容易發生
*透過p3=大於15的奇數可知，發生了很多undo segment header上的buffer busy waits（每個會話修改當前事務undo segment header，其他會話事物讀取）
*透過p3=大於15的偶數可知，發生了很多undo segment上的buffer busy waits（每個會話修改當前事務undo segment，其他會話事物讀取）
最佳化思路：
*設定較大的pctfree，但是存在問題：全表/索引掃描需要更多IO，SGA浪費，需要管理更多塊可能增加cache buffers chains latch爭用
*使用較小的塊，但是存在問題：全表/索引掃描需要更多IO，需要管理更多塊可能增加cache buffers chains latch爭用
*分割槽，主要問題是與業務邏輯耦合較高，帶來維護問題
5.2 設定pctfree=90
drop table test;
create table test(id number,name char(700))
pctfree 90 pctused 10
tablespace assm_tbs;
begin
for x in 1..100 loop
insert into test values(x,' ');
end loop;
commit;
end;
/
SELECT dbms_rowid.rowid_block_number(ROWID) AS block_no, COUNT(*) cnt
FROM test
GROUP BY dbms_rowid.rowid_block_number(ROWID);
BLOCK_NO CNT
---------- ----------
3728 1
3732 1
...
3806 1
3815 1
3826 1
3838 1
100 rows selected
create or replace procedure do_update(p_id in number) is
begin
for x in 1..1000 loop
for y in 1..10 loop
update test set name=' ' where id=10*(y-1)+p_id;
commit;
end loop;
end loop;
commit;
end;
/
set serveroutput on
exec session_pkg.get_snap;
declare
l_job number;
begin
for x in 1..9 loop
dbms_job.submit(l_job,'do_update('||x||');');
end loop;
commit;
end;
/
exec do_update(10);
exec session_pkg.rpt_stat_event(0);
==>
Session id:116 Serial#:84 Last sampid:8369206
----session stats---
Name Value
redo size 20,845,840
undo change vector size 9,278,428
session logical reads 1,328,212
consistent gets 1,282,449
consistent gets from cache 1,282,449
table scan blocks gotten 1,242,184
no work - consistent read gets 1,231,829
session uga memory 1,176,520
table scan rows gotten 1,030,542
session pga memory 720,896
db block changes 49,015
calls to get snapshot scn: kcm 46,100
db block gets 45,763
db block gets from cache 45,763
recursive calls 41,830
calls to kcmgas 30,967
enqueue releases 29,743
enqueue requests 29,740
redo entries 28,137
free buffer requested 21,084
consistent gets - examination 16,205
consistent changes 12,451
data blocks consistent reads - 11,648
execute count 11,406
table scans (short tables) 11,272
deferred (CURRENT) block clean 10,435
commit cleanouts 10,005
user commits 10,002
switch current to new buffer 9,996
CR blocks created 9,966
commit cleanouts successfully 9,885
messages sent 6,335
rollbacks only - consistent re 6,088
workarea memory allocated 5,990
cleanout - number of ktugct ca 4,490
immediate (CR) block cleanout 4,487
cleanouts and rollbacks - cons 4,133
active txn count during cleano 4,063
DB time 2,845
bytes received via SQL*Net fro 2,562
enqueue conversions 2,177
bytes sent via SQL*Net to clie 1,418
parse count (total) 1,355
session cursor cache hits 1,332
opened cursors cumulative 1,321
CPU used when call started 1,143
CPU used by this session 1,128
recursive cpu usage 1,097
sorts (rows) 1,089
redo ordering marks 957
concurrency wait time 854
free buffer inspected 486
commit txn count during cleano 427
calls to kcmgcs 381
buffer is not pinned count 371
cleanouts only - consistent re 354
enqueue waits 177
commit cleanout failures: cann 116
table fetch by rowid 114
shared hash latch upgrades - n 110
redo log space wait time 102
change write time 82
index scans kdiixs1 67
index fetch by key 36
parse count (hard) 29
steps of tune down ret. in spa 27
space was found by tune down 27
tune down retentions in space 27
drop segment calls in space pr 27
redo synch time 25
user calls 21
cluster key scan block gets 18
cluster key scans 18
table fetch continued row 18
cursor authentications 15
SQL*Net roundtrips to/from cli 11
write clones created in foregr 10
parse time elapsed 9
buffer is pinned count 9
local undo segment hints were 8
parse time cpu 8
redo log space requests 8
shared hash latch upgrades - w 7
redo buffer allocation retries 5
sorts (memory) 3
opened cursors current 3
redo synch writes 3
global undo segment hints help 2
local undo segment hints helpe 2
commit cleanout failures: call 2
commit cleanout failures: bloc 2
heap block compress 2
auto extends on undo tablespac 1
----session events---
Wait_Class Event Total_waits Time_waited
Commit log file sync 4 25
Concurrency latch: library cache pin 1 1
Concurrency latch: cache buffers chains 173 529
Concurrency buffer busy waits 686 324
Configuration log file switch completion 2 1
Configuration log buffer space 2 30
Configuration log file switch (checkpoint in 6 99
Configuration enq: HW - contention 144 168
Idle SQL*Net message from client 11 25
Network SQL*Net message to client 11 0
Other events in waitclass Other 400 201
----v$active_session_history---
Wait_class Event count(*) min_samp max_samp
Concurrency buffer busy waits 5 8369363 8369381
Concurrency latch: cache buffers chains 6 8369368 8369383
Configuration log buffer space 1 8369376 8369376
Configuration log file switch (checkpoint in1 8369384 8369384
Other enq: US - contention 2 8369365 8369386
PL/SQL procedure successfully completed
SQL> SELECT event, p1, p2, p3,count(*)
2 FROM v$active_session_history
3 WHERE sample_id > 8369206
4 AND event IN ('buffer busy waits', 'read by other session')
5 GROUP BY event, p1, p2, p3
6 ORDER BY event, p1, p2, p3;
EVENT P1 P2 P3 COUNT(*)
-------------------- ---------- ---------- ---------- ----------
buffer busy waits 2 2 13 18
buffer busy waits 2 57 23 3
buffer busy waits 2 73 25 3
buffer busy waits 2 105 29 4
buffer busy waits 2 137 33 4
buffer busy waits 2 153 35 2
buffer busy waits 2 729 37 2
buffer busy waits 2 5598 28 1
buffer busy waits 2 6169 32 1
buffer busy waits 2 9313 22 1
buffer busy waits 2 10391 38 3
buffer busy waits 2 12233 39 1
buffer busy waits 2 12733 34 1
buffer busy waits 11 3725 1 2
buffer busy waits 11 3728 1 1
buffer busy waits 11 3729 1 1
buffer busy waits 11 3731 1 1
buffer busy waits 11 3732 1 1
buffer busy waits 11 3733 1 1
buffer busy waits 11 3736 1 2
buffer busy waits 11 3738 1 1
buffer busy waits 11 3740 1 1
buffer busy waits 11 3741 1 1
buffer busy waits 11 3745 1 1
buffer busy waits 11 3752 1 1
buffer busy waits 11 3763 1 1
buffer busy waits 11 3769 1 1
buffer busy waits 11 3780 1 3
buffer busy waits 11 3794 1 2
buffer busy waits 11 3815 1 1
buffer busy waits 11 3825 1 1
buffer busy waits 11 3833 1 2
buffer busy waits 11 3838 1 1
33 rows selected
分析:
*場景5.1:DB Time:19sec,buffer busy waits:756/7.3sec,latch cache buffers chains:95/2sec,enq HW - contention 1/0sec
*場景5.2:DB Time:28.4sec,buffer busy waits:686/3.2sec,latch cache buffers chains:173/5.2sec,enq HW - contention 144/1.7sec
*透過對比可知:buffer busy waits雖然減少,但latch cache buffers chains增加,總的執行時間增加.
*每個行佔用一個資料塊,為什麼還會有buffer busy waits?是因為更新需要對錶全表掃描,讀取與更新衝突,導致資料塊爭用.
5.3 對錶進行分割槽
drop table test;
create table test(id number,name char(700))
partition by list(id)
(
partition p1 values (1,11,21,31,41,51,61,71,81,91),
partition p2 values (2,12,22,32,42,52,62,72,82,92),
partition p3 values (3,13,23,33,43,53,63,73,83,93),
partition p4 values (4,14,24,34,44,54,64,74,84,94),
partition p5 values (5,15,25,35,45,55,65,75,85,95),
partition p6 values (6,16,26,36,46,56,66,76,86,96),
partition p7 values (7,17,27,37,47,57,67,77,87,97),
partition p8 values (8,18,28,38,48,58,68,78,88,98),
partition p9 values (9,19,29,39,49,59,69,79,89,99),
partition p00 values (10,20,30,40,50,60,70,80,90,100),
partition pmax values (default)
)
tablespace assm_tbs;
begin
for x in 1..100 loop
insert into test values(x,' ');
end loop;
commit;
end;
/
SELECT dbms_rowid.rowid_block_number(ROWID) AS block_no, COUNT(*) cnt
FROM test
GROUP BY dbms_rowid.rowid_block_number(ROWID);
SELECT mod(id,10),dbms_rowid.rowid_block_number(ROWID) AS block_no,count(*)
FROM test
GROUP BY mod(id,10),dbms_rowid.rowid_block_number(ROWID)
ORDER BY 1,2;
MOD(ID,10) BLOCK_NO COUNT(*)
---------- ---------- ----------
0 5665 10
1 4513 10
2 4641 10
3 4769 10
4 4897 10
5 5025 10
6 5153 10
7 5281 10
8 5409 10
9 5537 10
10 rows selected
create or replace procedure do_update(p_id in number) is
begin
for x in 1..1000 loop
for y in 1..10 loop
update test set name=' ' where id=10*(y-1)+p_id;
commit;
end loop;
end loop;
commit;
end;
/
set serveroutput on
exec session_pkg.get_snap;
declare
l_job number;
begin
for x in 1..9 loop
dbms_job.submit(l_job,'do_update('||x||');');
end loop;
commit;
end;
/
exec do_update(10);
exec session_pkg.rpt_stat_event(0);
==>
Session id:116 Serial#:84 Last sampid:8380060
----session stats---
Name Value
redo size 20,220,128
undo change vector size 9,949,044
session uga memory 1,176,520
session pga memory 720,896
session logical reads 284,412
consistent gets from cache 220,240
consistent gets 220,240
no work - consistent read gets 163,867
table scan blocks gotten 163,648
table scan rows gotten 154,571
calls to get snapshot scn: kcm 80,251
enqueue releases 66,592
enqueue requests 66,589
db block gets 64,172
db block gets from cache 64,172
recursive calls 51,987
db block changes 42,795
redo entries 22,347
calls to kcmgas 21,012
execute count 12,493
table scans (short tables) 12,368
free buffer requested 10,961
enqueue conversions 10,579
commit cleanouts 10,005
commit cleanouts successfully 10,003
user commits 10,002
switch current to new buffer 10,001
buffer is pinned count 9,009
workarea memory allocated 5,990
deferred (CURRENT) block clean 5,655
messages sent 5,616
bytes received via SQL*Net fro 2,562
parse count (total) 2,441
session cursor cache hits 2,418
opened cursors cumulative 2,408
DB time 1,496
bytes sent via SQL*Net to clie 1,418
sorts (rows) 1,089
free buffer inspected 885
tune down retentions in space 877
steps of tune down ret. in spa 877
drop segment calls in space pr 877
space was found by tune down 877
redo ordering marks 811
enqueue waits 620
CPU used when call started 576
CPU used by this session 558
recursive cpu usage 518
buffer is not pinned count 331
calls to kcmgcs 226
concurrency wait time 154
change write time 141
table fetch by rowid 114
shared hash latch upgrades - n 77
consistent gets - examination 69
index scans kdiixs1 68
index fetch by key 36
redo synch time 31
parse count (hard) 29
user calls 21
cluster key scans 18
cluster key scan block gets 18
table fetch continued row 18
cursor authentications 15
SQL*Net roundtrips to/from cli 11
local undo segment hints were 10
parse time elapsed 8
parse time cpu 7
consistent changes 4
global undo segment hints help 3
global undo segment hints were 3
sorts (memory) 3
opened cursors current 3
redo synch writes 3
commit cleanout failures: bloc 2
heap block compress 2
local undo segment hints helpe 2
redo buffer allocation retries 2
immediate (CR) block cleanout 1
write clones created in foregr 1
cleanouts only - consistent re 1
commit txn count during cleano 1
cleanout - number of ktugct ca 1
----session events---
Wait_Class Event Total_waits Time_waited
Commit log file sync 3 31
Concurrency latch: library cache 1 0
Concurrency latch: row cache objects 2 0
Concurrency latch: cache buffers chains 3 0
Concurrency buffer busy waits 445 154
Configuration undo segment extension 2 0
Configuration log buffer space 2 79
Configuration enq: HW - contention 527 346
Idle SQL*Net message from client 11 17
Network SQL*Net message to client 11 0
Other events in waitclass Other 497 172
----v$active_session_history---
Wait_class Event count(*) min_samp max_samp
Concurrency buffer busy waits 2 8380170 8380171
Configuration enq: HW - contention 3 8380163 8380169
PL/SQL procedure successfully completed
例項級等待:
SELECT event, p1, p2, p3,count(*)
FROM v$active_session_history
WHERE sample_id > 8380060
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 10
buffer busy waits 2 9 17 6
buffer busy waits 2 41 21 1
buffer busy waits 2 57 23 1
buffer busy waits 2 73 25 1
buffer busy waits 2 89 27 1
buffer busy waits 2 105 29 1
buffer busy waits 2 137 33 1
buffer busy waits 2 153 35 4
buffer busy waits 2 729 37 2
buffer busy waits 2 12233 39 1
11 rows selected
分析:
*場景5.1:DB Time:19sec,buffer busy waits:756/7.3sec,latch cache buffers chains:95/2sec,enq HW - contention 1/0sec
*場景5.2:DB Time:28.4sec,buffer busy waits:686/3.2sec,latch cache buffers chains:173/5.2sec,enq HW - contention 144/1.7sec
*場景5.3:DB Time:14.9sec,buffer busy waits:445/1.54sec,latch cache buffers chains:3/0sec,enq HW - contention 527/3.46sec
*透過對比可知:buffer busy waits減少,latch cache buffers chains顯著減少,總的執行時間大幅減少.
*新問題:每個行佔用一個資料塊,為什麼還會有buffer busy waits發生在undo segment header?每個事務只處理特定分割槽,不存在跨會話訪問分割槽的情況,為何導致資料塊爭用?
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/18922393/viewspace-713231/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- 等待事件_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(3)事件AISession
- 【等待事件】ORACLE常見等待事件事件Oracle
- 【等待事件】等待事件系列（5.1）--Enqueue(佇列等待)事件ENQ佇列
- 等待事件事件
- 【TUNE_ORACLE】等待事件之等待事件類別Oracle事件
- 等待事件分析事件
- oracle等待事件Oracle事件
- Oracle 等待事件Oracle事件
- px等待事件事件
- 等待事件 二事件
- 【等待事件】等待事件系列（1）--User I/O型別事件型別
- 【效能調整】等待事件(三) 常見等待事件（一）事件
- 【效能調整】等待事件(四) 常見等待事件（二）事件
- 與IO相關的等待事件troubleshooting-系列4事件
- 基於AWR實現STATSPACK報告(4-等待事件)事件
- Oracle Mutex 等待事件OracleMutex事件
- 等待事件指令碼事件指令碼
- oracle等待事件一Oracle事件
- ASH, AWR , 等待事件事件
- latch free等待事件事件
- 【Oracle概念】-等待事件Oracle事件
- 頂級等待事件：事件
- Oracle 等待事件 一Oracle事件
- Oracle的等待事件Oracle事件
- 常見等待事件事件
- oracle等待事件3構造一個Direct Path write等待事件和構造一個Log File Sync等待事件Oracle事件
- 【等待事件之二】log 相關的等待事件
- Latch free等待事件(轉)事件
- gc cr request等待事件GC事件
- latch等待事件彙總事件
- log file sync等待事件事件
- 【等待事件】log file sync事件
- ORACLE 常見等待事件Oracle事件
- cursor: mutex S等待事件Mutex事件
- latch 相關等待事件事件
- 【等待事件】Buffer Exterminate事件