Investigate a long running procedure using AWR
                                                 Last update (2010-08-29 14:17:18)
                                                                                                                   Date added (2008-02-21 16:26:46)

Posted by: George Kaparelis

Summary
Here is a Real Case where i have to investigate in FLEXCUBE a long running procedure using AWR (Automatic Workload Repository) in Oracle Database 10g. Last night during 23:00-00:00, a batch program was running in a 3 node RAC environment. My only data comes from AWR (snap_ids 25185, 25186).

I run this batch program in 20-25 different sessions/groups, Parallel DIY, using all 3 nodes. Each session/group consists of 10-15 branches

First I have to check Top 5 Wait_Events (batch makes heavy use of indexes).
select T.*, e.name from
( select event_id, sum(time_waited) from dba_hist_active_sess_history
   where snap_id between 25185 and 25186
     group by event_id order by 2 desc
 ) T , v$event_name e where T.event_id = e.event_id and rownum <= 5

EVENT_ID   SUM(TIME_WAITED) NAME
---------------------------------------------------
2652584166         90376550 db file sequential read
1478861578         64325301 gc buffer busy
512320954          38247054 gc cr request
1620694733         25831414 db file parallel write
3905407295         18900809 gc current request

/* Let’s see what SQL was executing when it got snapped. */    

 select sql_id,
        event_id,
        count(*) cnt
  from  dba_hist_active_sess_history
  where snap_id between 25185 and 25186
     and event_id = 1478861578
group by sql_id , event_id
  having count(*) > 100
order by 3 desc

SQL_ID                 EVENT_ID      CNT
----------------------------------------
ar3pbd1k5k0n2        1478861578      147

select  sql_text from dba_hist_sqltext where sql_id = 'ar3pbd1k5k0n2';

SQL_TEXT
---------------------------------------------
Begin wrp_batch.pr_aeodICEOD(:1,:2,:3,:4);End;

/* Now see what object is being waited most. */

select count(distinct(current_obj#)) from dba_hist_active_sess_history
 where snap_id between 25185 and 25186
     and event_id = 1478861578 and sql_id='ar3pbd1k5k0n2';

COUNT(DISTINCT(CURRENT_OBJ#))
----------------------------
                            4
 
select current_obj#, count(*) cnt from dba_hist_active_sess_history
  where snap_id between 25185 and 25186
     and event_id = 1478861578 and sql_id= 'ar3pbd1k5k0n2'
  group by current_obj# order by 2 desc;

CURRENT_OBJ#     CNT
--------------------
      133016     141
          -1       4
           0       1
      137319       1
 
select object_id, owner, object_name, object_type from dba_objects
where object_id  = 133016;

OBJECT_ID   OWNER OBJECT_NAME          OBJECT_TYPE
--------------------------------------------------
133016      FCC   PK01_ACTB_DAILY_LOG        INDEX

/* Now let's find which blocks are getting most contended.  */

select current_file#, current_block#, count(*) cnt
 from dba_hist_active_sess_history
  where snap_id between 25185 and 25186
   and event_id = 1478861578 and sql_id='ar3pbd1k5k0n2'
    and current_obj# = 133016
group by current_file#, current_block#
    having count(*)> 0
order by 3 desc;

CURRENT_FILE#      CURRENT_BLOCK#            CNT
------------------------------------------------
          108               71468             11
           67               12848              5
           40              111732              3
           51              267230              3
          105              143605              3
           64               78883              3
            .                   .              .
            .                   .              .

/* Are these blocks data blocks or header blocks on the segment?
Let’s find out. */

select segment_name, header_file, header_block from dba_segments where owner='FCC' 
and segment_name = 'PK01_ACTB_DAILY_LOG';

SEGMENT_NAME             HEADER_FILE HEADER_BLOCK
-------------------------------------------------
PK01_ACTB_DAILY_LOG               19 3715

/* So, it seems there is so much contention on primary key index PK01_ACTB_DAILY_LOG 
(Table ACTB_DAILY_LOG is the busiest table on their 3-node OLTP RAC 10.1.4).

Solution: Recreate PK01_ACTB_DAILY_LOG as a reverse key index */ 
Reviews
Categories
Filters
Search