首页 » ORACLE 9i-23ai » Performance Tuning DML hang wait event ‘cursor: pin S wait on X’
Performance Tuning DML hang wait event ‘cursor: pin S wait on X’
年前一套数据库出现了性能问题，一周出现了两次，很多session 等待“cursor: pin S wait on X” 事件，这是一套11.2.0.4 RAC on RHEL6 的环境，下面记录一下该案例的优化方案。
下面附一段AWR 信息
Load Profile Per Second Per Transaction Per Exec Per Call DB Time(s): 313.0 280.4 3.38 2.52 DB CPU(s): 6.4 5.7 0.07 0.05 Redo size: 11,211.5 10,044.9 Logical reads: 88,141.2 78,969.2 Block changes: 28.0 25.1 Physical reads: 6,496.1 5,820.1 Physical writes: 5.3 4.8 User calls: 124.2 111.3 Parses: 28.3 25.4 Hard parses: 3.7 3.4 W/A MB processed: 1.0 0.9 Logons: 3.0 2.7 Executes: 92.5 82.8 Rollbacks: 0.0 0.0 Transactions: 1.1 Top 5 Timed Foreground Events Event Waits Time(s) Avg wait (ms) % DB time Wait Class cursor: pin S 1,238 689,786 557178 61.26 Concurrency cursor: pin S wait on X 4,535 308,591 68046 27.40 Concurrency gc buffer busy acquire 7,581,532 46,250 6 4.11 Cluster read by other session 5,898,496 25,712 4 2.28 User I/O DB CPU 23,058 2.05 Time Model Statistics Ordered by % or DB time desc, Statistic name Statistic Name Time (s) % of DB Time parse time elapsed 1,044,430.51 92.75 failed parse elapsed time 124,947.86 11.10 sql execute elapsed time 118,493.20 10.52 hard parse elapsed time 41,087.36 3.65 DB CPU 23,057.73 2.05 PL/SQL execution elapsed time 157.93 0.01 connection management call elapsed time 111.42 0.01 ...
# 查询当时活动会话的数量及等待事件(下面内容使用了Tanel poder 大师的SQL脚本包)
SQL/anbob1:SYS>@a
A-Script: Display active sessions...
COUNT(*) SQL_ID STATE EVENT
---------- -------------------------- -------------- -----------------------------------------------------
421 afa7gk65jpngj WAITING cursor: pin S wait on X
276 109krn13pzzjt WAITING cursor: pin S wait on X
40 109krn13pzzjt WAITING library cache lock
22 2kf7mzvwks7v3 WAITING enq: TX - row lock contention
19 fg6wm9u3th7yj WAITING cursor: pin S wait on X
19 fnamtz4w7ndfs WAITING enq: TX - row lock contention
11 9zu9tg64p3y36 WAITING read by other session
9 9xff53bsd4rwp WAITING enq: TX - row lock contention
3 9zu9tg64p3y36 ON CPU On CPU / runqueue
2 afa7gk65jpngj WAITING library cache lock
2 109krn13pzzjt ON CPU On CPU / runqueue
1 9zu9tg64p3y36 WAITING db file scattered read
1 afa7gk65jpngj ON CPU On CPU / runqueue
1 9cabuzkfac0fq ON CPU On CPU / runqueue
1 73aja91ns4m8d WAITING db file parallel read
1 fg6wm9u3th7yj WAITING db file sequential read
1 9b6jjak9kqrpr ON CPU On CPU / runqueue
1 9zu9tg64p3y36 WAITING gc current request
SQL> @snapper ash 5 1
----------------------------------------------------------------------------------------------------
Active% | INST | SQL_ID | SQL_CHILD | EVENT | WAIT_CLASS
----------------------------------------------------------------------------------------------------
35900% | 1 | afa7gk65jpngj | 1 | cursor: pin S wait on X | Concurrency
27100% | 1 | 109krn13pzzjt | | cursor: pin S wait on X | Concurrency
5900% | 1 | afa7gk65jpngj | | cursor: pin S wait on X | Concurrency
4000% | 1 | 109krn13pzzjt | 0 | library cache lock | Concurrency
2200% | 1 | 2kf7mzvwks7v3 | 0 | enq: TX - row lock contention | Application
1900% | 1 | fg6wm9u3th7yj | | cursor: pin S wait on X | Concurrency
1900% | 1 | fnamtz4w7ndfs | 1 | enq: TX - row lock contention | Application
1100% | 1 | 9zu9tg64p3y36 | 1 | read by other session | User I/O
900% | 1 | 9xff53bsd4rwp | 1 | enq: TX - row lock contention | Application
500% | 1 | 109krn13pzzjt | 0 | cursor: pin S wait on X | Concurrency
SQL/anbob1:SYS>select address,hash_value,executions,parse_calls,loaded_versions
from v$sqlarea where sql_id='fpu1pc7j8dnw8';
ADDRESS HASH_VALUE EXECUTIONS PARSE_CALLS LOADED_VERSIONS
---------------- ---------- ---------- ----------- ---------------
00000004FFB75C38 3800486792 0 1 0
Note:
约700个左右的会话在等待‘cursor: pin S wait on X’, 但似乎该sql 就没有execute成功过。
# Find blocker
SQL/anbob1:SYS>@sed cursor
Show wait event descriptions matching %cursor%..
EVENT# EVENT_NAME WAIT_CLASS PARAMETER1 PARAMETER2 PARAMETER3
-------------------- ------------ ------------- ------------ ------------
278 cursor: mutex S Concurrency idn value where
277 cursor: mutex X Concurrency idn value where
280 cursor: pin S Concurrency idn value where
281 cursor: pin S wait on X Concurrency idn value where
279 cursor: pin X Concurrency idn value where
p1 idn => sql hash value
p2 value => holder session sid
p3 where => where in code mutex
SQL/anbob1:SYS>select distinct p2raw,to_number(substr(to_char(rawtohex(p2raw)),1,8),'XXXXXXXX') sid
from v$session
where event = 'cursor: pin S wait on X';
P2RAW SID
---------------- ----------
000006EE00000000 1774
0000089200000000 2194
00000C9E00000000 3230
00000CA000000000 3232
SQL/anbob1:SYS>select p1, p2raw, count(*) from v$session
where event ='cursor: pin S wait on X'
and wait_time = 0
group by p1, p2raw;
P1 P2RAW COUNT(*)
---------- ---------------- ----------
1197473337 000006EE00000000 212
1197473337 00000C9E00000000 64
2274893777 00000CA000000000 19
2333790705 0000089200000000 418
SQL/anbob1:SYS>select sid,serial#,SQL_ID,BLOCKING_SESSION,BLOCKING_SESSION_STATUS,EVENT
from v$session where SID=2194
SID SERIAL# SQL_ID BLOCKING_SESSION BLOCKING_SESSION_STATU EVENT
---------- ---------- -------------------------- ---------------- ---------------------- ------------------------------
2194 255 afa7gk65jpngj UNKNOWN read by other session
SQL/anbob1:SYS>@xi afa7gk65jpngj %
eXplain the execution plan for sqlid afa7gk65jpngj child %...
update DEALER_REPORT set ORDER_STATUS=:1 where CUST_ORDER_ID=:2 and CITY_CODE=:3 and ACCEPT_DATE=:4
SQL/anbob1:SYS>select sid,serial#,SQL_ID,BLOCKING_SESSION,BLOCKING_SESSION_STATUS,EVENT
from v$session where SID=1774;
SID SERIAL# SQL_ID BLOCKING_SESSION BLOCKING_SESSION_STATU EVENT
---------- ---------- -------------------------- ---------------- ---------------------- ------------------------------
1774 353 109krn13pzzjt UNKNOWN read by other session
SQL/anbob1:SYS>@xi 109krn13pzzjt %
update DEALER_REPORT set REASON=:1, REMARK=:2 where CUST_ORDER_ID=:3
SQL/anbob1:SYS>@ind NEES_OWNER_USER.DEALER_REPORT
Display indexes where table or index name matches %NEES_OWNER_USER.DEALER_REPORT%...
TABLE_OWNER TABLE_NAME INDEX_NAME POS# COLUMN_NAME DSC
-------------------- ------------------------------ ------------------------------ ---- ------------------------------ ----
NEES_OWNER_USER DEALER_REPORT DEALER_REPORT_CI 1 CUST_ORDER_ID
2 CITY_CODE
DEALER_REPORT_I 1 DEALER_ID
2 CITY_CODE
3 ACCEPT_DATE
DEALER_REPORT_PK 1 REGISTER_NUMBER
DEALER_REPORT_PRINTORDER 1 PRINTORDER
2 CITY_CODE
3 ACCEPT_DATE
DEALER_REPORT_SI 1 SERVICE_ID
2 CITY_CODE
3 ACCEPT_DATE
Note:
最是UPDATE DEALER_REPORT表，而且看不到执行计划，blocker session在等待I/O 类事件， 表上存在索引。
其中一个holder call stack
SQL/anbob1:SYS>oradebug short_stack; ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1876<-sspuser()+112<-__sighandler()<-semtimedop()+10<-skgpwwait()+160<-ksliwat()+1865<-kslwaitctx()+163<-kcbzwb()+1903<-kcbgtcr()+31705<-ktrget3()+621<-ktrget2()+126<-kdifxs1()+4835<-kdifxs()+17<-qerixtFetch()+377<-rwsfcd()+103<-qeruaFetch()+574<-qervwFetch()+139<-qergsFetch()+858<-opifch2()+3022<-opiall0()+1642<-opikpr()+541<-opiodr()+916<-rpidrus()+211<-skgmstack()+148<-rpiswu2()+638<-kprball()+1241<-kkescFetch()+75<-kkedsamp()+6802<-kkedsSel()+1471<-kkecdn()+857<-kkotap()+9537<-kkoiqb()+11134<-kkooqb()+639<-kkoqbc()+2364<-apakkoqb()+171<-apaqbdDescendents()+449<-apaqbdList()+76<-apaqbd()+14<-apadrv()+866<-opitca()+2008<-kksFullTypeCheck()+69<-rpiswu2()+1618<-kksLoadChild()+10449<-kksSetBindType()+5505<-kkscsSearchChildList()+1574<-kksfbc()+12105<-opiexe()+2316<-opiall0()+1358<-opial7()+547<-opiodr()+916<-ttcpip()+2242<-opitsk()+1673<-opiino()+966<-opiodr()+916<-opidrv()+570<-sou2o()+103<-opimai_real()+133<-ssthrdmain()+252<-main()+201<-__libc_start_main()+253<-_start()+36
继续
SQL/anbob1:SYS> select * from X$MUTEX_SLEEP
ADDR INST_ID MUTEX_TYPE LOCATION SLEEPS WAIT_TIME
---------------- ---------- --------------- ---------------------------------------- ---------- ----------
00007FCE23E59780 1 Library Cache kglReleaseHandleReference 125 7 0
00007FCE23E59800 1 Library Cache kglGetHandleReference 124 147 0
00007FCE23E59880 1 Library Cache kglUpgradeLock 119 11199 0
00007FCE23E59900 1 Library Cache kgllldl2 112 30 0
00007FCE23E59980 1 Library Cache kglllal3 111 157 0
00007FCE23E59A00 1 Library Cache kglllal1 109 4 0
00007FCE23E59A80 1 Library Cache kglhdgn2 106 132769 0
00007FCE23E59B00 1 Library Cache kglpndl1 95 13219 0
00007FCE23E59B80 1 Library Cache kglpnal2 91 36248 0
00007FCE23E59C00 1 Library Cache kglpnal1 90 6609 0
00007FCE23E59C80 1 Library Cache kgllkdl1 85 751063 0
00007FCE23E59D00 1 Library Cache kgllkal3 82 157683 0
00007FCE23E59D80 1 Library Cache kgllkal1 80 19047 0
00007FCE23E59E00 1 Library Cache kglrfcl1 79 4 0
00007FCE23E59E80 1 Library Cache kglobld1 75 6 0
00007FCE23E59F00 1 Library Cache kglobpn1 71 53 0
00007FCE23E59F80 1 Library Cache kglhdgh1 64 218 0
00007FCE23E5A000 1 Library Cache kglhbh1 63 1 0
00007FCE23E5A080 1 Library Cache kglhdgn1 62 79981 0
00007FCE23E5A100 1 Library Cache kgllkc1 57 47666 0
00007FCE23E5A180 1 Library Cache kglic1 49 19 0
00007FCE23E5A200 1 Library Cache kglati1 45 177 0
00007FCE23E5A280 1 Library Cache kglrdtin1 44 7 0
00007FCE23E5A300 1 Library Cache kgldtin1 42 9 0
00007FCE23E5A380 1 Library Cache kglini1 32 26 0
00007FCE23E5A400 1 Library Cache kglkep1 12 2 0
00007FCE23E5A480 1 Library Cache kglpin1 4 26840 0
00007FCE23E5A500 1 Library Cache kglget2 2 13471 0
00007FCE23E5A580 1 Library Cache kglget1 1 980 0
00007FCE23E5A380 1 Cursor Parent kkscsPruneChild [KKSPRTLOC35] 1 0
00007FCE23E5A400 1 Cursor Parent kkscsAddChildNode [KKSPRTLOC34] 44 0
00007FCE23E5A480 1 Cursor Parent kxsBindCapture [KKSPRTLOC22] 1 0
00007FCE23E5A500 1 Cursor Parent kksLoadChild [KKSPRTLOC4] 1 0
00007FCE23E5A580 1 Cursor Parent kksfbc [KKSPRTLOC1] 2 0
00007FCE23E5A280 1 Cursor Pin kksLockDelete [KKSCHLPIN6] 12841 0
00007FCE23E5A300 1 Cursor Pin kksSetBindType [KKSCHLPIN4] 25 0
00007FCE23E5A380 1 Cursor Pin kksSetBindType [KKSCHLPIN3] 1696337 0
00007FCE23E5A400 1 Cursor Pin kkslce [KKSCHLPIN2] 3481581807 0 <<<============= 00007FCE23E5A480 1 Cursor Pin kksfbc [KKSCHLPIN1] 5045 0 00007FCE23E5A500 1 Cursor Pin kksfbc [KKSCHLFSP2] 21360 0 00007FCE23E5A580 1 Cursor Pin kksfbc [KKSCHLCREA] 6 0 00007FCE23E5A480 1 hash table kkshListChanged [KKSHBKLOC9] 35 0 00007FCE23E5A500 1 hash table kkscsSearchChildList [KKSHBKLOC2] 389 0 00007FCE23E5A580 1 hash table kkshGetNextChild [KKSHBKLOC1] 186 0 SQL/anbob1:SYS>select sid,event,p1,p2,p3,blocking_session from v$session where event like 'cursor: pin S%' order by 2,6;
SID EVENT P1 P2 P3 BLOCKING_SESSION
--------------- ------------------------------ --------------- --------------- --------------- ----------------
...
1745 cursor: pin S 1197473337 1911260446720 21474836480 445
1742 cursor: pin S 1197473337 1911260446720 21474836480 445
21474836480 445
1520 cursor: pin S 2333790705 2796023709696 21474836480 651
436 cursor: pin S 2333790705 2796023709696 21474836480 651
2804 cursor: pin S 2333790705 2796023709696 21474836480 651
2819 cursor: pin S 2333790705 2796023709696 21474836480 651
1723 cursor: pin S 2333790705 2796023709696 21474836480 651
1727 cursor: pin S 2333790705 2796023709696 21474836480 651
1513 cursor: pin S 2333790705 2796023709696 21474836480 651
1325 cursor: pin S 2333790705 2796023709696 21474836480 651
1305 cursor: pin S 2333790705 2796023709696 21474836480 651
1300 cursor: pin S 2333790705 2796023709696 21474836480 651
1299 cursor: pin S 2333790705 2796023709696 21474836480 651
3041 cursor: pin S 2333790705 2796023709696 21474836480 651
1095 cursor: pin S 2333790705 2796023709696 21474836480 651
1094 cursor: pin S 2333790705 2796023709696 21474836480 651
...
SELECT decode(trunc(&&P2/4294967296),
2 0,trunc(&&P2/65536),
3 trunc(&&P2/4294967296)) SID_HOLDING_MUTEX
4 FROM dual;
Enter value for p2: 2796023709696
SID_HOLDING_MUTEX
-----------------
651
SQL/anbob1:SYS>SELECT decode(trunc(&&P3/4294967296),
2 0,trunc(&&P3/65536),
3 trunc(&&P3/4294967296)) LOCATION_ID
FROM dual;
4 Enter value for p3: 21474836480
LOCATION_ID
-----------
5
SQL/anbob1:SYS>SELECT MUTEX_TYPE, LOCATION
2 FROM x$mutex_sleep
3 WHERE mutex_type like 'Cursor Pin%'
4 and location_id=&&LOCATION_ID;
Enter value for location_id: 5
MUTEX_TYPE LOCATION
-------------------- ---------------------------
Cursor Pin kkslce [KKSCHLPIN2]
当时也有做SSD TRACE
Ass.Awk Version 1.0.38
~~~~~~~~~~~~~~~~~~~~~~
Source file : /oracle/app/oracle/diag/rdbms/dbname/anbob1/trace/anbob1_ora_12933.trc
...
Resource Holder State
LOCK: Handle=0x6dc60a530 249: waiting for 'db file sequential read' (0x1c,0xb61a1,0x1)
Mutex 870d563a 249: waiting for 'db file sequential read' (0x1c,0xb61a1,0x1)
Mutex 870d563a 397: Blocker
Mutex 87981fd1 95: waiting for 'read by other session'
下面手动做个SQL TRACE 看看为什么HOLDER 会在等待I/O 相关事件长时间未成功，而后续相同SQL 在解析时会等待holder 的parent sql cursor 相关资源。
SQL/anbob1:SYS>oradebug setmypid Statement processed. SQL/anbob1:SYS>oradebug tracefile_name /oracle/app/oracle/diag/rdbms/dbname/anbob1/trace/anbob1_ora_12983.trc SQL/anbob1:SYS>oradebug unlimit; Statement processed. SQL/anbob1:SYS>oradebug event 10046 trace name context forever, level 12; Statement processed. SQL/anbob1:SYS>update NEES_OWNER_USER.DEALER_REPORT set ORDER_STATUS='1', IS_FJ='1' where CUST_ORDER_ID='1'; 0 rows updated. SQL/anbob1:SYS>oradebug event 10046 trace name context off Statement processed. SQL/anbob1:SYS>host
下面分析SQL TRACE 文件
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE
NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false')
NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),0), NVL(SUM(C2),0)
FROM
(SELECT /*+ IGNORE_WHERE_CLAUSE */ 1 AS C1, CASE WHEN
TO_NUMBER("DEALER_REPORT"."CUST_ORDER_ID")=1 THEN 1 ELSE 0 END AS C2 FROM
((SELECT /*+ NO_PARALLEL("NEES_OWNER_USER"."DEALER_REPORT")
SQL ID: g9d6upz9hdzw9 Plan Hash: 4285985923
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE
NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false')
NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),0), NVL(SUM(C2),0)
FROM
(SELECT /*+ IGNORE_WHERE_CLAUSE */ 1 AS C1, CASE WHEN
TO_NUMBER("DEALER_REPORT"."CUST_ORDER_ID")=1 THEN 1 ELSE 0 END AS C2 FROM
((SELECT /*+ NO_PARALLEL("NEES_OWNER_USER"."DEALER_REPORT")
FULL("NEES_OWNER_USER"."DEALER_REPORT")
NO_PARALLEL_INDEX("NEES_OWNER_USER"."DEALER_REPORT") */ * FROM
"NEES_OWNER_USER"."DEALER_REPORT" PARTITION(4) SAMPLE BLOCK (0.025497 , 1)
SEED (1)) UNION ALL (SELECT /*+
NO_PARALLEL("NEES_OWNER_USER"."DEALER_REPORT")
FULL("NEES_OWNER_USER"."DEALER_REPORT")
update NEES_OWNER_USER.DEALER_REPORT set ORDER_STATUS='1', IS_FJ='1'
where
CUST_ORDER_ID=1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.08 0.16 0 908 10 0
Execute 1 1.54 7.82 9867 9854 1 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 1.63 7.99 9867 10762 11 0 <<<<<<<<<<<<<
Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: SYS
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
0 0 0 UPDATE DEALER_REPORT (cr=0 pr=0 pw=0 time=24 us)
0 0 0 PARTITION RANGE ALL PARTITION: 1 541 (cr=0 pr=0 pw=0 time=15 us cost=467004 size=919040 card=45952)
0 0 0 TABLE ACCESS FULL DEALER_REPORT PARTITION: 1 541 (cr=6135 pr=6123 pw=0 time=4883619 us cost=467004 size=919040 card=45952) <<<<<<<<<<<<<
Note: 这个客户的数据库有个“风俗习惯” ，所有表都无统计信息，所以在递归SQL 中可以看到几个动态采样（ OPT_DYN_SAMP） ，这也在无知觉中增加了I/O 消耗， 而且执行计划是使用了FTS, 这是一个500多个子分区的分区表。 猜测是动态采样和错误的执行计划影响了SQL的运行时间， 下面对该表收集统计信息。 再对相同SQL 做10046 trace
SQL/anbob1:SYS>exec DBMS_STATS.GATHER_TABLE_STATS (ownname => 'NEES_OWNER_USER' , tabname => 'DEALER_REPORT',cascade => true, estimate_percent => 5,method_opt=>'for all indexed columns size 1', granularity => 'ALL', degree => 10); PL/SQL procedure successfully completed. update NEES_OWNER_USER.DEALER_REPORT set ORDER_STATUS='1', IS_FJ='1' where CUST_ORDER_ID='1' call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 1 0.03 0.36 55 404 0 0 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 2 0.03 0.36 55 404 0 0 <<<<<<<<<<<<< Misses in library cache during parse: 0 Optimizer mode: CHOOSE Parsing user id: SYS Number of plan statistics captured: 1 Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 0 0 0 UPDATE DEALER_REPORT (cr=404 pr=55 pw=0 time=363184 us) 0 0 0 PARTITION RANGE ALL PARTITION: 1 541 (cr=404 pr=55 pw=0 time=363170 us cost=5 size=20 card=1) 0 0 0 INDEX RANGE SCAN DEALER_REPORT_CI PARTITION: 1 541 (cr=404 pr=55 pw=0 time=361957 us cost=5 size=20 card=1)(object id 76439) <<<<<<<<<<<< Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ gc cr grant 2-way 32 0.00 0.01 db file sequential read 55 0.01 0.31 gc current block 2-way 1 0.00 0.00 gc cr grant congested 1 0.00 0.00 SQL*Net message to client 1 0.00 0.00 SQL*Net message from client 1 9.14 9.14 ********************************************************************************
Note:
可以看到没有了动态采样，执行计划也有原来的全表扫改成了索引，执行效率提升了N倍。
SQL/anbob1:SYS>select address,hash_value,executions,parse_calls,loaded_versions from v$sqlarea where sql_id='fpu1pc7j8dnw8';
ADDRESS HASH_VALUE EXECUTIONS PARSE_CALLS LOADED_VERSIONS
---------------- ---------- ---------- ----------- ---------------
00000004FFB75C38 3800486792 514 255 1
SQL/anbob1:SYS>@xi fpu1pc7j8dnw8 %
eXplain the execution plan for sqlid fpu1pc7j8dnw8 child %...
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------
SQL_ID fpu1pc7j8dnw8, child number 0
update DEALER_REPORT set ORDER_STATUS='1', IS_FJ='1' where
CUST_ORDER_ID=:1
NOTE: cannot fetch plan for SQL_ID: fpu1pc7j8dnw8, CHILD_NUMBER: 0
Please verify value of SQL_ID and CHILD_NUMBER;
It could also be that the plan is no longer in cursor cache (check v$sql_plan)
SQL_ID fpu1pc7j8dnw8, child number 1
-------------------------------------
update DEALER_REPORT set ORDER_STATUS='1', IS_FJ='1' where
CUST_ORDER_ID=:1
Plan hash value: 1243865889
--------------------------------------------------------------------------
| Id | Operation | Name | E-Rows | Pstart| Pstop |
--------------------------------------------------------------------------
| 0 | UPDATE STATEMENT | | | | |
| 1 | UPDATE | DEALER_REPORT | | | |
| 2 | PARTITION RANGE ALL| | 2 | 1 | 541 |
|* 3 | INDEX RANGE SCAN | DEALER_REPORT_CI | 2 | 1 | 541 |
--------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
3 - access("CUST_ORDER_ID"=:1)
NOTE:
注意到原来的问题SQL 也有了执行计划，很快也有了execution 次数增长。到现在已经过去快2个月，该问题没有再发生。
后来开SR ， 是这样解释的。
last provided traces show bad execution plan in case of missing statistics .
TABLE ACCESS FULL DEALER_REPORT PARTITION:
instead on
INDEX RANGE SCAN DEALER_REPORT_CI PARTITION:with hight waits in ;
gc cr multi block request 615 0.01 3.01 <<<<<<<<<<<<<<<
db file scattered read 613 0.13 3.16 <<<<<<<<<<<<<<<<ACTION PLAN
============
the statistics in all tables/indexes should be regathered and up to date
that should allow the CBO to find optimal execution plan .
so, the execution time will decrease and
the wait event ‘cursor: pin S’& ‘cursor: pin S wait on X’ should disappearRegards
Lech
(EMEA DBPERF team)
另外Tanel Poder也对 ‘cursor: pin S wait on X’事件进行了解释。
This wait happens when your session wants to examine / execute an existing
child cursor – but it’s being pinned in X mode by someone else. The usual
reasons for this are:
1) The cursor got flushed out for some reason (or it’s just the first time
anyone is running it) and the other session is currently hard
parsing/compiling/loading the contents of this cursor back into library
cache. The longer the parsing/loading takes, the longer you wait. If the
parsing session hits some (performance) issues, this pin may be held for a
long time.or
2) The child cursor is already loaded into cache, but someone else is
currently flushing it out (shared pool shortage, fragmentation & loading of
a big object, SGA target / ASMM reducing the SGA size).The thing with “auto-extending” connection pools is that there’s a
chicken-and-egg situation with troubleshooting performance & utilization
spikes – what caused what? Sometimes there’s just a mild performance hiccup
for whatever reason, which nobody would even noticed, but a trigger-happy
connection pool will greatly amplify it by starting up hundreds of new
connections during the problem time.0.6 logons per second is not a problem if that’s your actual number. But if
you are talking about 0.6 logons per second *on average in a 1-hour AWR
report, *then this could mean also (let’s say) 40 new connections per
second during your spike time (of 60 seconds for example) and then no more
logins throughout the rest of the hour. 60 x 50 / 3600 = 0.66…So if your spike lasted for X seconds, then your performance data should
also be from X seconds (or even more granular), otherwise these averages
over long time may hide the truth. You can parse the listener log with a
simple grep & awk command to get a more detailed overview (and somewhat
closer to the connection pool) about connection rates.If you want to reproduce “cursor: pin S for X” waits, you can use one of my
seminar demo scripts (
http://blog.tanelpoder.com/files/scripts/aot/demo4.sql ). Just run the
entire script in one session (it will pin a child and end up hard parsing
for a very long time) and then run the select part of that script only in a
different session. But my demo very narrowly focuses on causing the wait
event problem, I don’t think it will reproduce anything like you saw.Another option would be to get 10s or hundreds of sessions running the same
SQL statement (and overload the CPUs) and then purging the cursor with
DBMS_SHARED_POOL.PURGE (not just flush shared pool as it will skip pinned
chunks, but purge will wait until it gets the pin).—
*Tanel Poder*
微信扫一扫，打赏作者吧～
对不起，这篇文章暂时关闭评论。