[20130628]关于cursor pin S以及cursor pin S wait on X的相关问题.txt

[20130628]关于cursor pin S以及cursor pin S wait on X的相关问题.txt

生产系统最近一段时间总是出现cursor pin S wait on X,以前从来没有遇到,今天抽空看了一下.
了解关于cursor pin S以及cursor pin S wait on X的相关问题，我看了一些链接：

http://www.pythian.com/blog/cursor-pin-s-wait-on-x-in-the-top-5-wait-events/
http://www.pythian.com/blog/locks-latches-mutexes-and-cpu-usage/
http://www.itpub.net/thread-1799136-1-1.html

--讨论时思路有点，现在总结一下，也许依旧存在许多错误!
1.我的测试环境：
SQL> @ver
BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production

$ cat mutex_load.sh
N=1 ;
until test "$N" -gt "5";
do
    echo $N
    sqlplus /nolog @soft_parse.sql &
    sleep 1
    N=`expr $N + 1`
done

$ cat soft_parse.sql
connect scott/tiger
begin
for i in 1..4000000 loop
    execute immediate 'select 1234567890 from dual';
end loop;
end;
/
Exit

--说明：例子来自http://www.pythian.com/blog/locks-latches-mutexes-and-cpu-usage/,我做了一些修改。
--如果你的测试cpu很多，修改前面的"5",比cpu数量大就可以了。

2.测试如下：
执行如下:
exec   dbms_workload_repository.create_snapshot();
source  mutex_load.sh
等待结束
exec   dbms_workload_repository.create_snapshot();

3.查看awr报表：

Top 5 Timed Foreground Events

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

                                                           Avg                  

                                                          wait   % DB           

Event                                 Waits     Time(s)   (ms)   time Wait Class

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

DB CPU                                            1,327          78.3           

cursor: pin S                         4,573          80     18    4.7 Concurrenc

log file sync                            31           2     77     .1 Commit    

db file sequential read                 504           0      0     .0 User I/O  

SQL*Net more data to client              43           0      0     .0 Network   

--主要消耗在cursor: pin S.问题是执行的语句都是一样的.可见cursor: pin S是相同的语句大量频繁的执行。

4.查看v$mutex_sleep_history视图：

SELECT   mutex_identifier, mutex_type, MAX (gets), MAX (sleeps), mutex_value

    FROM v$mutex_sleep_history

   WHERE mutex_type = 'Cursor Pin' AND mutex_identifier = 1579191250

GROUP BY mutex_identifier, mutex_type, mutex_value

ORDER BY 3, 4;

MUTEX_IDENTIFIER MUTEX_TYPE                        MAX(GETS) MAX(SLEEPS) MUTEX_VALUE

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

      1579191250 Cursor Pin                          3904488         106 0000000D00000000

      1579191250 Cursor Pin                          6998293         297 0000000000000001

      1579191250 Cursor Pin                         45680895        1572 0000000000000003

      1579191250 Cursor Pin                         47411444        1375 0000004800000001

      1579191250 Cursor Pin                         47438126        1320 0000000000000002

      1579191250 Cursor Pin                         47968120        1311 00

6 rows selected.

--mutex_identifier=1579191250,对应sql语句的hash_value数值。
--补充1点，10G下这个视图这样查询mutex_type = 'Cursor Pin'没有结果，主要是

SQL> select dump(mutex_type) from v$mutex_sleep_history where substr(mutex_type,1,10)='Cursor Pin' and rownum

DUMP(MUTEX_TYPE)

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

Typ=1 Len=32: 67,117,114,115,111,114,32,80,105,110,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0

--这才发现10g版本后面有1串chr(0).我对比11G没有这个问题,估计是bug.
--10G执行修改如下:

SELECT   mutex_identifier, mutex_type, MAX (gets), MAX (sleeps), mutex_value

    FROM v$mutex_sleep_history

   WHERE mutex_type = 'Cursor Pin' OR SUBSTR (mutex_type, 1, 10) = 'Cursor Pin'

