[20161216]关于library cache lock.txt

--这几天一直在关注这个链接,http://www.itpub.net/thread-2073170-1-1.html
--就是library cache lock导致挂死业务,一般引起这个问题编译包,而应用正好在使用执行这个包,以及11g口令大小写导致无法登录的问题,
--我自己很久以前也遇到过一些,那时的系统是10g,http://www.itpub.net/thread-1842463-1-1.html,但是只要分析某个表就出现library cache lock,
--当时我采用方式是lock表统计,第2天仔细检查,才确定是bug,我们机器是rac,我轮询重启了数据库,再分析一切ok.

--今天我仔细看了链接 http://www.bobbydurrettdba.com/2014/11/24/parsing-blocks-stats-blocks-parsing/
--他提到了 分析sql语句阻塞 统计,统计阻塞相关表的分析执行的情况,我仅仅再重复作者的测试.

1.环境:
SCOTT@book> @ &r/ver1

PORT_STRING                    VERSION        BANNER
------------------------------ -------------- --------------------------------------------------------------------------------
x86_64/Linux 2.4.xx            11.2.0.4.0     Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production

create table t1 as select * from dba_tables;
create table t2 as select * from dba_tables;

--lz的上传附件http://www.bobbydurrettdba.com/uploads/parsingstatsparsing.zip,里面包含执行的sql语句.

2.测试1:
--session 1,单独执行:chain1.sql

explain plan into plan_table for
select
count(*)
from
     t1,
     t2,
     t2 t3,
     t2 t4,
     t2 t5,
     t2 t6,
     t2 t7,
...
  t1.owner=t96.owner and
  t1.owner=t97.owner and
  t1.owner=t98.owner and
  t1.owner=t99.owner and
  t1.owner=t100.owner
/

--分析这个执行计划,涉及表连接很多分析时间很长.

SCOTT@book> SELECT VALUE/100 "CPU in seconds"
  2  FROM V$SESSION a, V$SESSTAT b
  3  where a.SID = b.SID
  4  and a.SID = :monitored_sid
  5  and b.STATISTIC# = (SELECT STATISTIC# FROM V$STATNAME WHERE NAME='CPU used by this session');

CPU in seconds
--------------
          24.2

--//我的测试使用cpu 是24.2秒.

3.测试2:
--session 1,单独执行:chain1.sql

--session 2,单独执行:chain2.sql,也就是分析表
execute dbms_stats.gather_table_stats(NULL,'T1');

--可以发现session 2出现library cache lock.
SCOTT@book> -- show library cache lock wait time in seconds
SCOTT@book>
SCOTT@book> SELECT TIME_WAITED/100 "Library cache lock in seconds"
  2  FROM V$SESSION_EVENT a, V$SESSION b
  3  WHERE
  4  a.SID = b.SID and
  5  a.SID= :monitored_sid and
  6  a.event='library cache lock';

Library cache lock in seconds
-----------------------------
                        22.98

--//session 4,分析:

SYS@book> @ &r/wait
P1RAW            P2RAW            P3RAW                    P1         P2         P3        SID    SERIAL#       SEQ# EVENT                                    STATE               WAIT_TIME_MICRO SECONDS_IN_WAIT
---------------- ---------------- ---------------- ---------- ---------- ---------- ---------- ---------- ---------- ---------------------------------------- ------------------- --------------- ---------------
0000000062657100 0000000000000001 00               1650815232          1          0         56        711         74 SQL*Net message to client                WAITED SHORT TIME                 2               0
000000007C6DAA20 000000007C3518E0 00015A6D00010003 2087561760 2083854560 3.8090E+14         68        311         92 library cache lock                       WAITING                     3162559               3

SYS@book> @ &r/ev_name 'library cache lock'
    EVENT#   EVENT_ID NAME                                     PARAMETER1           PARAMETER2           PARAMETER3           WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS
