浅谈library cache里的争用(一)

library cache相关的争用都出自于语句解析阶段，我们今天要讨论的是其中较为常见的一个场景，那就是两个会话同时执行同一条SQL语句时到底会发生哪些争用，对应的等待事件是什么，随着语句的不断执行，这些等待事件是如何一步步演变的。

先准备一下实验环境：

###建表

---connect ad/Uiop246!

create table t1 as select * from all_users;

###清空Share pool

---connect as sysdba

alter system flush shared_pool;

###实验用到的script

/////////////////////////////////////

////    测试sql： sql_exec.sql   ////

/////////////////////////////////////

declare

v_sql varchar2(1000);

int_cur number;

v_rows number;

v_sec number;

begin

select extract(second from to_timestamp(to_char(sysdate,'yyyymmdd hh24:mi:ss'),'yyyymmdd hh24:mi:ss')) into v_sec from dual;

while ( v_sec <> 30 ) loop

select extract(second from to_timestamp(to_char(sysdate,'yyyymmdd hh24:mi:ss'),'yyyymmdd hh24:mi:ss')) into v_sec from dual;

end loop;

dbms_output.put_line('begin_time:'||sysdate);

int_cur:=dbms_sql.open_cursor;

for i in 1..50000 loop

v_sql:='select * from t1 where user_id='||i;

dbms_sql.parse(int_cur,v_sql,dbms_sql.native);

v_rows:=dbms_sql.execute(int_cur);

end loop;

dbms_output.put_line('end_time:'||sysdate);

end;

/

/////////////////////////////////////

////  统计用：sess_1st.sql       ////

/////////////////////////////////////

define v_sid1=&1

define v_sid2=&2

drop table sess_stat_1st;

drop table sess_evt_1st;

create table sess_stat_1st as select sn.name,se.sid,se.value from v$sesstat se,v$statname sn where se.sid in (&v_sid1,&v_sid2) and se.statistic#=sn.statistic# and sn.name like '%parse%';

create table sess_evt_1st as select sid,event,total_waits from v$session_event where sid in (&v_sid1,&v_sid2) order by sid,event;

/////////////////////////////////////

////  统计用：sess_2nd.sql       ////

/////////////////////////////////////

define v_sid1=&1

define v_sid2=&2

drop table sess_stat_2nd;

drop table sess_evt_2nd;

create table sess_stat_2nd as select sn.name,se.sid,se.value from v$sesstat se,v$statname sn where se.sid in (&v_sid1,&v_sid2) and se.statistic#=sn.statistic# and sn.name like '%parse%';

create table sess_evt_2nd as select sid,event,total_waits from v$session_event where sid in (&v_sid1,&v_sid2) order by sid,event;

col event format a30

set linesize 120  pagesize 60

select nd.sid,nd.event,nd.total_waits-nvl(st.total_waits,0) diff_waits from sess_evt_1st st,sess_evt_2nd nd where st.sid(+)=nd.sid and st.event(+)=nd.event order by event,sid;

select nd.sid,nd.name,nd.value-nvl(st.value,0) diff_stats from sess_stat_2nd nd,sess_stat_1st st where st.name(+)=nd.name and nd.sid=st.sid(+);

实验开始时我们要执行的语句还没有在shared pool里，也就是要从硬解析开始！

<<<< 1、硬解析的情况：当要执行的语句不在library cache里的时候，两个session同时执行相同的语句时必有一个session会进行硬解析 >>>>

###记录session 1 & session 2的会话信息

---session 1: ad/Uiop246!

set linesize 100

select a.sid,a.serial#,b.spid from v$session a,v$process b where a.paddr=b.addr and a.audsid=sys_context('userenv','sessionid');

       SID    SERIAL# SPID

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

      3307       1987 6160700

---session 2: ad/Uiop246!

set linesize 100

select a.sid,a.serial#,b.spid from v$session a,v$process b where a.paddr=b.addr and a.audsid=sys_context('userenv','sessionid');

       SID    SERIAL# SPID

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

      6605       1185 14549288

