数据库异常繁忙，大量library cache lock、cursor: pin S wait on X等待

syp4869

生产环境RAC数据库，今天凌晨3点至4点期间，两个实例上莫名其妙的产生了大量类别为Concurrency的等待事件。其中实例1为library cache lock、library cache load lock，实例2为cursor: pin S wait on X、row cache lock、library cache load lock等。该时段不会有大量用户访问数据库，正常情况下数据库应该比较空闲。从AWR报告中SQL ordered by Elapsed Time列表可以看出很多SQL的Elapsed Time和CPU Time相差很大，且出现了大量的delete from idl_ub2$ where obj#=:1 and part=:2、delete from settings$ where obj# = :1这类语句。
       对应的也生成了同时段两实例的ASH报告，报告中虽给出了导致等待事件发生的语句，比如实例1上执行多次的BEGIN vPD_PKG.SET_CONTEXT_COMPID('0400'); END;导致了大量的library cache lock等待。但是正常情况下，该SQL执行一次都会在一秒以内（即使单位时间内，比如一小时，执行了更多次）执行完成，今天凌晨却需要5秒。同样困惑的还有实例2上大量cursor: pin S wait on X等待是如何产生的。
       附件是问题时段两实例的AWR、ASH报告，烦请大侠们指点迷津。