---------- ---------- ---------------------------------------- -------------------- -------------------- -------------------- ------------- ----------- --------------------
       287  916468430 library cache lock                       handle address       lock address         100*mode+namespace      3875070507           4 Concurrency

SYS@book> @ &r/lcl
display  library cache lock problem

   INST_ID SADDR            HANDLE                  MOD        REQ OBJECT               SQL_ID        HASH_VALUE KGLNAOBJ                       USER_NAME            C50
---------- ---------------- ---------------- ---------- ---------- -------------------- ------------- ---------- ------------------------------ -------------------- --------------------------------------------------
         1 0000000085A697C0 000000007C6DAA20          2          0 T1                   gsmky1za3hww0 3560469376 T1                             SCOTT                alter system kill session '46,569' immediate;

display wait library cache lock

       SID    SERIAL# SPID       PID  P_SERIAL# EVENT                                    C50
---------- ---------- ------ ------- ---------- ---------------------------------------- --------------------------------------------------
        68        311 55054       30        145 library cache lock                       alter system kill session '68,311' immediate;

SYS@book> @ &r/sharepool/shp4 000000007C6DAA20 0
TEXT           KGLHDADR         KGLHDPAR         C40                                      KGLOBHD0         KGLOBHD6           KGLOBHS0   KGLOBHS6   KGLOBT16   N0_6_16        N20   KGLNAHSH KGLOBT03        KGLOBT09
-------------- ---------------- ---------------- ---------------------------------------- ---------------- ---------------- ---------- ---------- ---------- --------- ---------- ---------- ------------- ----------
父游标句柄地址 000000007C6DAA20 000000007C6DAA20 T1                                       000000007DF2E798 00                     4688          0          0      4688       4688 3560469376                        0

--我不知道这里为什么前面有1个sql_id,查询这个sql_id是找不到信息的,实际上T1,顺便问一下那位知道这个hash值如何计算的,sql语句是后面chr(0)的md5值.

SYS@book> select KGLHDADR,KGLHDPAR,KGLNAHSH,KGLNAHSV,KGLHDNSD,KGLOBT03 from x$kglob where kglhdadr='000000007C6DAA20';
KGLHDADR         KGLHDPAR           KGLNAHSH KGLNAHSV                         KGLHDNSD                                                         KGLOBT03
---------------- ---------------- ---------- -------------------------------- ---------------------------------------------------------------- -------------
000000007C6DAA20 000000007C6DAA20 3560469376 f1cd2b1c8166d406fc4e5e0fd4387380 TABLE/PROCEDURE

--一般KGLOBT03对应sql_id.KGLNAHSV=f1cd2b1c8166d406fc4e5e0fd4387380取后面8位d4387380,
SYS@book> @ &r/16to10 d4387380
16 to 10 DEC
------------
  3560469376
--//可以对上HASH_VALUE.
--//KGLNAHSV=f1cd2b1c8166d406fc4e5e0fd4387380取后面16位fc4e5e0fd4387380.

SYS@book> set numw 20
SYS@book> select to_number(substr(KGLNAHSV,-16),'xxxxxxxxxxxxxxxxxxxx') sql_id10 from x$kglob where kglhdadr='000000007C6DAA20';
            SQL_ID10
--------------------
18180572167819260800

--//参考链接: http://blog.itpub.net/267265/viewspace-1365382/
select replace(wmsys.wm_concat(c),',') from (
select c from (
SELECT SUBSTR ('0123456789abcdfghjkmnpqrstuvwxyz', a + 1, 1) c,rownum rn
  FROM (WITH data (a, b)
             AS (SELECT MOD (&1, 32) a, TRUNC (&1 / 32) b FROM DUAL
                 UNION ALL
                 SELECT MOD (b, 32) a, TRUNC (b / 32) b
                   FROM data
                  WHERE b !=0
                  )
        SELECT a
          FROM data)) order by rn desc);

REPLACE(WMSYS.WM_CONCAT(C),',')
---------------------------------
gsmky1za3hww0

--//与前面的sql_id正好对上.

