Oracle Study之--Oracle等待事件(8)

     库缓存中的对象在库缓存中被切割成多个内存块,另有一个对象句柄记录了各个内存块的地址和其他的一些信息。当你要修改句柄中的信息时,需要在句柄上加独占锁,而如果另一个进程恰好在这时要求读、写句柄中的信息,它就必须等待。此时的等待就被Oracle记入Library cache lock事件。而读、写对象内存块也是无法同时进行的,有人如果正在写,你的读操作就必须等待,读写内存块的等待事件就是Library cache pin。如果这两个等待事件过多,同样说明了库缓存过小或没有共享执行计划。或者,当你在数据库繁忙时使用DDL时,也会有这两个等待事件。

Library cache lock
这个等待事件发生在不同用户在共享中由于并发操作同一个数据库对象导致的资源争用的时候,比如当一个用户正在对一个表做DDL 操作时,其他的用户如果要访问这张表,就会发生library cache lock等待事件,它要一直等到DDL操作完成后,才能继续操作。
这个事件包含四个参数:
Handle address: 被加载的对象的地址。
Lock address: 锁的地址。
Mode: 被加载对象的数据片段。
Namespace: 被加载对象在v$db_object_cache 视图中namespace名称。
10gr2 rac:

sys@ORCL> select name from v$event_name where name like 'library%' order by 1;
NAME
--------------------------------------------------
library cache load lock
library cache lock
library cache pin
library cache revalidation
library cache shutdown

Library cache pin
这个等待事件和library cache lock 一样是发生在共享池中并发操作引起的事件。通常来讲,如果Oracle 要对一些PL/SQL 或者视图这样的对象做重新编译,需要将这些对象pin到共享池中。如果此时这个对象被其他的用户特有,就会产生一个library cache pin的等待。
这个等待事件也包含四个参数:
Handle address: 被加载的对象的地址。
Lock address: 锁的地址。
Mode: 被加载对象的数据片段。
Namespace: 被加载对象在v$db_object_cache 视图中namespace名称。

案例分析:

12:03:15 SCOTT@ prod>begin
12:03:38   2    for i in 1..100000 loop
  execute immediate 'insert into t1 values ('||i||')';
12:03:38   3  12:03:38   4    end loop;
12:03:38   5    end;
12:03:39   6    /
11:25:39 TOM@ prod>begin
12:03:43   2    for i in 1..100000 loop
12:03:43   3    execute immediate 'insert into t1 values ('||i||')';
12:03:43   4    end loop;
12:03:43   5    end;
12:03:43   6    /
12:04:33 SYS@ prod>r
  1  select event,TOTAL_WAITS,AVERAGE_WAIT,EVENT_ID from v$system_event
  2* where event like '%lib%'
EVENT                                                            TOTAL_WAITS AVERAGE_WAIT   EVENT_ID
---------------------------------------------------------------- ----------- ------------ ----------
library cache load lock                                                    5         17.8 2952162927
library cache: mutex X                                                   142          .27 1646780882
Elapsed: 00:00:00.03

查询语句:

方法一、只能查询librarycache pin相关信息

SQL> SELECT distinct decode(kglpnreq,0,'holding_session:'||s.sid,'waiting_session: '||s.sid) sid,
2 s.SERIAL#, kglpnmod "Pin Mode", kglpnreq "ReqPin",a.sql_text,kglnaown "Owner", kglnaobj "Object"
3 FROM x$kglpn p, v$session s,v$sqlarea a,v$session_wait sw,x$kglob x
4 WHERE p.kglpnuse=s.saddr
5 AND kglpnhdl=sw.p1raw
6 and kglhdadr=sw.p1raw
7 and event like 'library cache%'
8 and (a.hash_value, a.address) IN (
9 select
10 DECODE (sql_hash_value,
11 0,
12 prev_hash_value,
13 sql_hash_value
14 ),
15 DECODE (sql_hash_value, 0, prev_sql_addr, sql_address)
16 from v$session s2
17 where s2.sid=s.sid
18 )
19 ;

方法二、可以查询library cache pin和library cache lock 的信息

select  Distinct /*+ ordered */ w1.sid waiting_session,
h1.sid holding_session, 
w.kgllktype lock_or_pin, 
od.to_owner object_owner, 
od.to_name object_name, 
oc.Type, 
decode(h.kgllkmod, 0, 'None', 1, 'Null', 2, 'Share', 3, 'Exclusive', 
'Unknown') mode_held, 
decode(w.kgllkreq, 0, 'None', 1, 'Null', 2, 'Share', 3, 'Exclusive', 
'Unknown') mode_requested,
xw.KGLNAOBJ wait_sql,xh.KGLNAOBJ hold_sql 
from dba_kgllock w, dba_kgllock h, v$session w1, 
v$session h1,v$object_dependency od,V$DB_OBJECT_CACHE oc,x$kgllk xw,x$kgllk xh
where 
(((h.kgllkmod != 0) and (h.kgllkmod != 1) 
and ((h.kgllkreq = 0) or (h.kgllkreq = 1))) 
and 
(((w.kgllkmod = 0) or (w.kgllkmod= 1)) 
and ((w.kgllkreq != 0) and (w.kgllkreq != 1)))) 
and w.kgllktype = h.kgllktype 
and w.kgllkhdl = h.kgllkhdl 
and w.kgllkuse = w1.saddr 
and h.kgllkuse = h1.saddr 
And od.to_address = w.kgllkhdl 
And od.to_name=oc.Name 
And od.to_owner=oc.owner 
And w1.sid=xw.KGLLKSNM
And h1.sid=xh.KGLLKSNM 
And (w1.SQL_ADDRESS=xw.KGLHDPAR And w1.SQL_HASH_VALUE=xw.KGLNAHSH)
And (h1.SQL_ADDRESS=xh.KGLHDPAR And h1.SQL_HASH_VALUE=xh.KGLNAHSH) 
;

