Blog

Application job failed with trace file contents:

*** 2018-06-16 11:03:17.044
*** SESSION ID:(2437.25769) 2018-06-16 11:03:17.044
*** CLIENT ID:() 2018-06-16 11:03:17.044
*** SERVICE NAME:(BATCH) 2018-06-16 11:03:17.044
*** MODULE NAME:(DBMS_SCHEDULER) 2018-06-16 11:03:17.044
*** ACTION NAME:(IMMEDIATE16_06_2018_10_10_01) 2018-06-16 11:03:17.044

ORA-12012: error on auto execute of job "BATCH"."IMMEDIATE16_06_2018_10_10_01"
ORA-04021: timeout occurred while waiting to lock object
ORA-06512: at "BATCH.AP_DATA_PROCESS", line 652
ORA-06512: at line 1

Check the session details from ASH history:

set pagesize 100
set linesize 250
col INSTANCE_NUMBER format 99
col SESSION_ID format 99999
col BLOCKING_INST_ID format 99
col event format a20
col WAIT_CLASS format a15
col PROGRAM format a20
col MODULE format a16
col p3 format 99999999999999999999
select sql_id,to_char(SAMPLE_TIME,'YYYYMMDD-HH24:MI:SS'),
       INSTANCE_NUMBER,SESSION_ID,PROGRAM,MODULE,EVENT,
       CURRENT_OBJ#,WAIT_CLASS,BLOCKING_INST_ID,
       BLOCKING_SESSION, p3
from dba_hist_active_sess_history
where INSTANCE_NUMBER= 3 
and SESSION_ID = 2437 
and sample_time between to_date('16-06-18 11:00:00','DD-MM-YY HH24:MI:SS')
and to_date('16-06-18 11:04:00','DD-MM-YY HH24:MI:SS')
and event ='library cache lock'
order by sample_id;

