案例分享:library cache pin故障处理

 最近遇到了一起library cache pin的case，环境为11.2.0.4的rac，故障现象持续了十来分钟后，运维人员通过批量杀业务会话方式消除故障，客户希望通过Oracle ACS高级救援服务，对这次故障进行深入分析，找出问题根结，保障系统稳健运行。叼起小烟斗，拿起手中的放大镜，让我们来看看都发生了什么。

     AWR是DBA的“套路”，首先是DB Time，DB Time是数据库负载的晴雨表，通过db time per second，可以知道数据库性能在问题发生时段很严重，这个时间段业务侧也产生了明显的卡顿感知。

   在Top Event中，library cache pin占到了db time消耗的93.5%，为我们分析问题指出了方向。

      Library cache pin是用于管理library cache对象并发访问的，ping住所需要的object，加载heap到内存中(如果不在内存的话)，按照library cache的体系结构(bucket->handle chain->handle->heap0 heap6 etc)，要想获得具体对象，他需要先获得library cache lock锁，lock住对应handle，然后才会申请去获得objects的pin。也就是说lock是用于process的并发控制，pin是用于cache object的串行控制或者说一致性控制，在sql进行编译解析期间，需要获得Library Cache Lock 和 Library Cache Pin。确保没有其它会话进程可以对这些对象的定义进行调整，他没有nowait请求方式，如果已经有会话进程长期排它持有，其他会话就有可能一直等待，导致数据库性能产生波动。

     产生library cache pin的一般原因是对objects及其相关进行了变更，常见的变更原因有：

1. 用户权限管理

   发生在用户的权限进行管理时，grant、revoke操作

2. 高峰时的object管理

   在系统运行高峰时对数据库object的管理，比如添加删除列、drop表等ddl操作
   

3. 在PL/SQL包中存在大量的互跨的依赖性(dependency)，对存储过程进行编译

   特别是业务繁忙时，在PL/SQL包中存在大量的互跨的依赖性(dependency)，对存储过程进行编译

4. BUG

     选定问题时间段，通过ash做阻塞链分析，确定问题最先开始在14:55，问题在15:05左右结束，sql_id多数指向packge A。

     首先排查last ddl变化情况，排查出上图中155行package对象B的ddl时间与问题发生时间段高度吻合，经过开发确认，爆发问题的package A与进行编译的package B之间存在互相调用关系，这为更近一步分析问题提供了指引。该如何确认pin event是否是这个编译动作存在强关联呢？

      假设这次不是事后分析，而是事中处理，处在问题发生当时，可以通过x$kglob中的KGLNAOWN，KGLNAOBJ来直接进行确认,我们先假设这次是事中，做个测试。

     创建测试存储过程。

create or replace procedure test_kgllk (l_sleep in boolean , l_compile in boolean)
as
 begin
  if (l_sleep ) then
  sys.dbms_session.sleep(600);
  elsif (l_compile )  then
    execute immediate 'alter procedure test_count compile';
  end if;
 end;
/

会话一：

    会话一执行创建的存储过程。

会话二：

    会话二采用手工方式也对这个存储过程进行编译。

     通过x$kglob我们知道问题发生在了test_kgllk这个测试存储过程上，namespace为1，表示这是个table or procedure，通过dba_kgllock和gv$session、gv$process的关联查询，我们可以知道sid 91正在请求mode为3(exclusive)模式的锁，被sid 117所阻塞，通过COMMAND "PL/SQL EXECUTE"可以知道它正在执行一段存储过程。换种展现方式，我们会看的更清楚。

     我们这次遇到的情况时，ACS介入时，问题现场环境已经不在具备x$查询，只能另辟蹊径，想其他办法。

Library cache pin 的参数中，

       •      P1 = Handle address

       •      P2 = Pin address

       •      P3 = Encoded Mode & Namespace

    如果问题发生在namespace=1，我们可以通过p3参数获取到ojbect_id、namespace和request mode，我们依然根据上面的测试存储过程来进行模拟。

SQL> select p1,p2,p3,p3raw  from v$session_wait where event like 'library cache%';


  P1         P2             P3            P3RAW
