sitemap

RSS地图

收藏本站

设为首页

Oracle研究中心

当前位置:Oracle研究中心 > 运维DBA > Oracle等待事件 >

【案例】Oracle等待事件library cache lock产生原因和解决办法

时间:2016-12-07 18:56   来源:Oracle研究中心   作者:网络   点击:

天萃荷净 Oracle研究中心案例分析:运维DBA发现Oracle数据库出现library cache lock等待事件导致cpu使用非常高,结合案例来解决此等待事件。

本站文章除注明转载外,均为本站原创: 转载自love wife & love life —Roger 的Oracle技术博客
本文链接地址: soft parse 和 library cache lock

同事遇到一个library cache lock lath等待事件的问题,导致cpu使用非常高,关于library cache lock似乎存在一点争议,我这里用实验来进行说明。

---session 1

SQL> oradebug setmypid
Statement processed.‘

SQL> SELECT ADDR,latch#,LEVEL#,name  FROM V$latch WHERE name LIKE '%library cache%';

ADDR         LATCH#     LEVEL# NAME
-------- ---------- ---------- --------------------------------------------------
200107DC        217          5 library cache
20010840        218          6 library cache LOCK
200109D0        222          5 library cache LOAD LOCK
20010908        220          3 library cache pin allocation
20010A34        223          9 library cache hash chains
2001096C        221          3 library cache LOCK allocation
200108A4        219          6 library cache pin

7 ROWS selected.

SQL> oradebug peek 0x20010840 200

[20010840, 20010908) = 00000000 00000000 000000DA 00000006 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 ...

SQL>  oradebug peek 0x200108A4 200
[200108A4, 2001096C) = 00000000 00000000 000000DB 00000006 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 ...

SQL> SELECT 'oradebug poke 0x' || addr || ' 4 0x00000001' FROM v$latch_children WHERE name='library cache lock';

'ORADEBUGPOKE0X'||ADDR||'40X00000001'
-------------------------------------
oradebug poke 0x287C75F8 4 0x00000001

SQL> SELECT 'oradebug poke 0x' || addr || ' 4 0x00000001' FROM v$latch_children WHERE name='library cache pin';

'ORADEBUGPOKE0X'||ADDR||'40X00000001'
-------------------------------------
oradebug poke 0x287C7594 4 0x00000001

SQL> oradebug poke 0x287C75F8 4 1
BEFORE: [287C75F8, 287C75FC) = 00000000
AFTER:  [287C75F8, 287C75FC) = 00000001

SQL> oradebug poke 0x287C7594 4 1
BEFORE: [287C7594, 287C7598) = 00000000
AFTER:  [287C7594, 287C7598) = 00000001

---session 2

SQL> SHOW USER
USER IS "ROGER"

SQL> ALTER system FLUSH shared_pool;
System altered.

SQL> SELECT * FROM roger WHERE id=100 AND rownum < 3;

----hang住

---session 3

SQL> SHOW USER
USER IS "SYS"

SQL>  SELECT s.sid,s.serial#,p.spid FROM v$process p,v$session s WHERE p.addr=s.paddr AND
  2  s.username='ROGER';

       SID    SERIAL# SPID
---------- ---------- ------------
       145          4 11649

SQL>  oradebug setospid 11649
Oracle pid: 21, Unix process pid: 11649, image: oracle@oracleplus.net (TNS V1-V3)

SQL>  oradebug dump processstate 8
Statement processed.

SQL> oradebug tracefile_name
/home/ora10g/admin/roger/udump/roger_ora_11649.trc