SQL_ID TO_CHAR(SAMPLE_TI INSTANCE_NUMBER SESSION_ID PROGRAM MODULE EVENT CURRENT_OBJ# WAIT_CLASS BLOCKING_INST_ID BLOCKING_SESSION P3
------------- ----------------- --------------- ---------- -------------------- ---------------- -------------------- ------------ --------------- ---------------- ---------------- ---------------------
...
..
6cp7dp2xgxr6m 20180616-11:02:52 3 2437 oracle@racnode3 (J001) DBMS_SCHEDULER library cache lock 27307391 Concurrency 2 5205 76355447552016387
6cp7dp2xgxr6m 20180616-11:03:02 3 2437 oracle@racnode3 (J001) DBMS_SCHEDULER library cache lock 27307391 Concurrency 2 5205 76355447552016387
6cp7dp2xgxr6m 20180616-11:03:12 3 2437 oracle@rcanode3 (J001) DBMS_SCHEDULER library cache lock 27307391 Concurrency 2 5205 76355447552016387

20 rows selected.

The OBJ# matches the DDL command:

ALTER INDEX BATCH.CDR_IND REBUILD SUBPARTITION CDR_IND_SUB_213;

SQL>select OWNER,OBJECT_NAME,SUBOBJECT_NAME,
           OBJECT_TYPE,STATUS,LAST_DDL_TIME 
     from  dba_objects 
    where  OBJECT_ID=27307391;

OWNER OBJECT_NAME SUBOBJECT_NAME  OBJECT_TYPE        STATUS LAST_DDL_
----- ----------- --------------  ------------------ ------ --------
BATCH CDR_IND     CDR_IND_SUB_213 INDEX SUBPARTITION VALID  20180616-12:39:22

The P3 shows the waiting object details, we can see the session failed because of waiting for object CDR,  which is holding by blocking session 5205 on node 2.

SQL> select lpad('Library cache P3 value: ',50,'.')||76355447552016387 from dual;

..........................Library cache P3 value: 76355447552016387

SQL> select lpad('Library cache P3 value HEX: ',50,'.')||to_char(76355447552016387,'xxxxxxxxxxxxxxxxxxxxx') from dual;

.....................Library cache P3 value HEX: 10f44e000010003

SQL> select lpad('Object ID: ',50,'.')||to_number(substr('10f44e000010003',1,length('10f44e000010003')-8 ),'xxxxxxxxxxxxxx') from dual;

...........Object ID: 17777888

SQL> select lpad('Namespace: ',50,'.')||to_number(substr('10f44e000010003',-8,4),'xxxxxxxxxxxxxx') from dual;

.......................................Namespace: 1

SQL> select lpad('RequestMode: ',50,'.')||decode(to_number(substr('10f44e000010003',-4),'xxxxxxxxxxxxxx'),3,'exclusive mode',2,'share mode',1,'null mode',0,'no lock/pin held','unknown') from dual;

.....................................RequestMode: exclusive mode

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

1 TABLE/PROCEDURE

SQL>select OWNER,OBJECT_NAME,SUBOBJECT_NAME,OBJECT_TYPE,NAMESPACE 
from dba_objects where object_id=17777888;

OWNER     OBJECT_NAME   SUBOBJECT_NAME      OBJECT_TYPE     NAMESPACE
---------------- -----------------------  ---------------------------------  ------------------------  -----------------
BATCH        CDR                                                               TABLE                   1

Check blocking session details on racnode2, and found it is running DBMS_STATS against waiting object CDR from racnode3 .

b6usrg82hwsa3 20180616-11:02:56 2 5205 oracle@racnode2 (J032) DBMS_SCHEDULER row cache lock 18 Concurrency 0 2999959 GLOBAL
b6usrg82hwsa3 20180616-11:03:06 2 5205 oracle@racnode2 (J032) DBMS_SCHEDULER row cache lock 18 Concurrency 0 0       GLOBAL
b6usrg82hwsa3 20180616-11:03:16 2 5205 oracle@racnode2 (J032) DBMS_SCHEDULER row cache lock 18 Concurrency 0 1953712 GLOBAL
4m477zx25xrgq 20180616-11:03:26 2 5205 oracle@racnode2 (J032) DBMS_SCHEDULER                27307236       321 0     NOT IN WAIT
4m477zx25xrgq 20180616-11:03:36 2 5205 oracle@racnode2 (J032) DBMS_SCHEDULER                27307242       1582 0    NOT IN WAIT
4m477zx25xrgq 20180616-11:03:46 2 5205 oracle@racnode2 (J032) DBMS_SCHEDULER                27307219       1537 0    NOT IN WAIT


SQL> select sql_text from v$sql where sql_id='b6usrg82hwsa3';

SQL_TEXT
-------------------------------------------------------------------
call dbms_stats.gather_database_stats_job_proc ( )

SQL>se long 10000
SQL> select SQL_FULLTEXT from v$sql where sql_id='4m477zx25xrgq';
SQL_FULLTEXT
--------------------------------------------------------------------
/* SQL Analyze(1) */ select /*+ full(t) no_parallel(t) no_parallel_index(t)
dbms_stats cursor_sharing_exact use_weak_name_resl dynamic_sampling(0) no_monito
....
from "BATCH"."CDR" t
 where TBL$OR$IDX$PART$NUM("BATCH"."CDR",0,3,0,"ROWID") = :objn /*
 NDV,NIL,NIL,NDV,NIL,NIL,NDV,NIL,NIL,NDV,NIL,NIL,NDV,NIL,NIL,NDV,NIL,NIL,NDV,NIL
,NIL,NDV,NIL,NIL,NDV,NIL,NIL,NDV,NIL,NIL,NDV,NIL,NIL,NDV,NIL,NIL,NDV,NIL,NIL,NDV
,NIL,NIL,NDV,NIL,NIL,NDV,NIL,NIL,ACL,NIL,NIL*/

The blocking session ID 5205 on node 2 is running a weekend maintenance job –“Optimizer Statistics Gathering”. it is analysing partition table  CDR.

There are a lot of discussions about “library cache lock” from DBMS_STATS gather of stats for a subpartition.

19790972 – “library cache lock” waits due to DBMS_STATS gather of stats for a sub partition

Workaround

Under the approval of Oracle Support,  you can try to change below parameter value from 15 mins to longer time.

SQL>alter system set "_kgl_time_to_wait_for_locks'=60 scope=spfile;

SQL>shutdown immediate;

SQL>startup