Same SQL_ID, same execution plan (SQL_PLAN_HASH_VALUE), greatly different elapsed time – a simple way to troubleshoot this problem with ASH

A query runs fine in one environment, but is terrible in another. The usual suspects – different execution plan, hardware issues, etc are ruled out.

The next step is to look at the actual execution statistics and see where the difference is. Re-executing the statements with GATHER_PLAN_STATISTICS hint was not an option. SQL Monitoring was running, but the query was behind the retention period.

This is where the Oracle Active Session History (ASH), a separately licensed option, comes to play.

Using sql_plan_line_id column in dba_hist_active_sess_history ASH view to get load profile is not new – http://eastcoastoracle.org/PDF_files/2011/Presentations/BarunSQL_Performance_Tuning_with_Oracle_ASH_AWR_Real_World_Use_Cases_Public.pdf .

Similar technique can be used to easily find out from which plan step onwards the two execution plans start to differ.

At DB1:
select sql_plan_line_id , count(*)
from dba_hist_active_sess_history
where 
    sql_id = 'fmhbn1tn0c54z'
and sample_time
         between to_date('11/26/2012:10:00:00','MM/DD/YYYY:HH24:MI:SS’)
         and to_date('11/26/2012:11:00:00','MM/DD/YYYY:HH24:MI:SS’)
group by sql_plan_line_id
order by 1

"SQL_PLAN_LINE_ID" "COUNT(*)"
34                 135
35                 5
36                 2
37                 1
"" 2"",            2

At DB2:
select sql_plan_line_id , count(*)
from dba_hist_active_sess_history
where 
    sql_id = 'fmhbn1tn0c54z'
and sample_time
        between to_date('11/25/2012:09:00:00','MM/DD/YYYY:HH24:MI:SS’)
        and to_date('11/25/2012:10:00:00','MM/DD/YYYY:HH24:MI:SS’)
group by sql_plan_line_id
order by 1

"SQL_PLAN_LINE_ID" "COUNT(*)"
33                  467 <—— Deviation
34                  135
35                  5
36                  2
37                  1
"" 2"",             2

We see that the difference starts at line 33 of the execution plan, and we can focus on finding the root cause.

June 7, 2013:

Great note by Kerry Osborne – http://kerryosborne.oracle-guy.com/2013/06/sql-gone-bad-but-plan-not-changed/. Identical  PLAN_HASH_VALUEs are not a  guarantee that the underlying execution plans are identical.  This does not change the original post in any way, it is just something to be aware of.

Advertisements

2 Responses to Same SQL_ID, same execution plan (SQL_PLAN_HASH_VALUE), greatly different elapsed time – a simple way to troubleshoot this problem with ASH

  1. Tomas Winston says:

    Hi Iordan,
    First of all, apologies, I realise that this post is a number of months old.

    When I first saw your post I got a little excited at the prospect of using this sql script to debug a performance issue on a query.

    However, our DB is Oracle 10g so I am curious if there is a similar way of doing the same thing for Oracle 10g as the sql_plan_line_id column (along with some others) were only introduced in 11gR1?

    Many thanks in advance,

    Tomás

    • iiotzov says:

      Hi Tomás,

      Sorry for the delay.

      In 10g, we can have a query that could detect differences in the number of physical reads from a table/index.
      You can compare that numbers across different executions/environments, see where they start to deviate, and investigate further.
      Unfortunately, that query would be valuable only if most of the wait associated with the query is IO wait.

      select e.owner , e.segment_name , count(*)
      from dba_hist_active_sess_history s , dba_extents e
      where s.sql_id = 'fmhbn1tn0c54z'
      and a.sample_time
      between to_date('11/26/2012:10:00:00','MM/DD/YYYY:HH24:MI:SS')
      and to_date('11/26/2012:11:00:00','MM/DD/YYYY:HH24:MI:SS')
      and s.p1 = e.file_id
      and s.p2 between e.block_id and (e.block_id + e.blocks - 1)
      group by e.owner , e.segment_name

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: