ITPub博客

首页 > Linux操作系统 > Linux操作系统 > 等待事件_buffer_busy_waits_and_read_by_other_session(4)

等待事件_buffer_busy_waits_and_read_by_other_session(4)

原创 Linux操作系统 作者:redhouser 时间:2011-12-13 14:17:52 0 删除 编辑


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/,如需转载,请注明出处,否则将追究法律责任。

下一篇: simulator的功能
请登录后发表评论 登录
全部评论

注册时间:2011-05-26

  • 博文量
    211
  • 访问量
    790651