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

【案例】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$latchWHERE 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' FROMv$latch_children WHERE name='library cache lock';

'ORADEBUGPOKE0X'||ADDR||'40X00000001'

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

oradebug poke 0x287C75F8 4 0x00000001

SQL> SELECT 'oradebug poke 0x' || addr || ' 4 0x00000001' FROMv$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产生原因和解决办法