---------- ---------- ---------- ----------------
2079200912 1976308512 3.1355E+14 00011D2C00010003

     p3raw是p3的16进制格式。

转换request mode

SQL>   select to_number(substr('00011D2C00010003',-4),'xxxxxxxxxxxxxx') request_mode from dual;


REQUEST_MODE
------------
     3

       ○   2 - Share mode

       ○   3 - Exclusive mode

       转换Namespace

SQL>   select to_number(substr('00011D2C00010003',-8,4),'xxxxxxxxxxxxxx') namespace from dual;


 NAMESPACE
----------
   1

  转换Object_id

SQL>select to_number(substr('00011D2C00010003',1,length('00011D2C00010003')-8),'xxxxxxxxxxxxxx') object_id from dual;


 OBJECT_ID
----------
     73004
SQL> col owner for a20
SQL> select owner,object_name,object_type from dba_objects where object_id=73004;


OWNER         OBJECT_NAME    OBJECT_TYPE
---------   --------------- ------------------
TEST         TEST_KGLLK     PROCEDURE

     通过对p3的转换，可以得到library cache pin争用的焦点在test用户的test_kgllk这个procedure上，在我们这次的case处理中，沿用上面的分析思路，得出客户环境的pin争用是pkg B，加上ddl time时间吻合，建议客户对编译动作的发起源进行排查，最终得出是人为手工编译引起的一起数据库性能故障。

     针对超过一定规模的运维团队，建议采用人防、技防多管齐下的方式规范日常运维，一方面加强规章制度管控执行，强调变更作业的报备审批制度，做到专人、专岗、专账号，并且不与业务生产账号混用，另一方面我们也可以在特殊时期，采用一些技术手段能够在问题发生时能够做到快速定位。

     站在数据库DBA的角度讲，除了前面讲过的通过p3 ,x$kglob 手段外，还可以隐含参数_trace_kqlidp可以快速定位procedure,function等对象的失效原因，它可以在trace中输出概要和详情trc，但对于11g环境，需要先安装patch 4991675，我们同样来做个测试。

创建测试表和测试存储过程

SQL> create table llg as select * from dba_users;


Table created.


SQL> create or replace procedure test_count as
   v_total varchar2(100);
   begin
     select count(*) into v_total from llg;
   end;  
  /


Procedure created.

开启trace_kqlidp监控，对表结构进行变更。

      本次我们仅在session级别开启

在告警日志alert中，可以看到如下输出

Thread 1 advanced to log sequence 19 (LGWR switch)
  Current log# 1 seq# 19 mem# 0: u01/app/oracle/oradata/CDBTEST/redo01.log
2021-04-02T04:19:42.691380+08:00
PDB1(3):INVALIDATION performed by ospid=22701. Please see tracefile.

    提示ospid 22701发起了某项操作，导致有对象invaild。

INVALIDATION: Current SQL follows
alter table test.llg add abc1 varchar2(10)
----- Abridged Call Stack Trace -----
ksedsts()+426<-kqlidp0_int()+19108<-kqlidp0()+208<-atbdrv()+10584<-opiexe()+30035<-opiosq0()+4599<-kpooprx()+387<-kpoal8()+830<-opiodr()+1202<-ttcpip()+1222<-opitsk()+1895<-opiino()+936<-opiodr()+1202<-opidrv()+1094<-sou2o()+165<-opimai_real()+422<-ssthrdmain()+417
<-main()+256<-__libc_start_main()+245
----- End of Abridged Call Stack Trace -----
Partial short call stack signature: 0x8dae4fe170b023fa
Fine-grain delta dump for unit TEST.LLG
- Change bit vector 0:
  -23, -16,
- Change bit vector 1:Empty
- Change bit vector 2:Empty
- Shift table:Empty
kqlidp0: 73295 (CURSOR TEST.LLG) (Parent:    0) [ROOT]
kqlidp0:. 73005 (PROCEDURE TEST.TEST_COUNT) (Parent:73295) [ADDED TO QUEUE]
kqlidp0:. 73005 (PROCEDURE TEST.TEST_COUNT) (Parent:73295) [SKIP:FG INTERSECT EMPTY]

      详情trc里告诉了我们，是哪条命令引发的实效，都有谁被受到了影响。