###两session第一轮执行该语句

---session 3：先记录session 1 & session 2的初始值等待事件及统计值

@sess_1st.sql 3307 6605

---session 1:

@sql_exec.sql

begin_time:20160327 16:42:30

end_time:20160327 16:43:32

---session 2:

@sql_exec.sql

begin_time:20160327 16:42:30

end_time:20160327 16:43:32

耗时显示两session硬解析耗时均为62秒

---session 3：显示session 1 & session 2首次执行期间产生的等待事件及parse相关统计值

@sess_2nd.sql 3307 6605

       SID EVENT                          DIFF_WAITS

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

      3307 Disk file operations I/O                0

      6605 Disk file operations I/O                2

      3307 SQL*Net message from client             2

      6605 SQL*Net message from client             2

      3307 SQL*Net message to client               2

      6605 SQL*Net message to client               2

      3307 cursor: mutex X                         4

      3307 cursor: pin S                          49

      6605 cursor: pin S                          62

      3307 cursor: pin S wait on X              2206

      6605 cursor: pin S wait on X              2485

      3307 db file sequential read                 0

      6605 db file sequential read                 2

      3307 events in waitclass Other              39

      6605 events in waitclass Other             110

      3307 latch: shared pool                      1

      3307 library cache load lock               481

      6605 library cache load lock               474

      3307 library cache lock                    456

      6605 library cache lock                    477

      3307 library cache: mutex X               1723

      6605 library cache: mutex X               1470

       SID NAME                                                             DIFF_STATS

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

      6605 parse time cpu                                                         3048

      3307 parse time cpu                                                         3658

      6605 parse time elapsed                                                     6174

      3307 parse time elapsed                                                     6248

      6605 parse count (total)                                                   50016

      3307 parse count (total)                                                   50007

      6605 parse count (hard)                                                    22428

      3307 parse count (hard)                                                    27575

      6605 parse count (failures)                                                    0

      3307 parse count (failures)                                                    0

      6605 parse count (describe)                                                    0

      3307 parse count (describe)                                                    0

等待事件里出现最多的是cursor: pin S wait on X，因为Session 1 & session 2运行的语句都是相同的，且是同一时刻发起，相同语句被两个session同时执行的概率是很大的，这过程中必定有一个session执行的是硬解析，另一个执行的是软解析；比如session 1正在硬解析语句select * from t1 where user_id=1，硬解析的时候对于子游标需要以独占模式持有cursor pin类型的mutex，这时session 2也要执行该语句，那么它需要申请以共享模式在这个子游标上持有cursor pin类型的mutex，独占模式是排它的，所以session 2就等待在了"cursor: pin S wait on X"事件上，直到session 1完成硬解析，session 2才能获得共享的cursor pin型mutex。因此"cursor: pin S wait on X"的成因是：在session 1 & session 2同时运行相同的语句，其中一个session正在硬解析，另一个请求软解析的session就会等待在"cursor: pin S wait on X"事件上。

再来看看解析有关的指标parse count (hard)，两个session分别承担了22428、27575次硬解析，硬解析的总和50003次，接近5W次，对于特定的一条SQL来说若在session 1里进行了硬解析那么在session 2必定是软解析。

仔细思考一下parse count (hard)与cursor: pin S wait on X其实有一定的内在联系：parse count (hard)值小的Session其cursor: pin S wait on X等待次数往往会更多，在以上的输出中sid：6605的硬解析次数为22428，剩下的有27572次都是软解析，之所以这27572次都能做到软解析是因为其共享了sid:3307执行27575次硬解析后的结果，sid:6605执行软解析申请共享模式cursor pin mutex过程中就会更容易被sid:3307硬解析时持有的独占cursor pin mutex所阻塞；反观sid:3307的硬解析次数为27575，剩余的22425次都是软解析，软解析次数较sid:3307要少，因此其遇到cursor: pin S wait on X的几率自然就小很多了，所以说硬解析次数少(或者说软解析次数多)的session在cursor: pin S wait on X事件上的等待次数会比较多。