trace如下:
Process global information:
     process: 0x29e2ffec, call: 0x29f48a90, xact: (nil), curses: 0x29f18e94, usrses: 0x29f18e94
  ----------------------------------------
  SO: 0x29e2ffec, type: 2, owner: (nil), flag: INIT/-/-/0x00
  (process) Oracle pid=21, calls cur/top: 0x29f48a90/0x29f48a90, flag: (0) -
            int error: 0, call error: 0, sess error: 0, txn error 0
  (post info) last post received: 110 0 4
              last post received-location: kslpsr
              last process to post me: 29e2a970 1 6
              last post sent: 0 0 24
              last post sent-location: ksasnd
              last process posted by me: 29e2a970 1 6
    (latch info) wait_event=0 bits=0
        Location from where call was made: kgllkdl: child: cleanup: latch
      waiting for 287c75f8 Child library cache lock level=6 child#=1
        Location from where latch is held: No latch:
        Context saved from call: 0
        state=busy, wlstate=free
          waiters [orapid (seconds since: put on list, posted, alive check)]:
           10 (15, 1341052397, 15)
           21 (6, 1341052397, 6)
           11 (3, 1341052397, 3)
           waiter count=3
          gotten 53797 times wait, failed first 14 sleeps 16
          gotten 0 times nowait, failed: 0
      on wait list for 287c75f8

可以看到在等待library cache lock latch。

---session 1

释放library cache LOCK latch

SQL> oradebug poke 0x287C75F8 4 0
BEFORE: [287C75F8, 287C75FC) = 000000FF
AFTER:  [287C75F8, 287C75FC) = 00000000

---session 3

SQL> oradebug setospid 11649
Oracle pid: 21, Unix process pid: 11649, image: oracle@oracleplus.net (TNS V1-V3)

SQL> oradebug dump processstate 8
Statement processed.

SQL> oradebug tracefile_name
/home/ora10g/admin/roger/udump/roger_ora_11649.trc

trace如下:
Process global information:
     process: 0x29e2ffec, call: 0x29f48a90, xact: (nil), curses: 0x29f18e94, usrses: 0x29f18e94
  ----------------------------------------
  SO: 0x29e2ffec, type: 2, owner: (nil), flag: INIT/-/-/0x00
  (process) Oracle pid=21, calls cur/top: 0x29f48a90/0x29f48a90, flag: (0) -
            int error: 0, call error: 0, sess error: 0, txn error 0
  (post info) last post received: 110 0 4
              last post received-location: kslpsr
              last process to post me: 29e2a970 1 6
              last post sent: 0 0 24
              last post sent-location: ksasnd
              last process posted by me: 29e2a970 1 6
    (latch info) wait_event=0 bits=0
        Location from where call was made: kglpnal: child: alloc space: latch
      waiting for 287c7594 Child library cache pin level=6 child#=1
        Location from where latch is held: kglpndl: child
        Context saved from call: 0
        state=busy, wlstate=free
          waiters [orapid (seconds since: put on list, posted, alive check)]:
           10 (24, 1341052547, 24)
           21 (24, 1341052547, 24)
           11 (24, 1341052547, 24)
           12 (24, 1341052547, 24)
           waiter count=4
          gotten 14922 times wait, failed first 11 sleeps 12
          gotten 0 times nowait, failed: 0
      on wait list for 287c7594

可以看到在等待library cache pin latch。

---session 1

释放library cache pin latch

SQL>  oradebug poke 0x287C7594 4 0
BEFORE: [287C7594, 287C7598) = 000000FF
AFTER:  [287C7594, 287C7598) = 00000000

----session 2

SQL> select * from roger where id=100 and rownum < 3;

        ID
----------
       100
       100

 ---这里原本是hang住的,当释放latch以后,执行完成下面再次执行该sql,来看看软解析的情况是怎么样的?

-----session 1

SQL>  oradebug poke 0x287C75F8 4 1
BEFORE: [287C75F8, 287C75FC) = 00000000
AFTER:  [287C75F8, 287C75FC) = 00000001

SQL> oradebug poke 0x287C7594 4 1
BEFORE: [287C7594, 287C7598) = 00000000
AFTER:  [287C7594, 287C7598) = 00000001

----session 2

SQL> SELECT * FROM roger WHERE id=100 AND rownum < 3;
---再次hang住

-----session3

