latch: cache buffers chains

latch等待的描述：
如果一个需求的latch正忙，进程请求，spin，再重试，如果仍然不可用，再spin。这个循
环重复次数使用初始化参数_SPIN_COUNT决定的。如果整个循环后，latch还是不可用，进程
必须让出cpu占有权并进入睡眠期。开始是睡眠百分之一秒。这个时间在后续的睡眠将加倍
这将导致变慢发生，结果是cpu使用率的增加。CPU的使用率是进程spinning的后果。Spinning
意味着一个进程在固定的时间后继续查找可用的latch。

下面是从asktom网站上修改的latch的获取伪码
Loop
    for I in 1 .. 2000
    loop
        try to get latch
        if got latch, then spin_gets=spin_gets+1, return
        if I = 1 then misses=misses+1
    end loop
    INCREMENT WAIT COUNT
    sleep = sleep + 1
    Add WAIT TIME
End loop;
/

下面演示如何找出cache buffers chains的latch，并解决：

SQL> select count(*) from  v$latch_children where name='cache buffers chains'  ;

  COUNT(*)
----------
      1024

创建表t2，one row占用一个块。并创建4096条记录。
create table t2 (id number, name char(2000), name1 char(2000), name2 char(2000), name3 char(1000));

insert into t2 select object_id, object_name, object_name, object_name, object_name from dba_objects where rownum < 4096;
commit;

create index t2_ix on t2 (id);

每访问t2的记录，就要读一次块，就要获取一个latch。这样t2表占用了2029个latch。

SQL>
SQL> select count(distinct hladdr) cnt from x$bh
  2  where bj = 78577
  3  /
 
       CNT
----------
      2029
 
SQL>

创建T1表，这样尽可能多地访问t2表：

create table t1 (n1 number);

insert into t1 select rownum from dba_objects aa, dba_objects bb where rownum <= 1000000;
commit;

启动session运行测试语句，并打开10046 trace，session的个数和cpu个数相同：
select
    /*+ ordered full(t1) use_nl(t2) index(t2) */
    max(t2.name)
from
    t1, t2
where
    t2.id > t1.n1
;

buffer cache的dump文件：

ALTER SESSION SET EVENTS 'immediate trace name buffers level 1';

BH (0x25bc649c) file#: 1 rdba: 0x004163da (1/91098) class: 1 ba: 0x2584a000
  set: 5 pool: 3 bsz: 8192 bsi: 0 sflg: 1 pwc: 0,25
  dbwrid: 0 obj: 78577 objn: 78577 tsn: 0 afn: 1 hint: f

从10046 event trace文件，这里四个sessions同时运行，一个session在读block，其他的session在
等待事件"read by other session".

session 1:
WAIT #4250920: nam='db file sequential read' ela= 1835 file#=1 block#=92857 blocks=1 obj#=78577 tim=1309764775061085

session 2,3,4
WAIT #130952688: nam='read by other session' ela= 1505 file#=1 block#=92857 class#=1 obj#=78577 tim=1309764775061879

从x$bh获取latch的address
SQL> select hladdr from x$bh where file#=1 and dbablk = 92857;
 
HLADDR
--------
333C9008

这个latch上关联的object
SQL> select  obj,file#, dbablk from x$bh where hladdr = '333C9008';
 
       OBJ      FILE#     DBABLK
---------- ---------- ----------
     78577          1      92857
         2          1      53582
      5799          2      61326
       495          1      58153
     78577          1      93090
      5798          2      70235
        18          1      53815
       227          1      18878
        40          1      45139
4294967295          3       3767
       226          1       1526
     78577          1      93323

SQL> select to_number('333C9008', 'xxxxxxxxxxxx') from dual;
 