library cache lock与library cache load lock事件对应的争用对象主要集中在父、子游标以及表上，也是由于两session并发所导致的争用，只要有解析，不管是硬解析还是软解析(软软解析除外)，都会在执行过程中申请library cache lock资源，一旦申请的过程中与其它session发生争抢，就会遇到这两类等待

少量的cursor: pin S事件来自于sql_exec.sql脚本里的” select extract(second from to_timestamp(to_char(sysdate,'yyyymmdd hh24:mi:ss'),'yyyymmdd hh24:mi:ss')) into v_sec from dual”语句。在此不多讨论，后面会有介绍到cursor: pin S。

至此，每条语句都被执行了至少两遍，接下来就应该是软解析了。

<<<<<<<<<<<< 2、软解析的情况：当语句都被执行过一遍后，接下来的都是软解析了 >>>>>>>>>>>>>

###确认Sql还在shared pool里

select count(*) from v$sql where sql_text like 'select * from t1 where user_id=%';

  COUNT(*)

----------

     50001

###两session第二轮执行该语句，因为都在shared pool里所以这次应该都是软解析    

---session 3:执行前先统计session 1 & session 2的当前值

@sess_1st.sql 3307 6605

---session 1:

@sql_exec.sql

begin_time:20160327 16:54:30

end_time:20160327 16:54:33

---session 2:

@sql_exec.sql

begin_time:20160327 16:54:30

end_time:20160327 16:54:33

---session 3: 显示session 1 & session 2 第二轮执行期间产生的等待事件及parse相关统计值

@sess_2nd.sql 3307 6605

       SID EVENT                          DIFF_WAITS

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

      3307 Disk file operations I/O                0

      6605 Disk file operations I/O                0

      3307 SQL*Net message from client             2

      6605 SQL*Net message from client             2

      3307 SQL*Net message to client               2

      6605 SQL*Net message to client               2

      3307 cursor: mutex X                         0

      3307 cursor: pin S                          18

      6605 cursor: pin S                          18

      3307 cursor: pin S wait on X                 0

      6605 cursor: pin S wait on X                 0

      3307 db file sequential read                 0

      6605 db file sequential read                 0

      3307 events in waitclass Other               0

      6605 events in waitclass Other               0

      3307 latch: shared pool                      0

      3307 library cache load lock                 0

      6605 library cache load lock                 0

      3307 library cache lock                      0

      6605 library cache lock                      0

      3307 library cache: mutex X               9658   <---软解析时library cache:mutex X事件居多

      6605 library cache: mutex X               8130

22 rows selected.

       SID NAME                                                             DIFF_STATS

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

      6605 parse time cpu                                                          114

      3307 parse time cpu                                                          140

      6605 parse time elapsed                                                      126

      3307 parse time elapsed                                                      128

      6605 parse count (total)                                                   50001

      3307 parse count (total)                                                   50002

      6605 parse count (hard)                                                        0

      3307 parse count (hard)                                                        0

      6605 parse count (failures)                                                    0

      3307 parse count (failures)                                                    0

      6605 parse count (describe)                                                    0

      3307 parse count (describe)                                                    0

这次parse count (hard)值为0，等待事件里"library cache: mutex X"占大头，搜索hash链表寻找父游标句柄的时候需要"library cache: mutex X"的保护，找到父游标句柄后访问句柄内容的时候需要"library cache: mutex X"的保护，同样在访问子游标句柄内容的时候也需要申请"library cache: mutex X"，"X"表示以独占模式持有，所以两个session同时运行特定的SQL，在寻找父游标句柄、访问父游标与子游标句柄内容的时候是串行的，等前一个session释放了"library cache: mutex X"，后一个session才能申请"library cache: mutex X"。

至此，每条语句至少被执行了四遍，下面我们等待软软解析的出现

<<<<<<<<<<<< 3、预料中的软软解析并未出现  >>>>>>>>>>>>>

