AWR – Make DBA Life Easy

ORA-04021: timeout occurred while waiting to lock object

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

Tablespace Usage History Report

Useful report to show tablespace daily usage and space usage increasing ratio.

Please make sure you are licensed to run sqls against DBA_HIST_*, like dba_hist_tbspc_space_usage .

SQL> show parameter CONTROL_MANAGEMENT_PACK_ACCESS

NAME                            TYPE     VALUE
------------------------------- -------- -----------------------
control_management_pack_access  string   DIAGNOSTIC+TUNING

The length of the report depends on AWR retention. Please refer to “Change AWR Retention & Interval” for how to change AWR retention.

select THE_DATE,
       TABLESPACE,
       SIZE_IN_GB_TD,
       SIZE_IN_GB_YTD,
       SIZE_IN_GB_TD - SIZE_IN_GB_YTD  SIZE_IN_GB_INCREASED
from ( 
     select 
            to_char( histsnap.begin_interval_time, 'YYYY-MM-DD') THE_DATE,
            tbl.name TABLESPACE,
            round(max( tblusage.TABLESPACE_USEDSIZE ) * pmt.value /1024/1024/1024, 2) SIZE_IN_GB_TD,
            lag( round(max( tblusage.TABLESPACE_USEDSIZE ) * pmt.value /1024/1024/1024, 2),1) over ( order by to_char( histsnap.begin_interval_time, 'YYYY-MM-DD') ) SIZE_IN_GB_YTD 
     from 
          dba_hist_snapshot histsnap,
          dba_hist_tbspc_space_usage tblusage,
          v$tablespace tbl,
          v$parameter pmt
    where 
          histsnap.SNAP_ID = tblusage.SNAP_ID
      and tbl.ts# = tblusage.TABLESPACE_ID
      and tbl.name ='&TABLESPACENAME'
      and pmt.name ='db_block_size'
   group by 
          to_char( histsnap.begin_interval_time, 'YYYY-MM-DD'),
          tbl.name,
          pmt.value
 order by 
         to_char( histsnap.begin_interval_time, 'YYYY-MM-DD')
 );

Enter value for tablespacename: USERS
old 17: and tbl.name ='&TABLESPACENAME'
new 17: and tbl.name ='USERS'

THE_DATE   TABLESPACE SIZE_IN_GB_TD SIZE_IN_GB_YTD SIZE_IN_GB..ASED
---------- ---------- ------------- -------------- -----------------
2017-05-10 USERS        4.17
2017-05-11 USERS        4.17         4.17            0
2017-05-12 USERS        4.45         4.17             .28
2017-05-13 USERS        4.55         4.45             .1
2017-05-14 USERS        4.55         4.55            0
2017-05-15 USERS        4.56         4.55             .01
2017-05-16 USERS        4.84         4.56             .28
2017-05-17 USERS        4.96         4.84             .12
2017-05-18 USERS        5.14         4.96             .18
2017-05-19 USERS        5.14         5.14            0

10 rows selected.

ORA-12751: cpu time or run time policy violation

There is an overnight auto-purge job failure every day by throwing “ORA-12751: cpu time or run time policy violation” error.

Extracted trace file from slave process ( m001 ) of Manageability Monitor Process ( MMON) :

