ITPub博客

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

等待事件_buffer_busy_waits_and_read_by_other_session(3)

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


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

请登录后发表评论 登录
全部评论

注册时间:2011-05-26

  • 博文量
    211
  • 访问量
    790965