###两Session第三轮执行语句后的等待事件及parse统计值

---session 3:执行前先统计session 1 & session 2的当前值

@sess_1st.sql 3307 6605

---session 1:

@sql_exec.sql

begin_time:20160327 16:57:30

end_time:20160327 16:57:33

---session 2:

@sql_exec.sql

begin_time:20160327 16:57:30

end_time:20160327 16:57:33

---session 3: 显示session 1 & session 2 第三轮执行期间产生的等待事件及parse相关统计值

@sess_2nd.sql 3307 6605

       SID EVENT                          DIFF_WAITS

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

      3307 Disk file operations I/O                0

      6605 Disk file operations I/O                0

      3307 SQL*Net message from client             2

      6605 SQL*Net message from client             2

      3307 SQL*Net message to client               2

      6605 SQL*Net message to client               2

      3307 cursor: mutex X                         0

      3307 cursor: pin S                           9

      6605 cursor: pin S                          14

      3307 cursor: pin S wait on X                 0

      6605 cursor: pin S wait on X                 0

      3307 db file sequential read                 0

      6605 db file sequential read                 0

      3307 events in waitclass Other               0

      6605 events in waitclass Other               0

      3307 latch: shared pool                      0

      3307 library cache load lock                 0

      6605 library cache load lock                 0

      3307 library cache lock                      0

      6605 library cache lock                      0

      3307 library cache: mutex X               7039

      6605 library cache: mutex X               5837

       SID NAME                                                             DIFF_STATS

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

      6605 parse time cpu                                                          119

      3307 parse time cpu                                                          130

      6605 parse time elapsed                                                      109

      3307 parse time elapsed                                                      107

      6605 parse count (total)                                                   50002

      3307 parse count (total)                                                   50002

      6605 parse count (hard)                                                        0

      3307 parse count (hard)                                                        0

      6605 parse count (failures)                                                    0

      3307 parse count (failures)                                                    0

      6605 parse count (describe)                                                    0

      3307 parse count (describe)                                                    0

至此已经执行了三轮，5W条sql里的绝大部分都被解析了6次，执行了6次，等待事件和第二轮一样以"library cache: mutex X"为主

SQL> select parse_calls,executions,count(1) from v$sql where sql_text like 'select * from t1 where user_id=%' group by parse_calls,executions;

PARSE_CALLS EXECUTIONS   COUNT(1)

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

          4          6          3

          5          5         32

          5          6        586

          6          4          5

          6          5        770

          6          6      48604

         27         27          1

只要有解析，即便是软解析也是要在对象上加lock和pin的，lock和pin前也要先获取相应的mutex，因此亦会产生一定的开销，解析1次执行n次的软软解析才是效率最高的，要实现软软解析必须要求session_cached_Cursor设置的足够大，在我们这个数据库里Session_cached_cursor只设置成20，值太小所以无法缓冲更多的cursor以实现软软解析，大部分sql的parse_calls与executions数量一样，仍然是parse一次execute一次

SQL> show parameter session_Cached_cursor

NAME                                 TYPE        VALUE

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

session_cached_cursors               integer     20

<<<<<<<<<<<< 4、调大session_cached_cursor，软解析的同时将cursor缓冲至PGA  >>>>>>>>>>>>>

下面我们分别在session 1和session 2中把session_cached_cursors设置成50200

---session 1:

SQL> alter session set session_cached_cursors=50200;   

Session altered.

---session 2:

SQL> alter session set session_cached_cursors=50200;

Session altered.

###两session第四轮执行该语句

---session 3:执行前先统计session 1 & session 2的当前值

@sess_1st.sql 3307 6605

---session 1:

@sql_exec.sql

begin_time:20160327 17:04:30

end_time:20160327 17:06:31

---session 2:

@sql_exec.sql

begin_time:20160327 17:04:30

end_time:20160327 17:06:30

我们发现把session_cached_cursor调大后，语句执行事件从前一次执行时的3秒增加到了120秒，这是因为需要把5W条的SQL依次缓存进PGA，缓存的这一次是比较慢的，后面再执行就很快了，正所谓磨刀不误砍柴工

