暂无图片
暂无图片
暂无图片
暂无图片
暂无图片
首页 / soft parse 和 library cache lock

soft parse 和 library cache lock

原创 Roger 2012-06-30
907
同事遇到一个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 '{39ecd679003247f2ed728ad9c7ed019a369dd84d0731b449c26bf628d3c1a20b}library cache{39ecd679003247f2ed728ad9c7ed019a369dd84d0731b449c26bf628d3c1a20b}';

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
SQL> 


---session 2
SQL> show user
USER is "ROGER"
SQL> alter system flush shared_pool;

System altered.

SQL> 
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@killdb.com (TNS V1-V3)
SQL>  oradebug dump processstate 8
Statement processed.
SQL> oradebug tracefile_name
/home/ora10g/admin/roger/udump/roger_ora_11649.trc
SQL> 


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
SQL> 


---session 3

SQL> oradebug setospid 11649
Oracle pid: 21, Unix process pid: 11649, image: oracle@killdb.com (TNS V1-V3)
SQL> oradebug dump processstate 8
Statement processed.
SQL> oradebug tracefile_name
/home/ora10g/admin/roger/udump/roger_ora_11649.trc
SQL> 


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
SQL>  


----session 2

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

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

SQL> ---这里原本是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
SQL> 

----session 2
SQL> select * from roger where id=100 and rownum < 3;
---再次hang住


-----session3
[root@killdb ~]# 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
SQL> 

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


trace内容如下：
[root@killdb ~]#  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@killdb ~]$ 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 killdb as select object_id from dba_objects;

Table created.

SQL> select * from killdb where object_id=1000;

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

SQL> select hash_value,sql_text from v$sqlarea where sql_text like 'select * from killdb{39ecd679003247f2ed728ad9c7ed019a369dd84d0731b449c26bf628d3c1a20b}';

HASH_VALUE
----------
SQL_TEXT
--------------------------------------------------------------------------------
 368615450
select * from killdb where 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> 
SQL> 
SQL> 
SQL> select sid from select s.sid,s.serial#,p.spid from v$process p,v$session s where p.addr=s.paddr and
  2  
SQL> 
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
---------- ---------- ------------
       140         29 3490

SQL> oradebug setospid 3490
Oracle pid: 24, Unix process pid: 3490, image: oracle@killdb.com (TNS V1-V3)
SQL> oradebug event 10049 trace name context forever,level 2686066736;
Statement processed.
SQL> 

----session 1
SQL> select * from killdb where object_id=1000;

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

SQL>

---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 killdb where 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
SQL> 

此时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@killdb ~]# 



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 killdb where object_id=1000

SQL> /
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 killdb where 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。
「喜欢这篇文章，您的关注和赞赏是给作者最好的鼓励」
关注作者
【版权声明】本文为墨天轮用户原创内容，转载时必须标注文章的来源（墨天轮），文章链接，文章作者等基本信息，否则作者和墨天轮有权追究责任。如果您发现墨天轮中有涉嫌抄袭或者侵权的内容，欢迎发送邮件至：contact@modb.pro进行举报，并提供相关证据，一经查实，墨天轮将立刻删除相关内容。

评论