附注:

生产环境案例分析:(转自:http://www.itpub.net/thread-1504538-1-1.html)

 今天接到同事的电话,说他的一个存储过程已经run了一个多小时了,还在继续run,他觉得极不正常,按道理说不应该run这么长时间。

我说那我去看一下吧。

这个库是一个AIX上的10.2.0.4,我采集了一下问题时间段的AWR报告:


Begin Snap:



13302



11-Jun-10 12:00:56



109



4.7



End Snap:



13303



11-Jun-10 13:00:02



97



4.9



Elapsed:




59.10 (mins)





DB Time:




113.98 (mins)




Top 5事件为:


Event



Waits



Time(s)



Avg Wait(ms)



% Total Call Time



Wait Class



library cache pin



1,252



3,656



2,920



53.5



Concurrency



library cache lock



989



2,890



2,922



42.3



Concurrency



CPU time




219




3.2




db file sequential read



5,694



12



2



.2



User I/O



log file parallel write



1,467



11



8



.2



System I/O


从AWR报告结果里我们可以看出在出问题的时间段,系统在经历严重的library cache pin以及library cache lock等待。

从Load Profile中我们又可以看到:



Per Second



Per Transaction



Parses:



12.83



65.83



Hard parses:



0.05



0.25


也就是说导致上述library cache pin和library cache lock的并不是hard parse

对于library cache pin等待来说,AWR报告的作用有限,最有效的方式就是找到持有library cache pin以及等待library cache pin的session,然后看看他们在做什么


SQL> SELECT s.sid, kglpnmod "Mode", kglpnreq "Req", SPID "OS Process"

  2  FROM v$session_wait w, x$kglpn p, v$session s ,v$process o

  3  WHERE p.kglpnuse=s.saddr

  4  AND kglpnhdl=w.p1raw

  5  and w.event like '%library cache pin%'

  6  and s.paddr=o.addr

  7  /

       SID       Mode        Req OS Process

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

       396          0          2 6381970

       396          0          2 6381970

       396          0          2 6381970

       396          0          2 6381970

       341          2          0 4092132

       341          2          0 4092132

       341          2          0 4092132

       341          2          0 4092132

       363          0          2 3514690

       363          0          2 3514690

       363          0          2 3514690

       363          0          2 3514690

       304          0          2 3977478

       304          0          2 3977478

       304          0          2 3977478

       304          0          2 3977478

       354          0          3 3137874

       354          0          3 3137874

       354          0          3 3137874

       354          0          3 3137874

20 rows selected

我那位run存储过程的同事所在的session是396,从上述结果里我们可以看出来396现在想以Share模式(即Req=2)去持有library cache pin,同时现在持有上述library cache pin的是session 341,且341的持有模式也是Share(即Mode=2)。

本来Share和Share是可以共享的,但不幸的是在396之前,session 354想以Exclusive模式(即Req=3)去持有上述library cache pin,这直接导致了396需要处于等待的Queue中,同时处于Queue中的还有363和304。

我为什么这么说呢,因为oracle对library cache pin的解释中有一句非常经典的话:

An X request (3) will be blocked by any pins held S mode (2) on the object.
An S request (2) will be blocked by any X mode (3) pin held, or may queue behind some other X request.

所以从AWR报告和上述查询结果中我们可以得出如下结论:

1、  我那位run存储过程的同事为什么run了1个多小时还没有run完是因为这个存储过程正在经历严重的library cache pin等待;

2、  而为什么会导致严重的library cache pin等待是因为session 341和354联手达到了这一效果,即341以Share模式持有library cache pin,接着354想以Exclusive模式持有,这直接导致所有的后续请求全部被处于等待的Queue中。也就是说341阻塞了354,而354又间接阻塞了396

既然知道了原因,那我们去看一下session 341在做什么事情:

SQL> select decode(sql_hash_value,0,prev_hash_value,sql_hash_value) from v$session where sid=341;

DECODE(SQL_HASH_VALUE,0,PREV_H

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

                     784727971

间隔10秒钟后再次执行:

SQL> select decode(sql_hash_value,0,prev_hash_value,sql_hash_value) from v$session where sid=341;

DECODE(SQL_HASH_VALUE,0,PREV_H

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

                     784727971

间隔10秒钟后再次执行:

SQL> select decode(sql_hash_value,0,prev_hash_value,sql_hash_value) from v$session where sid=341;

DECODE(SQL_HASH_VALUE,0,PREV_H

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

                     784727971

SQL> select sql_text from v$sqltext where hash_value=784727971 order by piece;

SQL_TEXT

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

begin   -- Call the procedure   p_adj_rrp_main(o_vc_flag => Oracle Study之--Oracle等待事件(8)_Oracle_vc_flag); end;

从结果里可以看到341一直在run一个存储过程。

给持有341的那位大姐打电话,问她在做什么,她告诉我说她从昨晚就开始run这个存储过程,今早来看发现死掉了,所以她就没管了。

知道原因后处理起来还是很容易的,当我把session 341干掉后,整个系统的library cache pin一下子就降下来了,接着我那位同事的run了一个多小时的存储过程过了没多久就run完了。