soft parse 和 library cache lock
本站文章除注明转载外，均为本站原创： 转载自love wife love life —Roger的Oracle/MySQL/PostgreSQL数据恢复博客
本文链接地址: soft parse 和 library cache lock
同事遇到一个library cache lock lath等待的问题，导致cpu使用非常高，关于
library cache lock似乎存在一点争议，我这里用实验来进行说明。
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 |
---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 SQL> |
|
1 2 3 4 5 6 7 8 9 10 11 |
---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住 |
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 |
---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> |
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 |
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。
|
1 2 3 4 5 6 7 |
---session 1 释放library cache lock latch SQL> oradebug poke 0x287C75F8 4 0 BEFORE: [287C75F8, 287C75FC) = 000000FF AFTER: [287C75F8, 287C75FC) = 00000000 SQL> |
|
1 2 3 4 5 6 7 8 9 |
---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> |
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 |
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。
|
1 2 3 4 5 6 7 8 |
---session 1 释放library cache pin latch SQL> oradebug poke 0x287C7594 4 0 BEFORE: [287C7594, 287C7598) = 000000FF AFTER: [287C7594, 287C7598) = 00000000 SQL> |
|
1 2 3 4 5 6 7 8 9 10 |
----session 2 SQL> select * from roger where id=100 and rownum < 3; ID ---------- 100 100 SQL> ---这里原本是hang住的，当释放latch以后，执行完成 |
下面再次执行该sql，来看看软解析的情况是怎么样的？
|
1 2 3 4 5 6 7 8 9 10 11 12 |
-----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住 |
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 |
-----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.
|
1 2 3 4 5 6 7 8 9 10 11 |
----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> |
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 |
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是什么模式呢？
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 |
---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%'; 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. |
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 |
----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
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 |
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
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 |
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 ~]# |
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 |
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。
One Response to “soft parse 和 library cache lock”
good! thanks
Leave a Reply
You must be logged in to post a comment.