TO_NUMBER('333C9008','XXXXXXXX
------------------------------
                     859607048

10046文件中latch地址859607048的等待时间

dbs101_ora_7388.trc:
*** 2011-07-04 15:37:47.062
WAIT #130952688: nam='latch: cache buffers chains' ela= 145 address=859607048 number=155 tries=0 obj#=78578 tim=1309765067100689

dbs101_ora_7392.trc
*** 2011-07-04 15:33:01.528
WAIT #9030904: nam='latch: cache buffers chains' ela= 19951 address=859607048 number=155 tries=0 obj#=78577 tim=1309764781528588
*** 2011-07-04 15:36:51.231
WAIT #9030904: nam='latch: cache buffers chains' ela= 51106 address=859607048 number=155 tries=0 obj#=78577 tim=1309765011231417

从视图v$latch_children获取的等待时间
select addr,name,gets,misses,sleeps,spin_gets,wait_time from v$latch_children where addr = '333C9008';
SQL> select addr,name,gets,misses,sleeps,spin_gets,wait_time from v$latch_children where addr = '333C9008';
 
ADDR     NAME                                                                   GETS     MISSES     SLEEPS  SPIN_GETS WAIT_TIME
-------- ---------------------------------------------------------------- ---------- ---------- ---------- ---------- ----------
333C9008 cache buffers chains                                                 193532         12          3          9      71202

10046trace文件和视图v$latch_children的等待时间是一致的：

145 (elapsed time from dbs101_ora_7388.trc) + 19951 (from dbs101_ora_7392.trc) + 51106 (from dbs101_ora_7392.trc) = 71202 (from v$latch_children)

找出misses最多的latch：

select * from (
select addr, gets, misses, sleeps, spin_gets, wait_time from  v$latch_children  where name = 'cache buffers chains'
--and misses > 100
order by misses desc
) where rownum < 10;

The maximum misses:
SQL>
SQL> select * from (
  2  select addr, gets, misses, sleeps, spin_gets, wait_time from  v$latch_children  where name = 'cache buffers chains'
  3  --and misses > 100
  4  order by misses desc
  5  ) where rownum < 10;
 
ADDR           GETS     MISSES     SLEEPS  SPIN_GETS  WAIT_TIME
-------- ---------- ---------- ---------- ---------- ----------
3244BB94     203150         31         12         20     842841
333DBB54     183999         30          0         30          0
32FDA9B8     191245         25          8         17     428451
3245F9C8     197388         23          6         17     476217
32FE1FFC     188990         23          6         17     421296
3243546C     213260         23          5         19     306787
3245B478     182297         22          2         20     209660
333EC018     218019         22          7         15     496826
32FD9100     216307         22          5         17     425692
 
9 rows selected
 
SQL>

SQL> select to_number('3244BB94', 'xxxxxxxxxx') from dual;
 
TO_NUMBER('3244BB94','XXXXXXXX
------------------------------
                     843365268

from dbs101_ora_7388.trc:
WAIT #130952688: nam='latch: cache buffers chains' ela= 1366 address=843365268 number=155 tries=0 obj#=78577 tim=1309764779683875
*** 2011-07-04 15:34:06.915
WAIT #130952688: nam='latch: cache buffers chains' ela= 101953 address=843365268 number=155 tries=0 obj#=78577 tim=1309764847017969
*** 2011-07-04 15:36:06.580
WAIT #130952688: nam='latch: cache buffers chains' ela= 104435 address=843365268 number=155 tries=0 obj#=78578 tim=1309764966580359

from dbs101_ora_7390.trc:
WAIT #4250920: nam='latch: cache buffers chains' ela= 21 address=843365268 number=155 tries=0 obj#=78577 tim=1309764779682830
*** 2011-07-04 15:38:14.083
WAIT #4250920: nam='latch: cache buffers chains' ela= 61799 address=843365268 number=155 tries=0 obj#=78577 tim=1309765094399634

from dbs101_ora_7426.trc:
*** 2011-07-04 15:34:07.059
WAIT #3263736: nam='latch: cache buffers chains' ela= 108072 address=843365268 number=155 tries=0 obj#=78577 tim=1309764847059566
*** 2011-07-04 15:36:06.580
WAIT #3263736: nam='latch: cache buffers chains' ela= 138956 address=843365268 number=155 tries=0 obj#=78577 tim=1309764966580044
*** 2011-07-04 15:38:10.304
WAIT #3263736: nam='latch: cache buffers chains' ela= 102981 address=843365268 number=155 tries=0 obj#=78577 tim=1309765090304646
*** 2011-07-04 15:38:14.346
WAIT #3263736: nam='latch: cache buffers chains' ela= 9636 address=843365268 number=155 tries=0 obj#=78577 tim=1309765094346043
*** 2011-07-04 15:38:30.179
WAIT #3263736: nam='latch: cache buffers chains' ela= 112570 address=843365268 number=155 tries=0 obj#=78577 tim=1309765110654012

from dbs101_ora_7392.trc:
*** 2011-07-04 15:38:13.905
WAIT #9030904: nam='latch: cache buffers chains' ela= 101052 address=843365268 number=155 tries=0 obj#=78577 tim=1309765094440969

如果从系统运行找出最高cpu的session 12125：

select sid,serial#,event,sql_id from v$session where paddr in (select addr from v$process where spid = 12125);

SQL> select sid,serial#,event,sql_id from v$session where paddr in (select addr from v$process where spid = 12125);
 
       SID    SERIAL# EVENT                                                            SQL_ID
---------- ---------- ---------------------------------------------------------------- -------------
       152         17 latch: cache buffers chains                                      f3j8cdu341xmb
 
SQL>

SQL> select buffer_gets,executions,elapsed_time from v$sqlarea where sql_id = 'f3j8cdu341xmb';
 
BUFFER_GETS EXECUTIONS ELAPSED_TIME
----------- ---------- ------------
   15130998          4    928305827
 
SQL>

SQL> @getplan.sql
 
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
SQL_ID  f3j8cdu341xmb, child number 0
-------------------------------------
select     /*+ ordered full(t1) use_nl(t2) index(t2) */
max(t2.name) from     t1, t2 where     t2.id > t1.n1
Plan hash value: 2951347925
--------------------------------------------------------------------------------
| Id  | Operation                     | Name  | Rows  | Bytes | Cost (%CPU)| Tim
--------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |       |       |       |    10M(100)|
|   1 |  SORT AGGREGATE               |       |     1 |  2010 |            |
|   2 |   NESTED LOOPS                |       |       |       |            |
|   3 |    NESTED LOOPS               |       |  8550K|    16G|    10M  (1)| 33:
|   4 |     TABLE ACCESS FULL         | T1    |  1000K|  4882K|   420   (2)| 00:
|*  5 |     INDEX RANGE SCAN          | T2_IX |     9 |       |     1   (0)| 00:
|   6 |    TABLE ACCESS BY INDEX ROWID| T2    |     9 | 18045 |    10   (0)| 00:
--------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
 
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
-------------------------------------------------------------
   1 - SEL$1
   4 - SEL$1 / T1@SEL$1
   5 - SEL$1 / Column Projection Information (identified by operation id):
-----------------------------------------------------------
   1 - (#keys=0) MAX("T2"."NAME")[2000]
   2 - "T2"."NAME"[CHARACTER,2000]
   3 - "T2".ROWID[ROWID,10]
   4 - "T1"."N1"[NUMBER,22]
   5 - "T2".ROWID[ROWID,10]
   6 - "T2"."NAME"[CHARACTER,2000]
 
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
 
42 rows selected
 
SQL>

FROM AWR report:

Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU                                              958          42.6
latch: cache buffers chains           2,943         265     90   11.8 Concurrenc
read by other session                10,874          73      7    3.2 User I/O
db file sequential read               5,247          42      8    1.9 User I/O
db file scattered read                  220           2     11     .1 User I/O

                                           Pct    Avg   Wait                 Pct
                                    Get    Get   Slps   Time       NoWait NoWait
Latch Name                     Requests   Miss  /Miss    (s)     Requests   Miss
------------------------ -------------- ------ ------ ------ ------------ ------
cache buffers chains         69,609,301    0.0    0.3    265       11,791    0.0

Latch Sleep Breakdown                 DB/Inst: DBS10/dbs101  Snaps: 1148-1149
-> ordered by misses desc

                                       Get                                 Spin
Latch Name                        Requests       Misses      Sleeps        Gets
-------------------------- --------------- ------------ ----------- -----------
cache buffers chains            69,609,301       10,904       3,036       7,960

Latch Miss Sources                    DB/Inst: DBS10/dbs101  Snaps: 1148-1149
-> only latches with sleeps are shown
-> ordered by name, sleeps desc

                                                     NoWait              Waiter
Latch Name               Where                       Misses     Sleeps   Sleeps
------------------------ -------------------------- ------- ---------- --------
cache buffers chains     kcbgtcr: fast path (cr pin       0      2,570    1,164
cache buffers chains     kcbrls_1                         0        414    1,780
cache buffers chains     kcbzwb                           0        183       81
cache buffers chains     kclcls_3                         0         15        5
cache buffers chains     kcbrls_2                         0         12      145
cache buffers chains     kcbzib: finish processing        0          6       29
cache buffers chains     kcbgtcr: kslbegin excl           0          2       18

Segments by Logical Reads             DB/Inst: DBS10/dbs101  Snaps: 1148-1149
-> Total Logical Reads:      34,795,093
-> Captured Segments account for   99.9% of Total

           Tablespace                      Subobject  Obj.       Logical
Owner         Name    Object Name            Name     Type         Reads  %Total
---------- ---------- -------------------- ---------- ----- ------------ -------
SYS        SYSTEM     T2                              TABLE   34,640,976   99.56
SYS        SYSTEM     T2_IX                           INDEX       71,984     .21
SYS        SYSTEM     I_HH_OBJ#_INTCOL#               INDEX        8,064     .02
SYS        SYSTEM     T1                              TABLE        6,080     .02
SYS        SYSTEM     I_CCOL1                         INDEX        3,888     .01

FROM ASH Report:

Top User Events                 DB/Inst: DBS10/dbs101  (Jul 04 20:15 to 20:24)

                                                               Avg Active
Event                               Event Class        % Event   Sessions
----------------------------------- --------------- ---------- ----------
CPU + Wait for CPU                  CPU                  79.07       2.99
latch: cache buffers chains         Concurrency          11.03       0.42
read by other session               User I/O              3.77       0.14
db file sequential read             User I/O              2.45       0.09
          -------------------------------------------------------------

Top Event P1/P2/P3 Values       DB/Inst: DBS10/dbs101  (Jul 04 20:15 to 20:24)

Event                          % Event  P1 Value, P2 Value, P3 Value % Activity
------------------------------ ------- ----------------------------- ----------
Parameter 1                Parameter 2                Parameter 3
-------------------------- -------------------------- --------------------------
latch: cache buffers chains      11.03         "843368308","155","0"       0.25
address                    number                     tries

read by other session             3.77               "1","91203","1"       0.15
file#                      block#                     class#

db file sequential read           2.50                 "1","569","1"       0.05
file#                      block#                     blocks

          -------------------------------------------------------------

Top SQL with Top Events        DB/Inst: DBS10/dbs101  (Jul 04 20:15 to 20:24)

                                                        Sampled #
                 SQL ID             Planhash        of Executions     % Activity
----------------------- -------------------- -------------------- --------------
Event                          % Event Top Row Source                    % RwSrc
------------------------------ ------- --------------------------------- -------
          f3j8cdu341xmb           2951347925                    4          87.94
CPU + Wait for CPU               72.30 NESTED LOOPS                        33.82
select /*+ ordered full(t1) use_nl(t2) index(t2) */ max(t2.name) from
 t1, t2 where t2.id > t1.n1

latch: cache buffers chains      10.25 TABLE ACCESS - BY INDEX ROWID       10.15

read by other session             3.77 TABLE ACCESS - BY INDEX ROWID        3.77

          -------------------------------------------------------------

dump latch的内容：
oradebug setmypid
oradebug dump latches 2
oradebug tracefile_name

ALTER SESSION SET EVENTS 'immediate trace name latches level 2';

dump trace 文件内容：
 32437904 Child cache buffers chains level=1 child#=1308
        Location from where latch is held: kcb2.h LINE:3322 ID:kcbrls_1:
        Context saved from call: 0
        state=free wlstate=free [value=0]
    gotten 571545 times wait, failed first 167 sleeps 39
    gotten 497 times nowait, failed: 0

 32437904 Child cache buffers chains level=1 child#=1308
        Location from where latch is held: kcb2.h LINE:3256 ID:kcbxbh:
        Context saved from call: 0
        state=free wlstate=free [value=0]
    gotten 659873 times wait, failed first 236 sleeps 53
    gotten 497 times nowait, failed: 0

SQL> select * from (
  2  select addr, gets, misses, sleeps, spin_gets, wait_time from  v$latch_children  where name = 'cache buffers chains'
  3  --and misses > 100
  4  order by misses desc
  5  ) where rownum < 10;
 
ADDR           GETS     MISSES     SLEEPS  SPIN_GETS  WAIT_TIME
-------- ---------- ---------- ---------- ---------- ----------
333DBB54     770504        270          2        268      15911
32437904     660033        236         53        183    3351953
3245B478     663000        215         41        174    1551391
3243546C     694367        208         34        176    1867519
333EC018     687213        207         52        156    3520162
3244BB94     675679        195         51        145    3037190
3245F9C8     674994        185         41        144    2370118
32461E60     642850        182         42        141    2203799
3244C774     643535        178         51        128    4173747

视图中的数据基本和dump trace文件中的相同：

    gotten 659873 times wait, failed first 236 sleeps 53
GETS 660033 times, misses 236, sleeps 53, spin_gets 183

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/25105315/viewspace-701403/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/25105315/viewspace-701403/