频繁SQL Failed Parse 导致”Library Cache Lock” & “kksfbc child completion” “cursor: pin S wait on X”

by

环境oracle 12c， 大量session同1个SQL ID等待library cache lock，blocker session在频繁的变，并且last_call_et并不久，SQL id在v$sqlarea查询不到对应的SQL TEXT, 间隔性出现cursor: pin S wait on X和kksfbc child completion等待事件， library cache lock的P3值(namesapce+mode)为5373954, 这简单简单记录。

SQL> @dec 5373954
                                DEC                  HEX
----------------------------------- --------------------
                     5373954.000000               520002

SQL> @hex 52
                                DEC                  HEX
----------------------------------- --------------------
                          82.000000                   52

SQL>  SELECT indx,kglstdsc FROM x$kglst  WHERE kglsttyp='NAMESPACE' and indx=82;

      INDX KGLSTDSC
---------- --------------------------------------------------------------------------------------------------------------------------------
        82 SQL AREA BUILD

SQL AREA BUILD namespace是SQL PARSE阶段.

建议收集信息
1, AWR/ASH REPORT
2, hanganalyze and systemstate dumps

oradebug setmypid;
oradebug unlimit;
oradebug hanganalyze 3;
oradebug dump systemstate 266;
oradebug tracefile_name

12c后，检查 DB ALERT LOG 是否有频繁的 PARSE ERROR信息，格式如下:

PARSE ERROR: ospid=12555, error=904 for statement:
select cxxx,xxxxx from xxxx ...;

如果为11g 可以启用10035 event捕捉Parse fail信息到db alert log。

ALTER SYSTEM SET EVENTS '10035 trace name context forever, level 1';

手动执行SQL text,或分析error code 修正应用程序解决该问题。

从ASH 分析cursor: pin S wait on X

select ash.sample_time, ash.session_id, ash.session_serial#, ash.sql_id,  
       ash.event, -- ash.p1, ash.p1text, ash.p2, ash.p2text, ash.p3, ash.p3text,
       ash.wait_time, ash.time_waited, 
       ash.blocking_session, ash.blocking_session_serial#,
       ash.in_parse --, ash.in_hard_parse, ash.in_sql_execution
from v$active_session_history ash
where ash.event = 'cursor: pin S wait on X'
order by ash.sql_id, ash.sample_time;

-- ash summary
with sum_by_session as (
        select ash.sql_id, ash.session_id, 
               trunc(ash.sample_time,'HH') timeframe, min(ash.sample_time) min_time, max(ash.sample_time) max_time,
               sum(ash.wait_time) + sum(ash.time_waited)  total_wait,
               ash.event, ash.p1, ash.p1text, ash.p2, ash.p2text, ash.p3, ash.p3text, ash.in_hard_parse
        from v$active_session_history ash
        join v$active_session_history sqlids on sqlids.sql_id = ash.sql_id
        where (ash.event like 'cursor: pin S%' or ash.in_hard_parse = 'Y' )
        and sqlids.event = 'cursor: pin S wait on X'
        group by  ash.sql_id,  ash.session_id, ash.event, ash.p1, ash.p1text, ash.p2, ash.p2text, ash.p3, ash.p3text, ash.in_hard_parse
                 ,trunc(ash.sample_time,'HH')
         )        
select s.sql_id, to_char(s.timeframe,'dd-Mon-RR HH24') timeframe,
       to_char(min(s.min_time),'HH24:MI:SS')||'-'||to_char(max(s.max_time),'HH24:MI:SS') timeperiod, 
       round(sum(total_wait)/1000000,2)  total_wait_in_s,
       s.event, s.p1, s.p1text, s.p2, s.p2text, s.p3, s.p3text, s.in_hard_parse, 
       listagg(s.session_id,',') within group (order by s.session_id) as sids
from sum_by_session s              
group by s.sql_id,  s.event, s.p1, s.p1text, s.p2, s.p2text, s.p3, s.p3text, s.in_hard_parse, s.timeframe
order by s.sql_id, s.in_hard_parse desc, s.timeframe;

查看严重程度

select * from v$event_histogram 
where event = 'cursor: pin S wait on X';

Mutex 分析

select MUTEX_TYPE,LOCATION,REQUESTING_SESSION,BLOCKING_SESSION,SLEEP_TIMESTAMP
from GV$MUTEX_SLEEP_HISTORY
where location='kkslce [KKSCHLPIN2]'