Maclean Liu(刘相兵

Top 5  中 parse类的等待 占了绝大多数  library cache lock 、 library cache load lock 说明系统中存在大量编译compile






但是parse 和 hard parse 并不多



BEGIN      vPD_PKG.SET_CONTEXT_COMPID('0400');   END;     这个语句消耗了大量的 DB TIME ， 但其cpu time 很少， 可以确认是这个过程造成了 性能问题








伴随这个语句 vPD_PKG.SET_CONTEXT_COMPID 出现的还有以下 这些SQL:

delete from idl_ub2$ where obj#=:1 and part=:2
delete from objauth$ where obj#=:1
delete from idl_char$ where obj#=:1 and part=:2
delete from javaobj$ where obj#=:1
delete from ncomp_dll$ where obj#=:1 returning dllname into :2


这很明显是在 重编译 compile 某些 PL/SQL 对象






可以的话 把 vPD_PKG.SET_CONTEXT_COMPID 这个过程贴出来 ， 搜索了以下 这个对象貌似是国内的开发人员弄的。

为什么要在一个小时内 上万次的 重编译对象？

aaaaaaaa2000

BEGIN      vPD_PKG.SET_CONTEXT_COMPID('0400');   END;     这个语句消耗了大量的 DB TIME ， 但其cpu time 很少， 可以确认是这个过程造成了 性能问题

什么样的场景是消耗大量的db time但是占用很少的cpu time？这个语句在干啥？如果是parse的话也应该占用cpu time吧

Maclean Liu(刘相兵

Parse CPU to Parse Elaped 反应了 总的Parse 时间中 CPU占的比例，

为什么 parse 使用的Cpu time占这么小的比例？　

因为Parse 的绝大多数时间消耗在 library cache lock和library cache load lock这类 library 等待上

syp4869

VPD_PKG.SET_CONTEXT_COMPID过程的代码如下：
PROCEDURE SET_CONTEXT_COMPID(I_COMPID IN VARCHAR2) IS
    V_CONTEXT VARCHAR2(8):=SYS_CONTEXT('VPD_CONTEXT','COMPID');
  BEGIN
    DBMS_SESSION.RESET_PACKAGE;
    DBMS_SESSION.SET_CONTEXT('VPD_CONTEXT','COMPID',UPPER(I_COMPID));
  EXCEPTION
    WHEN OTHERS THEN
      DBMS_SESSION.RESET_PACKAGE;
      DBMS_SESSION.SET_CONTEXT('VPD_CONTEXT','COMPID',V_CONTEXT);
  END SET_CONTEXT_COMPID;

该数据库使用了VPD技术，需要大量的调用该过程设置环境变量。
附件为同一个数据库2月25号凌晨3点至5点的AWR报告，从中可以看出，BEGIN vPD_PKG.SET_CONTEXT_COMPID('0400'); END;执行的次数更多，但并没造成如此严重library cache lock等待，所以我很困惑3月2号这天凌晨是什么导致了如此严重的library cache lock、library cache load lock这些等待。

3月2号凌晨的AWR报告中大量出现的执行次数为3947次的诸如delete from obj$ where obj# = :1这类的语句，是否是导致问题的原因呢？这些语句又为何产生？
实例2上有大量的cursor: pin S wait on X等待，九百多万次，这个是如何产生的呢？

Maclean Liu(刘相兵

一种猜测：

可能由于某个object 被 library cache lock in X mode且长期不释放， 导致了大量进程 因为 library cache lock而等待。

但是这需要当时的systemstate dump来确定， 建议你找一下 1号节点上的 diag、lmd、lck、lmon进程的trace上传。

anbob

重编译包含 session cache cursor 软软解析的数量么？

Maclean Liu(刘相兵

”重编译包含 session cache cursor 软软解析的数量么？“

他这个case 主要是对一些PL/SQL对象的 重编译 recompile ，而非对CURSOR游标的


SQL> select * from v$version;

BANNER
----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - 64bi
PL/SQL Release 10.2.0.1.0 - Production
CORE    10.2.0.1.0      Production
TNS for Linux: Version 10.2.0.1.0 - Production
NLSRTL Version 10.2.0.1.0 - Production


SQL> create or replace procedure mac1 as begin null; end;
  2  /

Procedure created.

SQL>
SQL> oradebug setmypid ;
Statement processed.
SQL> oradebug event 10046 trace name context forever,level 1;
Statement processed.
SQL> alter procedure mac1 compile;

Procedure altered.

SQL> oradebug tracefile_name;
/s01/admin/G10R21/udump/g10r21_ora_471.trc


[root@vrh8 udump]# grep delete /s01/admin/G10R21/udump/g10r21_ora_471.trc
delete from procedureinfo$ where obj#=:1
delete from argument$ where obj#=:1
delete from procedurec$ where obj#=:1
delete from procedureplsql$ where obj#=:1
delete from procedurejava$ where obj#=:1
delete from vtable$ where obj#=:1
delete from idl_ub1$ where obj#=:1 and part=:2 and version<>:3
delete from idl_char$ where obj#=:1 and part=:2 and version<>:3
delete from idl_ub2$ where obj#=:1 and part=:2 and version<>:3
delete from idl_sb4$ where obj#=:1 and part=:2 and version<>:3
delete from ncomp_dll$ where obj#=:1 returning dllname into :2
delete from idl_ub1$ where obj#=:1 and part=:2 and version<>:3
delete from idl_char$ where obj#=:1 and part=:2 and version<>:3
delete from idl_ub2$ where obj#=:1 and part=:2 and version<>:3
delete from idl_sb4$ where obj#=:1 and part=:2 and version<>:3
delete from ncomp_dll$ where obj#=:1 returning dllname into :2
delete from idl_ub1$ where obj#=:1 and part=:2 and (piece#<:3 or piece#>:4) and version=:5
delete from idl_char$ where obj#=:1 and part=:2 and (piece#<:3 or piece#>:4) and version=:5
delete from idl_ub2$ where obj#=:1 and part=:2 and (piece#<:3 or piece#>:4) and version=:5
delete from idl_sb4$ where obj#=:1 and part=:2 and (piece#<:3 or piece#>:4) and version=:5
delete from idl_ub1$ where obj#=:1 and part=:2 and version<>:3
delete from idl_char$ where obj#=:1 and part=:2 and version<>:3
delete from idl_ub2$ where obj#=:1 and part=:2 and version<>:3
delete from idl_sb4$ where obj#=:1 and part=:2 and version<>:3
delete from ncomp_dll$ where obj#=:1 returning dllname into :2
delete from idl_char$ where obj#=:1 and part=:2 and (piece#<:3 or piece#>:4) and version=:5
delete from idl_ub2$ where obj#=:1 and part=:2 and (piece#<:3 or piece#>:4) and version=:5
delete from error$ where obj#=:1
delete from settings$ where obj# = :1
delete from warning_settings$ where obj# = :1
delete from dependency$ where d_obj#=:1
delete from access$ where d_obj#=:1


对于cursor 游标的编译  一般称之为 parse
对于PL/SQL object的编译 一般称为 compile


若session cached cursor (PGA中)

关于session cached cursor
"游标缓存本身是保存在sga的shared pool共享池中的， 但是SESSION_CACHED_CURSOR指定的是session会话缓存游标的上限，主要体现在PGA的UGA中保存这些缓存游标的地址,如下文：

SQL> oradebug setmypid ;
Statement processed.
SQL> oradebug dump errorstack 4;
Statement processed.

trace content

—– Session Open Cursors —–

—– Session Cached Cursor Dump —–
—– Generic Session Cached Cursor Dump —–
———————————————————–
————– Generic Session Cached Cursors Dump ——–
———————————————————–
hash table=0x7f9baed440f0 cnt=4 LRU=0x7f9baed36ca0 cnt=4 hit=3 max=50 NumberOfTypes=6
type#0 name=DICTION count=0
type#1 name=BUNDLE count=0
type#2 name=SESSION count=4
type#3 name=PL/SQL count=0
type#4 name=CONSTRA count=0
type#5 name=REPLICA count=0
Bucket#051 seg=0x7f9baed44a78 nit=5 nal=5 ips=5 sz=56 flg=3 ucnt=1
0 cob=0x7f9baed54940 idx=33 flg=0 typ=2 cur=0x7f9baed58308 lru=1 fl=1
Bucket#098 seg=0x7f9baed45348 nit=5 nal=5 ips=5 sz=56 flg=3 ucnt=1
0 cob=0x7f9baed5c2b0 idx=62 flg=0 typ=2 cur=0x7f9baed5c3e0 lru=1 fl=1
Bucket#123 seg=0x7f9baed457f8 nit=5 nal=5 ips=5 sz=56 flg=3 ucnt=1
0 cob=0x7f9baed5be18 idx=7b flg=0 typ=2 cur=0x7f9baed5bf48 lru=1 fl=1
Bucket#203 seg=0x7f9baed466f8 nit=5 nal=5 ips=5 sz=56 flg=3 ucnt=1
0 cob=0x7f9baed5b980 idx=cb flg=0 typ=2 cur=0x7f9baed5bab0 lru=1 fl=1
———————————————————–
——Finished Dumping Generic Session Cached Cursors——
———————————————————–

在dedicated server模式下这些”Session Cached Cursors”在PGA的UGA中， 而在shared server模式下则UGA中SGA中。"


http://www.oracledatabase12g.com ... B5%81%E7%A8%8B.html

若session cached cursor 相关的cursor实体 失效或者被刷出shared pool ， 那么session cached cursor 也将失效。

Maclean Liu(刘相兵

7 楼的问题“重编译包含 session cache cursor 软软解析的数量么？”可能是  说soft soft parse 是否算在总的parse次数内，这个我们可以看下面的演示：

session 1:

SQL> select * from v$version;

BANNER
----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - 64bi
PL/SQL Release 10.2.0.1.0 - Production
CORE    10.2.0.1.0      Production
TNS for Linux: Version 10.2.0.1.0 - Production
NLSRTL Version 10.2.0.1.0 - Production


SQL> set serveroutput on
SQL> set linesize 200 pagesize 1400
SQL> set time on
21:09:28 SQL> declare
21:09:28   2    l_audsid number;
21:09:28   3    l_sid    number;
21:09:28   4    l_serial number;
21:09:28   5    l_module varchar2(128);
21:09:28   6    l_pid    number;
21:09:28   7    l_spid   number;
21:09:28   8    l_trace  varchar2(2000);
21:09:28   9    l_user   varchar2(128);
21:09:28  10  begin
  DBMS_APPLICATION_INFO.SET_MODULE(module_name => 'Maclean Liu OppO',
21:09:28  11  21:09:28  12                                     action_name => 'ACTIVE');
21:09:28  13    select audsid, sid, SERIAL#, module,username
21:09:28  14      into l_audsid, l_sid, l_serial, l_module,l_user
21:09:28  15      from v$session
21:09:28  16     where sid = (select distinct sid from v$mystat);
21:09:28  17    select pid, spid
21:09:28  18      into l_pid, l_spid
21:09:28  19      from v$process
21:09:28  20     where addr = (select paddr
21:09:28  21                     from v$session
21:09:28  22                    where sid = l_sid
                    and serial# = l_serial);
21:09:28  23  21:09:28  24    SELECT d.VALUE || '/' || LOWER(RTRIM(i.INSTANCE, CHR(0))) || '_ora_' ||
21:09:28  25           p.spid || '.trc'
21:09:28  26      into l_trace
21:09:28  27      FROM (SELECT p.spid
21:09:28  28              FROM v$mystat m, v$session s, v$process p
21:09:28  29             WHERE m.statistic# = 1
21:09:28  30               AND s.SID = m.SID
21:09:28  31               AND p.addr = s.paddr) p,
21:09:28  32           (SELECT t.INSTANCE
21:09:28  33              FROM v$thread t, v$parameter v
21:09:28  34             WHERE v.NAME = 'thread'
21:09:28  35               AND (v.VALUE = 0 OR t.thread# = TO_NUMBER(v.VALUE))) i,
21:09:28  36           (SELECT VALUE FROM v$parameter WHERE NAME = 'user_dump_dest') d;
21:09:28  37  
21:09:28  38    dbms_output.enable(9999999);
21:09:28  39    dbms_output.put_line('===============================================');
21:09:28  40    dbms_output.put_line(' USERNAME=' || l_user);
21:09:28  41    dbms_output.put_line(' SESSION ID=' || l_sid || '  SERIAL#=' || l_serial);
21:09:28  42    dbms_output.put_line(' AUDSID=' || l_audsid || '      MODULE#=' ||
21:09:28  43                         l_module);
21:09:28  44    dbms_output.put_line(' PID=' || l_pid || '          SPID#=' || l_spid);
21:09:28  45    dbms_output.put_line(' TRACE_FILE_LOCATION=' || l_trace);
21:09:28  46    dbms_output.put_line('===============================================');
21:09:28  47    commit;
21:09:28  48  end;
21:09:28  49  /
===============================================
USERNAME=SYS
SESSION ID=141  SERIAL#=142
AUDSID=4294967295      MODULE#=Maclean Liu OppO
PID=15          SPID#=581
TRACE_FILE_LOCATION=/s01/admin/G10R21/udump/g10r21_ora_581.trc
===============================================

PL/SQL procedure successfully completed.


session 1 的SID 141

session 2 监控 session 1的statistics :

SQL> set linesize 200 pagesize 2000
SQL> col name for a30
SQL> select b.name,a.value, s.username, s.sid, s.serial#
  2  from v$sesstat a, v$statname b, v$session s
  3  where a.statistic# = b.statistic#  and s.sid=a.sid
  4  and b.name in ('session cursor cache count','parse count (total)','parse count (hard)')
  5  and s.sid=141
  6  order by 1
  7  /

NAME                                VALUE USERNAME                              SID    SERIAL#
------------------------------ ---------- ------------------------------ ---------- ----------
parse count (hard)                      0 SYS                                   141        144
parse count (total)                     8 SYS                                   141        144
session cursor cache count              4 SYS                                   141        144


parse count 8
session cached cursor  4


session 1 运行以下SQL:

SQL>
SQL>      declare
  2      l_cursor  number;
  3      begin
  4      FOR i IN 1..30000 LOOP
  5              l_cursor:=dbms_sql.open_cursor;
  6              dbms_sql.parse(l_cursor,'SELECT /* LLLLL */ * FROM dual',dbms_sql.native);
  7              dbms_sql.close_cursor(l_cursor);
  8        END LOOP;
  9       end;
10       /

PL/SQL procedure successfully completed.

同一条SQL  软软解析30000次


session 2 得到的结果：


SQL> select b.name,a.value, s.username, s.sid, s.serial#
  2  from v$sesstat a, v$statname b, v$session s
  3  where a.statistic# = b.statistic#  and s.sid=a.sid
  4  and b.name in ('session cursor cache count','parse count (total)','parse count (hard)')
  5  and s.sid=141
  6  order by 1
  7  /

NAME                                VALUE USERNAME                              SID    SERIAL#
------------------------------ ---------- ------------------------------ ---------- ----------
parse count (hard)                      0 SYS                                   141        144
parse count (total)                 30009 SYS                                   141        144
session cursor cache count              5 SYS                                   141        144

session cursor cache 多cache 了一个cursor from 4 => 5
parse count    8=> 30009

说明了 soft soft parse 软软解析 算在parse count(total)之内

syp4869

Maclean:
         那些语句有没可能是SMON进程在清理OBJ$等表而执行的呢？我看过你博客上对于SMON功能的介绍，感觉有些相似。因为这个数据库昨天一直都在删除一些临时表的。
         如果是某个进程以X mode长时间持有某object的library cache lock，那么那个进程可能在进行哪些操作呢？