GROUP BY mutex_identifier, mutex_type, mutex_value

ORDER BY 4 DESC;

--查询内部x$mutex_sleep_history视图。

SELECT   mutex_addr, mutex_identifier, mutex_type, MAX (gets), MAX (sleeps), mutex_value

    FROM x$mutex_sleep_history where mutex_identifier=1579191250

GROUP BY mutex_addr, mutex_identifier, mutex_type, mutex_value

ORDER BY 5 DESC, 4

MUTEX_ADDR       MUTEX_IDENTIFIER MUTEX_TYPE                        MAX(GETS) MAX(SLEEPS) MUTEX_VALUE

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

00000000AEFB16C8       1579191250 Cursor Pin                         45680895        1572 0000000000000003

00000000AEFB16C8       1579191250 Cursor Pin                         47411444        1375 0000004800000001

00000000AEFB16C8       1579191250 Cursor Pin                         47438126        1320 0000000000000002

00000000AEFB16C8       1579191250 Cursor Pin                         47968120        1311 00

00000000AEFB16C8       1579191250 Cursor Pin                          6998293         297 0000000000000001

00000000AEFB16C8       1579191250 Cursor Pin                          3904488         106 0000000D00000000

6 rows selected.

--前面4位表示回话的sid，后面是是"引用计数"或模式。
--知道该语句的MUTEX_ADDR，如果人为的修改这个地址的内存值(MUTEX_VALUE)，看看情况如何呢？注意我现在没有执行对应sql语句。
--该地址的内容应该为0.

5.调用oradebug修改：

SQL> oradebug setmypid
Statement processed.
SQL> oradebug poke 0x00000000AEFB16C8 8 0x4800000001
BEFORE: [0AEFB16C8, 0AEFB16D0) = 00000000 00000000
AFTER:  [0AEFB16C8, 0AEFB16D0) = 00000001 00000048
--不知道是否应该写成0x0100000048，好像从下面的p2raw显示看应该是正确的。

--打开另外的回话，执行：
SQL> select 1234567890 from dual;
--回话挂起！

SQL> set serveroutput on

SQL> exec scott.print_table('select * from v$session where event like ''cursor%''');

SADDR                         : 00000000BF861380

SID                           : 198

SERIAL#                       : 33

AUDSID                        : 3477911

PADDR                         : 00000000BF4FA9A0

USER#                         : 84

USERNAME                      : SCOTT

COMMAND                       : 3

OWNERID                       : 2147483644

TADDR                         :

LOCKWAIT                      :

STATUS                        : ACTIVE

SERVER                        : DEDICATED

SCHEMA#                       : 84

SCHEMANAME                    : SCOTT

OSUSER                        : oracle11g

PROCESS                       : 5815

MACHINE                       : hisdg

PORT                          : 0

TERMINAL                      : pts/1

PROGRAM                       : sqlplus@hisdg (TNS V1-V3)

TYPE                          : USER

SQL_ADDRESS                   : 00000000B3664FD0

SQL_HASH_VALUE                : 1579191250

SQL_ID                        : 0ta1datg212yk

SQL_CHILD_NUMBER              :

SQL_EXEC_START                :

SQL_EXEC_ID                   :

PREV_SQL_ADDR                 : 00000000B3A6C668

PREV_HASH_VALUE               : 3548995700

PREV_SQL_ID                   : 7zwnax39sks3n

PREV_CHILD_NUMBER             : 0

PREV_EXEC_START               : 2013-06-28 16:27:45

PREV_EXEC_ID                  : 16777216

PLSQL_ENTRY_OBJECT_ID         :

PLSQL_ENTRY_SUBPROGRAM_ID     :

PLSQL_OBJECT_ID               :

PLSQL_SUBPROGRAM_ID           :

MODULE                        : SQL*Plus