4.测试4:
--session 1,单独执行:chain1.sql

--session 2,单独执行:chain2.sql,也就是分析表
execute dbms_stats.gather_table_stats(NULL,'T1');

--session 3,单独执行:chain3.sql,做一个硬解析:select /* comment to force hard parse */ count(*) from T1;
--补充 实际上只要执行sql语句涉及t1的表都会出现阻塞.

--//可以发现session 2,3都出现了library cache lock.

SYS@book> @ &r/wait
P1RAW            P2RAW            P3RAW                    P1         P2         P3        SID    SERIAL#       SEQ# EVENT                     STATE               WAIT_TIME_MICRO SECONDS_IN_WAIT
---------------- ---------------- ---------------- ---------- ---------- ---------- ---------- ---------- ---------- ------------------------- ------------------- --------------- ---------------
0000000062657100 0000000000000001 00               1650815232          1          0         46        589         69 SQL*Net message to client WAITED SHORT TIME                 2               0
000000007C6DAA20 000000007BBE6938 00015A6D00010003 2087561760 2076076344 3.8090E+14         68        311        158 library cache lock        WAITING                     9187405               9
000000007C6DAA20 000000007E570F38 00015A6D00010002 2087561760 2119634744 3.8090E+14         56        719         25 library cache lock        WAITING                     8126936               8

SYS@book> @ &r/lcl

display  library cache lock problem

   INST_ID SADDR            HANDLE                  MOD        REQ OBJECT               SQL_ID        HASH_VALUE KGLNAOBJ                       USER_NAME            C50
---------- ---------------- ---------------- ---------- ---------- -------------------- ------------- ---------- ------------------------------ -------------------- --------------------------------------------------
         1 0000000085ACB3C0 000000007C6DAA20          2          0 T1                   gsmky1za3hww0 3560469376 T1                             SCOTT                alter system kill session '80,81' immediate;

display wait library cache lock

       SID    SERIAL# SPID       PID  P_SERIAL# EVENT                                    C50
---------- ---------- ------ ------- ---------- ---------------------------------------- --------------------------------------------------
        56        719 55406       29         31 library cache lock                       alter system kill session '56,719' immediate;
        68        311 55054       30        145 library cache lock                       alter system kill session '68,311' immediate;

--这里也就完整演示了分析sql语句阻塞分析表,分析表也会导致阻塞相关表的sql语句.

5.测试5:
--//又重复1次做测试4,我发现即使做软分析一样会阻塞.

--但是我修改chain3.sql执行,修改查询表T2,
select /* comment to force hard parse */ count(*) from T2;

--我发现session 2 依旧会阻塞,但是session 3很快完成,这也说明分析表T1这时阻塞了session 3的执行.

6.测试6:
--我修改chain1.sql,条件一半是t1.owner=...一半是t2.owner=...
..
  t1.owner=t49.owner and
  t1.owner=t50.owner and
  t2.owner=t51.owner and
  t2.owner=t52.owner and
  t2.owner=t53.owner and
...

--session 1,单独执行:chain1.sql

--session 2,单独执行:chain2.sql,也就是分析表
execute dbms_stats.gather_table_stats(NULL,'T1');

SCOTT@book> SELECT TIME_WAITED/100 "Library cache lock in seconds"
  2  FROM V$SESSION_EVENT a, V$SESSION b
  3  WHERE
  4  a.SID = b.SID and
  5  a.SID= :monitored_sid and
  6  a.event='library cache lock';

Library cache lock in seconds
-----------------------------
                         8.26
--我仅仅发现library cache lock减少不少.

7.我仔细思考itpub网友遇到的问题,我猜测bug可能性大,但是可能与后台执行的sql tuning advisor有关.