[root@oracleplus~]# cat /home/ora10g/admin/roger/udump/roger_ora_11649.trc | grep "library cache"
      waiting for 287c75f8 Child library cache lock level=6 child#=1
    waiting for 'latch: library cache lock' wait_time=0, seconds since wait started=6
        waited for 'latch: library cache lock', seq_num: 30
      longest_non_idle_wait: 'latch: library cache lock'
      waiting for 287c7594 Child library cache pin level=6 child#=1
    waiting for 'latch: library cache pin' wait_time=0, seconds since wait started=24
     for 'latch: library cache lock' count=1 wait_time=2 min 0 sec
     for 'latch: library cache lock' count=1 wait_time=5.177851 sec
     for 'latch: library cache lock' count=1 wait_time=5.917101 sec
        waited for 'latch: library cache lock', seq_num: 32
      longest_non_idle_wait: 'latch: library cache lock'
      waiting for 287c75f8 Child library cache lock level=6 child#=1
    waiting for 'latch: library cache lock' wait_time=0, seconds since wait started=24
     for 'latch: library cache pin' count=1 wait_time=2 min 8 sec
     for 'latch: library cache pin' count=1 wait_time=3.237725 sec
     for 'latch: library cache pin' count=1 wait_time=23.357272 sec
     for 'latch: library cache lock' count=1 wait_time=2 min 0 sec
     for 'latch: library cache lock' count=1 wait_time=5.177851 sec
     for 'latch: library cache lock' count=1 wait_time=5.917101 sec

可以看到,软解析仍然会申请library cache lock latch.

----session 1

SQL> oradebug poke 0x287C75F8 4 0
BEFORE: [287C75F8, 287C75FC) = 000000FF
AFTER:  [287C75F8, 287C75FC) = 00000000

----session 3
SQL> oradebug dump processstate 8
Statement processed.

trace内容如下:
[root@oracleplus~]#  cat /home/ora10g/admin/roger/udump/roger_ora_11649.trc|grep "library cache"
      waiting for 287c75f8 Child library cache lock level=6 child#=1
    waiting for 'latch: library cache lock' wait_time=0, seconds since wait started=6
        waited for 'latch: library cache lock', seq_num: 30
      longest_non_idle_wait: 'latch: library cache lock'
      waiting for 287c7594 Child library cache pin level=6 child#=1
    waiting for 'latch: library cache pin' wait_time=0, seconds since wait started=24
     for 'latch: library cache lock' count=1 wait_time=2 min 0 sec
     for 'latch: library cache lock' count=1 wait_time=5.177851 sec
     for 'latch: library cache lock' count=1 wait_time=5.917101 sec
        waited for 'latch: library cache lock', seq_num: 32
      longest_non_idle_wait: 'latch: library cache lock'
      waiting for 287c75f8 Child library cache lock level=6 child#=1
    waiting for 'latch: library cache lock' wait_time=0, seconds since wait started=24
     for 'latch: library cache pin' count=1 wait_time=2 min 8 sec
     for 'latch: library cache pin' count=1 wait_time=3.237725 sec
     for 'latch: library cache pin' count=1 wait_time=23.357272 sec
     for 'latch: library cache lock' count=1 wait_time=2 min 0 sec
     for 'latch: library cache lock' count=1 wait_time=5.177851 sec
     for 'latch: library cache lock' count=1 wait_time=5.917101 sec
      waiting for 287c7594 Child library cache pin level=6 child#=1
    waiting for 'latch: library cache pin' wait_time=0, seconds since wait started=3427
     for 'latch: library cache lock' count=1 wait_time=38 min 23 sec
     for 'latch: library cache lock' count=1 wait_time=23.913215 sec
     for 'latch: library cache pin' count=1 wait_time=2 min 8 sec
     for 'latch: library cache pin' count=1 wait_time=3.237725 sec
     for 'latch: library cache pin' count=1 wait_time=23.357272 sec
     for 'latch: library cache lock' count=1 wait_time=2 min 0 sec

手工释放library cache lock latch以后,发现还好等待library cache pin latch。

下面继续来证明软解析获得library cache lock是什么模式呢?

---session 1