MODULE_HASH                   : 3669949024

ACTION                        :

ACTION_HASH                   : 0

CLIENT_INFO                   :

FIXED_TABLE_SEQUENCE          : 23354

ROW_WAIT_OBJ#                 : -1

ROW_WAIT_FILE#                : 0

ROW_WAIT_BLOCK#               : 0

ROW_WAIT_ROW#                 : 0

TOP_LEVEL_CALL#               : 94

LOGON_TIME                    : 2013-06-28 15:33:09

LAST_CALL_ET                  : 235

PDML_ENABLED                  : NO

FAILOVER_TYPE                 : NONE

FAILOVER_METHOD               : NONE

FAILED_OVER                   : NO

RESOURCE_CONSUMER_GROUP       :

PDML_STATUS                   : DISABLED

PDDL_STATUS                   : ENABLED

PQ_STATUS                     : ENABLED

CURRENT_QUEUE_DURATION        : 0

CLIENT_IDENTIFIER             :

BLOCKING_SESSION_STATUS       : UNKNOWN

BLOCKING_INSTANCE             :

BLOCKING_SESSION              :

FINAL_BLOCKING_SESSION_STATUS : UNKNOWN

FINAL_BLOCKING_INSTANCE       :

FINAL_BLOCKING_SESSION        :

SEQ#                          : 1038

EVENT#                        : 280

EVENT                         : cursor: pin S

P1TEXT                        : idn

P1                            : 1579191250

P1RAW                         : 000000005E208BD2

P2TEXT                        : value

P2                            : 309237645313

P2RAW                         : 0000004800000001

P3TEXT                        : where

P3                            : 21474836480

P3RAW                         : 0000000500000000

WAIT_CLASS_ID                 : 3875070507

WAIT_CLASS#                   : 4

WAIT_CLASS                    : Concurrency

WAIT_TIME                     : 0

SECONDS_IN_WAIT               : 236

STATE                         : WAITING

WAIT_TIME_MICRO               : 235628840

TIME_REMAINING_MICRO          : -1

TIME_SINCE_LAST_WAIT_MICRO    : 0

SERVICE_NAME                  : SYS$USERS

SQL_TRACE                     : DISABLED

SQL_TRACE_WAITS               : FALSE

SQL_TRACE_BINDS               : FALSE

SQL_TRACE_PLAN_STATS          : FIRST EXEC

SESSION_EDITION_ID            : 100

CREATOR_ADDR                  : 00000000BF4FA9A0

CREATOR_SERIAL#               : 9

ECID                          :

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

PL/SQL procedure successfully completed.

--可以发现等待事件： cursor: pin S。P1: 1579191250,P2RAW : 0000004800000001.

SQL> oradebug poke 0x00000000AEFB16C8 8 0x0

--sql语句完成！另外这样会产生一个子光标。

SQL> @dpc '' ''

PLAN_TABLE_OUTPUT

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

SQL_ID  0ta1datg212yk, child number 1

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

select 1234567890 from dual

Plan hash value: 1388734953

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

| Id  | Operation        | Name | E-Rows | Cost (%CPU)|

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

|   0 | SELECT STATEMENT |      |        |     2 (100)|

|   1 |  FAST DUAL       |      |      1 |     2   (0)|

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

SQL> @share 0ta1datg212yk

SQL_TEXT                       = select 1234567890 from dual

SQL_ID                         = 0ta1datg212yk

ADDRESS                        = 00000000B3664FD0

CHILD_ADDRESS                  = 00000000B3664B70

CHILD_NUMBER                   = 0

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

SQL_TEXT                       = select 1234567890 from dual

SQL_ID                         = 0ta1datg212yk

ADDRESS                        = 00000000B3664FD0

CHILD_ADDRESS                  = 00000000B39E9800

CHILD_NUMBER                   = 1

TOP_LEVEL_RPI_CURSOR           = Y

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