SYS@book> select client_name, status,attributes,window_group from dba_autotask_client;
CLIENT_NAME                              STATUS   ATTRIBUTES                                                   WINDOW_GROUP
---------------------------------------- -------- ------------------------------------------------------------ --------------
auto optimizer stats collection          ENABLED  ON BY DEFAULT, VOLATILE, SAFE TO KILL                        ORA$AT_WGRP_OS
auto space advisor                       ENABLED  ON BY DEFAULT, VOLATILE, SAFE TO KILL                        ORA$AT_WGRP_SA
sql tuning advisor                       ENABLED  ONCE PER WINDOW, ON BY DEFAULT, VOLATILE, SAFE TO KILL       ORA$AT_WGRP_SQ

SYS@book> select * from (select * from DBA_AUTOTASK_SCHEDULE order by 2 ) where rownum<=10;
WINDOW_NAME      START_TIME                         DURATION
---------------- ---------------------------------- -------------
FRIDAY_WINDOW    2016-12-16 22:00:00.300000 +08:00  +000 04:00:00
SATURDAY_WINDOW  2016-12-17 06:00:00.300000 +08:00  +000 20:00:00
SUNDAY_WINDOW    2016-12-18 06:00:00.300000 +08:00  +000 20:00:00
MONDAY_WINDOW    2016-12-19 22:00:00.300000 +08:00  +000 04:00:00
TUESDAY_WINDOW   2016-12-20 22:00:00.300000 +08:00  +000 04:00:00
WEDNESDAY_WINDOW 2016-12-21 22:00:00.300000 +08:00  +000 04:00:00
THURSDAY_WINDOW  2016-12-22 22:00:00.300000 +08:00  +000 04:00:00
FRIDAY_WINDOW    2016-12-23 22:00:00.300000 +08:00  +000 04:00:00
SATURDAY_WINDOW  2016-12-24 06:00:00.300000 +08:00  +000 20:00:00
SUNDAY_WINDOW    2016-12-25 06:00:00.300000 +08:00  +000 20:00:00
10 rows selected.

SYS@book> select * from DBA_AUTOTASK_WINDOW_CLIENTS;
WINDOW_NAME                    WINDOW_NEXT_TIME                   WINDO AUTOTASK OPTIMIZE SEGMENT_ SQL_TUNE HEALTH_M
------------------------------ ---------------------------------- ----- -------- -------- -------- -------- --------
MONDAY_WINDOW                  2016-12-19 22:00:00.000000 +08:00  FALSE ENABLED  ENABLED  ENABLED  ENABLED  DISABLED
TUESDAY_WINDOW                 2016-12-20 22:00:00.000000 +08:00  FALSE ENABLED  ENABLED  ENABLED  ENABLED  DISABLED
WEDNESDAY_WINDOW               2016-12-21 22:00:00.000000 +08:00  FALSE ENABLED  ENABLED  ENABLED  ENABLED  DISABLED
THURSDAY_WINDOW                2016-12-22 22:00:00.000000 +08:00  FALSE ENABLED  ENABLED  ENABLED  ENABLED  DISABLED
FRIDAY_WINDOW                  2016-12-16 22:00:00.000000 +08:00  FALSE ENABLED  ENABLED  ENABLED  ENABLED  DISABLED
SATURDAY_WINDOW                2016-12-17 06:00:00.000000 +08:00  FALSE ENABLED  ENABLED  ENABLED  ENABLED  DISABLED
SUNDAY_WINDOW                  2016-12-18 06:00:00.000000 +08:00  FALSE ENABLED  ENABLED  ENABLED  ENABLED  DISABLED
7 rows selected.

--//可以3项工作是集中在一起执行的,有一些分析消耗大量资源,而这个时候有做统计分析,出现某种特殊的bug导致阻塞感觉"很正常".我感觉oracle应该改进一下,错开执行时间.
--//我显示基本disbale 了,auto space advisor,sql tuning advisor.
--//停止auto space advisor,是因为遭遇了日志暴涨的情况,链接:http://blog.itpub.net/267265/viewspace-1329205/