---session 3:

@sess_2nd.sql 3307 6605

       SID EVENT                          DIFF_WAITS

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

      3307 Disk file operations I/O                0

      6605 Disk file operations I/O                0

      3307 SQL*Net message from client             2

      6605 SQL*Net message from client             2

      3307 SQL*Net message to client               2

      6605 SQL*Net message to client               2

      3307 cursor: mutex X                         0

      3307 cursor: pin S                          62

      6605 cursor: pin S                          69

      3307 cursor: pin S wait on X                 0

      6605 cursor: pin S wait on X                 0

      3307 db file sequential read                 0

      6605 db file sequential read                 0

      3307 events in waitclass Other               0

      6605 events in waitclass Other               0

      3307 latch: shared pool                      0

      3307 library cache load lock                 0

      6605 library cache load lock                 0

      3307 library cache lock                      0

      6605 library cache lock                      0

      3307 library cache: mutex X                 15        <---library cache:mutex X次数少了

      6605 library cache: mutex X                 16

       SID NAME                                                             DIFF_STATS

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

      6605 parse time cpu                                                        11533

      3307 parse time cpu                                                        11535

      6605 parse time elapsed                                                    11611

      3307 parse time elapsed                                                    11701

      6605 parse count (total)                                                   49984

      3307 parse count (total)                                                   49984

      6605 parse count (hard)                                                        0

      3307 parse count (hard)                                                        0

      6605 parse count (failures)                                                    0

      3307 parse count (failures)                                                    0

      6605 parse count (describe)                                                    0

      3307 parse count (describe)                                                    0

v$open_cursor里的cursor_type是OPEN-RECURSIVE，并不是我们所熟悉的"SESSION CURSOR CACHED"，可能与我们使用dbms_sql包执行sql有关系

SQL> select sid,cursor_type,count(1) from v$open_cursor where sid in (3307,6605) group by sid,cursor_type;

       SID CURSOR_TYPE                                                        COUNT(1)

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

      3307 OPEN                                                                      1

      3307 OPEN-RECURSIVE                                                        50003

      3307 PL/SQL CURSOR CACHED                                                      1

      3307 SESSION CURSOR CACHED                                                     3

      6605 OPEN                                                                      1

      6605 OPEN-RECURSIVE                                                        50003

      6605 PL/SQL CURSOR CACHED                                                      1

      6605 SESSION CURSOR CACHED                                                     3

SQL> select parse_calls,executions,count(1) from v$sql where sql_text like 'select * from t1 where user_id=%' group by parse_calls,executions;

PARSE_CALLS EXECUTIONS   COUNT(1)

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

          6          8         20

          7          7         32

          7          8        587

          8          6          5

          8          7        770

          8          8      48586  <---executions=parse_calls，说明还是软解析

         27         27          1

第四轮的执行还是软解析，整个过程中几乎没有明显的等待事件，时间都耗在了cache游标到PGA的过程中

<<<<<<<<<<<<  5、软软解析来了  >>>>>>>>>>>>>

###两session第五轮执行该语句

@sess_1st.sql 3307 6605

---session 1:

@sql_exec.sql

begin_time:20160327 17:12:30

end_time:20160327 17:12:32

---session 2:

@sql_exec.sql

begin_time:20160327 17:12:30

end_time:20160327 17:12:32

---session 3:

