首页 » ORACLE » 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 eventcursor: pin S’& ‘cursor: pin S wait on X’ should disappear

Regards
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*

打赏

对不起,这篇文章暂时关闭评论。