--作者后面做了一些补充,我仅仅摘录下来:
http://www.bobbydurrettdba.com/2014/11/24/parsing-blocks-stats-blocks-parsing/
P.S. After reviewing the SR I wanted to understand what this parse blocks stats blocks parse looked like in a state
dump.  The Oracle support analyst explained how the locks looked in a state dump that we uploaded but I didn't get a
chance to look at it closely until today.  I found the most important information in lines with the string "
LibraryObjectLock" at the front of the line after some spaces or tabs.  There were three types of lines – the holding
share lock, the waiting exclusive lock, and the many waiting share locks:

LibraryObjectLock:  Address=... Handle=0x5196c8908 Mode=S ...
LibraryObjectLock:  Address=... Handle=0x5196c8908 RequestMode=X ...
LibraryObjectLock:  Address=... Handle=0x5196c8908 RequestMode=S ...

The "…" indicates places I edited out other details.  The handle 0x5196c8908 identifies the table being locked.  The
"Mode=S" string indicates a successful share lock of that table by the session with the long parse time.  The
"RequestMode=X" was from the stats job trying to get exclusive access to the table.  The "RequestMode=S" was all the
other sessions trying to get shared access to the table waiting for stats to first get exclusive access.  Anyway, I just
wanted to translate what Oracle support told me into something that might be useful to others.  Plus I want to remember
it myself!

--附上我的执行脚本:
$ cat lcl.sql
PROMPT
PROMPT display  library cache lock problem
PROMPT

column object format a20
column user_name format a20
SELECT inst_id
      ,kgllkses saddr
      ,kgllkhdl handle
      ,kgllkmod MOD
      ,kgllkreq REQ
      ,kglnaobj object
      ,KGLLKSQLID sql_id
      ,kglnahsh hash_value
      ,KGLNAOBJ
      ,user_name
      ,   'alter system kill session '''
       || s.sid
       || ','
       || s.serial#
       || ''''
       || ' immediate;'
          c50
  --,lock_a.*
  FROM x$kgllk lock_a, v$session s
WHERE    s.saddr = lock_a.kgllkses and
kgllkmod > 0
       AND EXISTS
              (SELECT lock_b.kgllkhdl
                 FROM x$kgllk lock_b
                WHERE     kgllkses IN (SELECT saddr
                                         FROM v$session
                                        WHERE event like 'library cache lock') /* blocked session */
                                        --WHERE event like 'library cache pin') /* blocked session */
                      AND lock_a.kgllkhdl = lock_b.kgllkhdl
                      AND kgllkreq > 0);

PROMPT
PROMPT display wait library cache lock
PROMPT
SELECT s.sid
      ,s.serial#
      ,p.spid
      ,p.pid
      ,p.serial# p_serial#
      ,s.event
      ,   'alter system kill session '''
       || s.sid
       || ','
       || s.serial#
       || ''''
       || ' immediate;'
          c50
  FROM v$session s, v$process p
WHERE s.paddr = p.addr
AND s.event= 'library cache lock';
--AND s.event= 'library cache pin';

$ cat shp4.sql
column N0_6_16 format 99999999
SELECT DECODE (kglhdadr,
               kglhdpar, '父游标句柄地址',
               '子游标句柄地址')
          text,
       kglhdadr,
       kglhdpar,
       substr(kglnaobj,1,40) c40,
       kglobhd0,
       kglobhd6,
       kglobhs0,kglobhs6,kglobt16,
       kglobhs0+kglobhs6+kglobt16 N0_6_16,
       kglobhs0+kglobhs1+kglobhs2+kglobhs3+kglobhs4+kglobhs5+kglobhs6+kglobt16 N20,
       kglnahsh,
       kglobt03 ,
       kglobt09 
  FROM x$kglob
WHERE kglobt03 = '&1'  or kglhdpar='&1' or kglhdadr='&1' or KGLNAHSH= &2;

$ cat wait.sql
select p1raw,p2raw,p3raw,p1,p2,p3,sid,serial#,seq#,event,state,wait_time_micro,seconds_in_wait from v$session where wait_class<>'Idle' order by event ;