PL/SQL procedure successfully completed.

--原因是TOP_LEVEL_RPI_CURSOR，TOP_LEVEL_RPI_CURSOR     Is top level RPI cursor,链接http://psoug.org/reference/cursor_sharing.html。
--不知道什么东西？？？？


6.接着测试：

SQL> oradebug poke 0x00000000AEFB16C8 8 0x4800000001
BEFORE: [0AEFB16C8, 0AEFB16D0) = 00000000 00000000
AFTER:  [0AEFB16C8, 0AEFB16D0) = 00000001 00000048

--回到回话在执行如下：
SQL> select 1234567890 from dual;
1234567890
----------
1234567890

--OK没有问题！但是如果执行如下

begin
execute immediate 'select 1234567890 from dual';
end;
/

--回话再次挂起！为什么呢？查看等待事件依旧是cursor: pin S。
--小结一下：
--第1次执行的sql_id一样的，但是这条语句要生成新的子光标，由于锁定了MUTEX_ADDR=0x00000000AEFB16C8的值，这样必须等待。
--而第2次执行相同的语句，因为子光标已经生成，锁定了MUTEX_ADDR=0x00000000AEFB16C8的值,无法解析。。。。期待高手解析。
--但是当执行execute immediate 'select 1234567890 from dual';效果就和前面一样了。

7.cursor: pin S Wait On X的模拟。
--前面都没有模拟出cursor: pin S Wait On X，按照前面的链接，应该是硬解析太多，version_count太高(也就是每次生成计划时,
--生成子光标，这个时候要锁定这个链，应该出现cursor: pin S Wait On X这种情况)，这样看到现象是版本太高，如何测试
--想起这个链接http://www.antognini.ch/2012/10/how-many-children-can-a-parent-cursor-have-1000000/

$ cat  mutex_load1.sh
N=1 ;
until test "$N" -gt "5";
do
    echo $N
    sqlplus scott/tiger @soft_parse1.sql &
    sleep 1
    N=`expr $N + 1`
done

$ cat  soft_parse1.sql
DECLARE
    l_count PLS_INTEGER;
BEGIN
    FOR i IN 1..100
    LOOP
    EXECUTE IMMEDIATE 'ALTER SESSION SET optimizer_index_caching = '||i;
    FOR j IN 1..100
    LOOP
        EXECUTE IMMEDIATE 'ALTER SESSION SET optimizer_index_cost_adj = '||j;
        EXECUTE IMMEDIATE 'SELECT 12345 FROM dual' ;
    END LOOP;
    END LOOP;
END;
/

--这样环境变量不一样，会生成许多子光标。看看结果如何呢。为了测试准确，最好重启数据库来测试：

执行如下:
exec   dbms_workload_repository.create_snapshot();
source  mutex_load1.sh
等待结束
exec   dbms_workload_repository.create_snapshot();

--测试的中间我看了：

select event,a.* from v$session a where event like 'cursor%';

显示的都是cursor: pin S wait on X等待事件。看看awr报表如何：

Top 5 Timed Foreground Events

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

                                                           Avg                  

                                                          wait   % DB           

Event                                 Waits     Time(s)   (ms)   time Wait Class

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

cursor: pin S wait on X              10,939         116     11   39.3 Concurrenc

DB CPU                                              103          35.0           

kksfbc child completion               1,322          67     51   22.7 Other     

library cache: mutex X                1,216           4      3    1.3 Concurrenc

library cache lock                    2,777           2      1     .7 Concurrenc

8.补充vage的内容：
http://www.itpub.net/thread-1799136-1-1.html
在10.2.0.4中，如果只有cursor: pin S、cursor: pin S Wait On X，是软软解析过多，不是硬解析。
因为软软解析时，只需要cursor: Pin S，其他什么都不需要。只有cursor: Pin S和cursor: Pin S Wait X竞争过高的话，一定是软软解析的问题。