*** 2017-02-01 01:11:39.393
*** SESSION ID:(9.3069) 2017-02-01 01:11:39.393
*** CLIENT ID:() 2017-02-01 01:11:39.393
*** SERVICE NAME:(SYS$BACKGROUND) 2017-02-01 01:11:39.393
*** MODULE NAME:(MMON_SLAVE) 2017-02-01 01:11:39.393
*** ACTION NAME:(Auto-Purge Slave Action) 2017-02-01 01:11:39.393
...
..
----- START DDE Action: 'ORA_12751_DUMP' (Sync) -----
CPU time exceeded 300 seconds
Time limit violation detected at:
ksedsts()+465<-kspol_12751_dump()+145<-dbgdaExecuteAction()+1065<-dbgerRunAction()+109<-dbgerRunActions()+4134<-dbgexPhaseII()+1873<-dbgexProcessError()+2680<-dbgeExecuteForError()+88<-dbgePostErrorKGE()+2136<-dbkePostKGE_kgsf()+71<-kgeselv()+276<-ksesecl0()+162
<-ksucin()+147<-delrow()+13790<-qerdlFetch()+1822<-delexe()+1001<-opiexe()+10315<-kpoal8()+2380<-opiodr()+917<-kpoodrc()+36<-rpiswu2()+1776<-kpoodr()+636<-upirtrc()+2436<-kpurcsc()+98<-kpuexec()+10790<-OCIStmtExecute()+39<-kewrose_oci_stmt_exec()+55<-kewrgwxf1_gwrsql_exft_1()+317
<-kewrgwxf_gwrsql_exft()+496<-kewrdsr1_delete_snaprange_1()+476<-kewrdsr_delete_snapshot_range()+133<-kewrpanp_purge_all_nonpts()+923<-kewrpdc_periodic_cleanup()+41<-kewrsnrm_snapshot_removal()+169<-kewrpsr_purge_snapshot_range()+116<-kewrapad_auto_purge_all_dbids()+682
<-kewraps_auto_purge_slave()+942<-kebm_slave_main()+586<-ksvrdp()+1766<-opirip()+674<-opidrv()+603<-sou2o()+103<-opimai_real()+250<-ssthrdmain()+265<-main()+201<-__libc_start_main()+253Current Wait Stack:
...
..
.
*** 2017-02-01 01:15:05.083
*** KEWROCISTMTEXEC - encountered error: (ORA-12751: cpu time or run time policy violation
)
 *** SQLSTR: total-len=351, dump-len=240,
 STR={delete from WRH$_SYSMETRIC_HISTORY tab where (:beg_snap <= tab.snap_id and tab.snap_id <= :end_snap and dbid = :dbid) and not exists (select 1 from WRM$_BASELINE b where (tab.dbid = b.dbid) and }

We can see there is a 300 seconds ( 5 minutes ) CPU time limitation resource violation.

Subscribe to get access

Read more of this content when you subscribe today.

Copy AWR Snapshots Data to Different Database

Copy AWR snapshots data from production to test database, where performance comparison can be held.

EXTRACT AWR DATA FROM SOURCE

Connect to source database as SYS user.

@$ORACLE_HOME/rdbms/admin/awrextr.sql
......
.....
....
...
Choose a Directory Name from the above list (case-sensitive).

Enter value for directory_name: DATA_PUMP_DIR

Using the dump directory: DATA_PUMP_DIR

Specify the Name of the Extract Dump File
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
The prefix for the default dump file name is awrdat_92100_92110.
To use this name, press <return> to continue, otherwise enter
an alternative.

Enter value for file_name: awrdat_92100_92110

Using the dump file prefix: awrdat_92100_92110
|
| ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
| The AWR extract dump file will be located
| in the following directory/file:
| /u02/app/oracle/admin/TESTDB/dpdump/
| awrdat_92100_92110.dmp
| ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
|
| *** AWR Extract Started ...
|
| This operation will take a few moments. The
| progress of the AWR extract operation can be
| monitored in the following directory/file:
| /u02/app/oracle/admin/TESTDB/dpdump/
| awrdat_92100_92110.log
|

End of AWR Extract

The script will prompt and ask for the following information :

dbid
The number of days of snapshots to choose from
Begin Snapshot Id
End Snapshot ID
Value for directory_name
Dump file name to be created ( prefix only ): awrdat_92100_92110

LOAD AWR DATA INTO TARGET

Connect to target database as SYS user.

@$ORACLE_HOME/rdbms/admin/awrload.sql

......
.....
....
...
... Creating AWR_STAGE_LOAD user

|
| ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
| Loading the AWR data from the following
| directory/file:
| /tmp
| awrdat_92100_92110.dmp
| ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
|
| *** AWR Load Started ...
|
| This operation will take a few moments. The
| progress of the AWR load operation can be
| monitored in the following directory/file:
| /tmp
| awrdat_92100_92110.log
|

The script will prompt and ask for :

The name of directory object.
The name of dump file.
The staging schema name to load AWR data into. ( will be dropped automatically after AWR loading ).
The default tablespace name for staging schema.
The temporary tablespace name.

Change AWR Retention and Interval

Use “dbms_workload_repository.modify_snapshot_settings” to change AWR retention and interval.

Check current Retention and Interval

RETENTION = 8 days ( 11520 Mins ) ( Default )
INTERVAL = 1 hour ( 60 Mins ) ( Default )

SQL> desc dba_hist_wr_control
 Name          Null?     Type
 ------------- --------- --------------------------
 DBID          NOT NULL NUMBER
 SNAP_INTERVAL NOT NULL INTERVAL DAY(5) TO SECOND(1)
 RETENTION NOT NULL     INTERVAL DAY(5) TO SECOND(1)
 TOPNSQL                VARCHAR2(10)

SQL> select dbid from v$database;

DBID
----------
2920212463

SQL> col SNAP_INTERVAL format a30
SQL> col RETENTION format a30
SQL> select dbid,SNAP_INTERVAL,RETENTION 
       from dba_hist_wr_control;

 DBID      SNAP_INTERVAL       RETENTION
---------- ------------------- ------------------------------
2920212463 +00000 01:00:00.0   +00008 00:00:00.0

SQL> col SNAP_INTERVAL_MINS format a40
SQL> col RETENTION_MINS format a40
SQL> select dbid,SNAP_INTERVAL*24*60 SNAP_INTERVAL_MINS,
            RETENTION*24*60 RETENTION_MINS 
       from dba_hist_wr_control;

 DBID      SNAP_INTERVAL_MINS            RETENTION_MINS
---------- ----------------------------  -----------------------------
2920212463 +000000060 00:00:00.000000000 +000011520 00:00:00.000000000

Change Retention and Interval

Retention from 8 days ( 11520 Mins ) —-> 31 days ( 44640 Mins )
Interval from 1 hour ( 60 Mins ) —-> 0.5 hour ( 30 Mins )

SQL>exec dbms_workload_repository.modify_snapshot_settings
                                 (retention=>44640,
                                  interval=>30,
                                      dbid=>2920212463);

PL/SQL procedure successfully completed.

Check New Retention and Interval

SQL> select dbid,SNAP_INTERVAL,RETENTION 
       from dba_hist_wr_control;

DBID S     NAP_INTERVAL      RETENTION
---------- ----------------- ---------------------
2920212463 +00000 00:30:00.0 +00031 00:00:00.0

SQL> select dbid,SNAP_INTERVAL*24*60 SNAP_INTERVAL_MINS,
                     RETENTION*24*60 RETENTION_MINS 
       from dba_hist_wr_control;

 DBID SNAP_INTERVAL_MINS                   RETENTION_MINS
---------- ------------------------------- ----------------------------
2920212463 +000000030 00:00:00.000000000   +000044640 00:00:00.000000000

Check SYSAUX Tablespace Usage

SQL> SELECT occupant_name, space_usage_kbytes/1024 MBS 
       FROM V$SYSAUX_OCCUPANTS 
   order by 2;

OCCUPANT_NAME             MBS
------------------------- ----------
TSM                         0
EXPRESSION_FILTER           0
ULTRASEARCH_DEMO_USER       0
...
..
.
SM/ADVISOR                 69.3125
AUDIT_TABLES              136.1875
SM/OPTSTAT                406.4375
SM/AWR                   1633.3125

31 rows selected.