@sess_2nd.sql 3307 6605     

       SID EVENT                          DIFF_WAITS

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

      3307 Disk file operations I/O                0

      6605 Disk file operations I/O                0

      3307 SQL*Net message from client             2

      6605 SQL*Net message from client             2

      3307 SQL*Net message to client               2

      6605 SQL*Net message to client               2

      3307 cursor: mutex X                         0

      3307 cursor: pin S                         478

      6605 cursor: pin S                         669

      3307 cursor: pin S wait on X                 0

      6605 cursor: pin S wait on X                 0

      3307 db file sequential read                 0

      6605 db file sequential read                 0

      3307 events in waitclass Other               0

      6605 events in waitclass Other               0

      3307 latch: shared pool                      0

      3307 library cache load lock                 0

      6605 library cache load lock                 0

      3307 library cache lock                      0

      6605 library cache lock                      0

      3307 library cache: mutex X                  2

      6605 library cache: mutex X                  0

       SID NAME                                                             DIFF_STATS

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

      6605 parse time cpu                                                           59

      3307 parse time cpu                                                           51

      6605 parse time elapsed                                                       73

      3307 parse time elapsed                                                       65

      6605 parse count (total)                                                       1    <---解析次数接近0

      3307 parse count (total)                                                       1

      6605 parse count (hard)                                                        0

      3307 parse count (hard)                                                        0

      6605 parse count (failures)                                                    0

      3307 parse count (failures)                                                    0

      6605 parse count (describe)                                                    0

      3307 parse count (describe)                                                    0

select parse_calls,executions,count(1) from v$sql where sql_text like 'select * from t1 where user_id=%' group by parse_calls,executions;

PARSE_CALLS EXECUTIONS   COUNT(1)

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

          6          9          2

          6         10         18

          7          9         72

          7         10        547

          8          8         53

          8          9       3538

          8         10      45769   <---executions增加，parse_calls不变，说明已经是软软解析了

         10         10          1

         27         27          1

在第五轮的执行中，终于出现了软软解析，耗时仅2秒，由于子游标的执行计划已经被缓冲到了PGA，所以语句执行期间只要以共享模式获得"cursor: pin S"类型的mutex就能轻松访问到PGA里的执行计划。

<<<<<<<<<<<<  6、往后的都是软软解析了  >>>>>>>>>>>>>

###两session第六轮执行该语句

@sess_1st.sql 3307 6605

---session 1:

@sql_exec.sql

begin_time:20160327 17:17:30

end_time:20160327 17:17:32

---session 2:

@sql_exec.sql

begin_time:20160327 17:17:30

end_time:20160327 17:17:32

---session 3:

@sess_2nd.sql 3307 6605              

       SID EVENT                          DIFF_WAITS

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

      3307 Disk file operations I/O                0

      6605 Disk file operations I/O                0

      3307 SQL*Net message from client             2

      6605 SQL*Net message from client             2

      3307 SQL*Net message to client               2

      6605 SQL*Net message to client               2

      3307 cursor: mutex X                         0

      3307 cursor: pin S                         520

      6605 cursor: pin S                         597

      3307 cursor: pin S wait on X                 0

      6605 cursor: pin S wait on X                 0

      3307 db file sequential read                 0

      6605 db file sequential read                 0

      3307 events in waitclass Other               0

      6605 events in waitclass Other               0

      3307 latch: shared pool                      0

      3307 library cache load lock                 0

      6605 library cache load lock                 0

      3307 library cache lock                      0

      6605 library cache lock                      0

      3307 library cache: mutex X                  3

      6605 library cache: mutex X                  0

       SID NAME                                                             DIFF_STATS

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

      6605 parse time cpu                                                           69

      3307 parse time cpu                                                           52

      6605 parse time elapsed                                                       56

      3307 parse time elapsed                                                       56

      6605 parse count (total)                                                       1

      3307 parse count (total)                                                       1

      6605 parse count (hard)                                                        0

      3307 parse count (hard)                                                        0

      6605 parse count (failures)                                                    0

      3307 parse count (failures)                                                    0

      6605 parse count (describe)                                                    0

      3307 parse count (describe)                                                    0       

SQL> select parse_calls,executions,count(1) from v$sql where sql_text like 'select * from t1 where user_id=%' group by parse_calls,executions;

PARSE_CALLS EXECUTIONS   COUNT(1)

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

          6         11          3

          6         12         17

          7         10          4

          7         11         86

          7         12        529

          8         10        253

          8         11       5174

          8         12      43933

         12         12          1

         27         27          1

总结一下：