软软解析时的cursor: Pin S wait on X，是10G下统计信息错误的一个小BUG，在11GR2后已经修证。具体来说，就是把本应显示为cursor: Pin S等待事件的，错误的显示为cursor: Pin S Wait On X等待事件了。

为什么会有这样的错误，以last_day_1983 粘上来的结果为例，他的P2RAW是0000001F00000000，这一串16进制字就是Mutex_Value，也可以在v$mutex_sleep_history中找到。这串值就是将来要传进Mutex内存位的值，因此Oracle称它为Mutex_value。

它的前一半（高位）：0000001F，是要加Mutex的会话的SID，这里也就是31号会话。31号会话要申请Mutex。后一半（低位）是"引用计数"或模式。

如果是独占Mutex，高位的SID部分将一直是持有Mutex的会话SID，低位模式（或称引用计数）部分一直是0。

如果是共享Mutex，只在申请Mutex过程中，高位的SID部分是SID。同时将引用计数加1。一旦已经成功申请共享Mutex，高位的SID部分将清0。释放的时候也一样，释放过程中，先将SID传进高位的SID部分，然后将引用计数减1，再将SID部分清0。

其实对Mutex来讲，高位SID部分不为0，就会阻塞别的进程访问此Mutex。后面的模式（或引用计数），除统计共享Mutex的持有者外，还有一种作用，就是依据此模式值，判断用户等待事件是什么。

比如说，Mutex_value当前值是（也就是说Mutex内存位中现有的值）：
000000F100000000

这说明是以独占模式持有，如有进程以共享模式申请，等待事件将是Cursor:pin s wait on x。进程以独占模式申请呢，等待事件是Cursor：pin X。

0000000000000002，这样的值呢？这说明有两个进程以共享模式持有Mutex。这不阻塞共享Mutex的申请过程，但如果申请独占Mutex，等待事件还是Cursor：Pin X。

好，接着这个例子，比如说有进程要释放共享Mutex了，有如下三步：

1、将Mutex值改为：000000F100000001。引用计数部已经是减1后的值了。
2、做些其他事件（比如说修改Mutex统计资料之类）
3、将高位SID清0：0000000000000001，完成释放。

在第3步完成前，Mutex这样的值000000F100000001，将会阻塞其他进程申请Mutex。但后面模式部分不为0，Oracle知道，这是一个共享Mutex，所以等待事件是Cursor :pin s或cursor :pin X。

假设在0000000000000001基础上，有又一个进程释放共享Mutex呢，过程是这样的
1、将Mutex值改为：00000SID00000000。引用计数部已经是减为0了，前部的SID我就直接写个SID。
2、做些其他事件（比如说修改Mutex统计资料之类）
3、将高位SID清0：0000000000000000，完成释放。

好，将设在第3步完成前，有进程申请Mutex，当前Mutex值是00000SID00000000，注意模式部分是0，Oracle将认为这是一个独占Mutex。如果这时有进程申请共享Mutex，等待事件将是cursorin wait on x。

这种情况就是软软解析时的cursorin wait on x的成因。它其实是引用计数刚好减到0时的一种特殊情况。或者，也可以认为这是一个小BUG，在11G中，不会再出现同样的情况。

硬解析总要访问各种Mutex，因此硬解析问题会有多种Mutex争用。特别的是，硬解析需要Sahred Pool Latch。因此如果是好几个Mutex和Shared Pool Latch竞争都较高，哪就是硬解析问题。

软解析也需要多种Mutex，但软解析并不需要Shared Pool Latch（某些软解析还需要一至两次），因此如果有多种Mutex，但Shared PoolLatch竞争不明显，哪就是软解析问题。

如果只有cursor:pin s，说明是软软解析。如果是cursor :pin s再加上cursor :pin s wait on x，说明是数量不多的进程，同时以极高的频率软软解析某些相同的SQL。比如说几个进程在PL/SQL循环中频繁解析某一个SQL.