[ora10g@oracleplus~]$ sqlplus roger/roger

SQL*Plus: Release 10.2.0.5.0 - Production ON Fri Jun 29 22:32:53 2012
Copyright (c) 1982, 2010, Oracle.  ALL Rights Reserved.
Connected TO:
Oracle DATABASE 10g Enterprise Edition Release 10.2.0.5.0 - Production
WITH the Partitioning, OLAP, DATA Mining AND REAL Application Testing options

SQL> DROP TABLE killdb;
TABLE dropped.

SQL> CREATE TABLE oracleplusAS SELECT object_id FROM dba_objects;
TABLE created.

SQL> SELECT * FROM oracleplusWHERE object_id=1000;

OBJECT_ID
----------
      1000

SQL> SELECT hash_value,sql_text FROM v$sqlarea WHERE sql_text LIKE 'select * from killdb%';

HASH_VALUE
----------
SQL_TEXT
--------------------------------------------------------------------------------
368615450

SELECT * FROM oracleplusWHERE object_id=1000

SQL> SELECT to_char(368615450,'xxxxxxxxxx') FROM dual;

TO_CHAR(368
-----------
   15f8a01a

SQL> SELECT to_number('a01a2030','xxxxxxxxxxxxxxxx') FROM dual;

TO_NUMBER('A01A2030','XXXXXXXXXXXXXXXX')
----------------------------------------
                              2686066736

SQL> ALTER system FLUSH shared_pool;
System altered.

----session 2

SQL> conn /AS sysdba
Connected.

SQL> SELECT sid FROM SELECT s.sid,s.serial#,p.spid FROM v$process p,v$session s WHERE p.addr=s.paddr AND

SQL> SELECT s.sid,s.serial#,p.spid FROM v$process p,v$session s WHERE p.addr=s.paddr AND
  2  s.uhttp://www.oracleplus.netsername='ROGER';

       SID    SERIAL# SPID
---------- ---------- ------------
       140         29 3490

SQL> oradebug setospid 3490
Oracle pid: 24, Unix process pid: 3490, image: oracle@oracleplus.net (TNS V1-V3)

SQL> oradebug event 10049 trace name context forever,level 2686066736;
Statement processed.

----session 1

SQL> SELECT * FROM oracleplusWHERE object_id=1000;

OBJECT_ID
----------
      1000

—session 2

SQL> oradebug tracefile_name
/home/ora10g/admin/roger/udump/roger_ora_3490.trc

trace 内容如下:
*** 2012-06-29 22:36:37.753
*** ACTION NAME:() 2012-06-29 22:36:37.719
*** MODULE NAME:(SQL*Plus) 2012-06-29 22:36:37.719
*** SERVICE NAME:(SYS$USERS) 2012-06-29 22:36:37.719
*** SESSION ID:(140.29) 2012-06-29 22:36:37.719
Received ORADEBUG command 'event 10049 trace name context forever,level 2686066736' from process Unix process pid: 3447, image:
KGLTRCLCK kgllkal    hd = 0x0x26336978  KGL Lock addr = 0x0x27fb9f80 mode = N
KGLTRCLCK kglget     hd = 0x0x26336978  KGL Lock addr = 0x0x27fb9f80 mode = N
KGLTRCPIN kglpin     hd = 0x0x26336978  KGL Pin  addr = 0x0x27fa004c mode = X
KGLTRCPIN kglpndl    hd = 0x0x26336978  KGL Pin  addr = 0x0x27fa004c mode = X
KGLTRCLCK kgllkal    hd = 0x0x2991982c  KGL Lock addr = 0x0x27fbbaf4 mode = N
KGLTRCLCK kglget     hd = 0x0x2991982c  KGL Lock addr = 0x0x27fbbaf4 mode = N
KGLTRCPIN kglpin     hd = 0x0x2991982c  KGL Pin  addr = 0x0x27bafd14 mode = X
KGLTRCPIN kglpndl    hd = 0x0x2991982c  KGL Pin  addr = 0x0x27bafd14 mode = X
*** 2012-06-29 22:36:50.912
Received ORADEBUG command 'tracefile_name' from process Unix process pid: 3447, image:

—-session 1

SQL> select * from oraclepluswhere object_id=1000;

OBJECT_ID
----------
      1000

SQL> 再次执行该sql,来观察软解析的情况

---session 2

SQL>  oradebug event 10049 trace name context forever,level 2686066736;
Statement processed.

SQL> oradebug tracefile_name
/home/ora10g/admin/roger/udump/roger_ora_3490.trc

此时trace信息如下:
Received ORADEBUG command 'tracefile_name' from process Unix process pid: 3447, image:
*** 2012-06-29 22:42:32.468
Received ORADEBUG command 'event 10049 trace name context forever,level 2686066736' from process Unix process pid: 3447, image:
KGLTRCLCK kgllkdl    hd = 0x0x2991982c  KGL Lock addr = 0x0x27fbbaf4 mode = N
KGLTRCLCK kgllkdl2   hd = 0x0x2991982c  KGL Lock addr = 0x0x27fbbaf4 mode = 0
KGLTRCLCK kgllkdl    hd = 0x0x26336978  KGL Lock addr = 0x0x27fb9f80 mode = N
KGLTRCLCK kgllkdl2   hd = 0x0x26336978  KGL Lock addr = 0x0x27fb9f80 mode = 0
KGLTRCLCK kgllkal    hd = 0x0x26336978  KGL Lock addr = 0x0x27f95bc0 mode = N
KGLTRCLCK kglget     hd = 0x0x26336978  KGL Lock addr = 0x0x27f95bc0 mode = N
KGLTRCLCK kgllkal    hd = 0x0x2991982c  KGL Lock addr = 0x0x27fa6e84 mode = N
*** 2012-06-29 22:42:42.723
Received ORADEBUG command 'tracefile_name' from process Unix process pid: 3447, image:
[root@oracleplus~]#

SQL> col KGLNAOBJ FOR a65
SQL> SET LINES 200

SQL> SELECT kglhdadr,kglhdpar,kglnaobj FROM x$kglob WHERE LOWER(kglhdadr)='&aaa';
Enter VALUE FOR aaa: 26336978
OLD   1: SELECT kglhdadr,kglhdpar,kglnaobj FROM x$kglob WHERE LOWER(kglhdadr)='&aaa'
NEW   1: SELECT kglhdadr,kglhdpar,kglnaobj FROM x$kglob WHERE LOWER(kglhdadr)='26336978'

KGLHDADR KGLHDPAR KGLNAOBJ
-------- -------- -----------------------------------------------------------------
26336978 26336978 SELECT * FROM oracleplusWHERE object_id=1000

Enter VALUE FOR aaa: 2991982c
OLD   1: SELECT kglhdadr,kglhdpar,kglnaobj FROM x$kglob WHERE LOWER(kglhdadr)='&aaa'
NEW   1: SELECT kglhdadr,kglhdpar,kglnaobj FROM x$kglob WHERE LOWER(kglhdadr)='2991982c'

KGLHDADR KGLHDPAR KGLNAOBJ
-------- -------- -----------------------------------------------------------------
2991982C 26336978 SELECT * FROM oracleplusWHERE object_id=1000

我们可以看到此时的library cache lock是N模式,并没有X。

通过前面的实验,我们可以做出如下的几点总结:

1. sql的解析顺序是先library cache lock,然后是library cache pin。
2. 针对cursor获得的library cache lock mode是null,而不是X。
3. 针对cursor获得的library cache pin mode是X。
4. sql软解析时,也需要获得library cache lock latch。

--------------------------------------ORACLE-DBA----------------------------------------

最权威、专业的Oracle案例资源汇总之【案例】Oracle等待事件library cache lock产生原因和解决办法

本文由大师惜分飞原创分享,网址:http://www.oracleplus.net/arch/1371.html

Oracle研究中心

关键词:

library cache lock解决笔记

Oracle library cache lock等待事件