[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.