Tracing Oracle SQL plan execution with DTrace

SQL is a declarative language – in other words you just declare what needs to be done and Oracle takes care of the part how it’s done.

However there’s nothing declarative about the actual SQL execution when it happens. SQL plan is just a tree of kernel rowsource functions executed in a specific order (defined in child cursor’s sql area).

The root of SQL plan is where the fetch function (opifch2 for example) gets the rows for passing back to the user (or PL/SQL engine).
The branches are operations like joins, union etc, which don’t have access to any data themselves and can just call other functions recursively to get rows
The leaves are the execution plan operations without any children, they call data layer to acces actual datablocks.

The first execution plan line (with lowest ID) without any children is the one where data access starts, that’s the place where first logical IO happens.

A commented exec plan is below:

SQL> select count(*) from all_users;

  COUNT(*)
----------
        35

SQL> @x

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
SQL_ID  b2zqhgr5tzbpk, child number 0
-------------------------------------
select count(*) from all_users

Plan hash value: 3268326079

--------------------------------------------------------------------------
| Id  | Operation            | Name  | E-Rows |  OMem |  1Mem | Used-Mem |
--------------------------------------------------------------------------
|   1 |  SORT AGGREGATE      |       |      1 |       |       |          |       <- ROOT
|*  2 |   HASH JOIN          |       |     35 |  1517K|  1517K|  637K (0)| <- BRANCH
|*  3 |    HASH JOIN         |       |     35 |  1593K|  1593K| 1361K (0)| <- BRANCH
|   4 |     TABLE ACCESS FULL| TS$   |     13 |       |       |          |   <- LEAF
|*  5 |     TABLE ACCESS FULL| USER$ |     35 |       |       |          |    <- LEAF
|   6 |    TABLE ACCESS FULL | TS$   |     13 |       |       |          |    <- LEAF
--------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("U"."TEMPTS#"="TTS"."TS#")
   3 - access("U"."DATATS#"="DTS"."TS#")
   5 - filter("U"."TYPE#"=1)

I have written about how to map execution plan lines back to kernel functions here:

http://blog.tanelpoder.com/2008/06/15/advanced-oracle-troubleshooting-guide-part-6-understanding-oracle-execution-plans-with-os_explain/

The above approach is based on pstack, mostly useful for demonstrations but has helped me to diagnose one spinning condition in an execution plan once (that’s the whole reason I came up with this technique).

As I said above, SQL execution just means that the kernel’s rowsource functions are executed in a loop with order and hierarchy specified in the child cursor’s execution plan.

So, if you want to learn and really understand the sequence of SQL plan execution – it’s dead easy with DTrace. Here’s what happens when you fetch from the above execution plan:

solaris02$ dtrace -p 1063 -Fn 'pid$target:oracle:qer*Fetch*:entry pid$target:oracle:qer*Fetch*:return' | tee plan.txt
dtrace: description 'pid$target:oracle:qer*Fetch*:entry pid$target:oracle:qer*Fetch*:return' matched 264 probes
CPU FUNCTION
  1  -> qergsFetch
  1    -> qerhjFetch
  1      -> qerhjFetch
  1        -> qertbFetch
  1        <- qertbFetch
  1        -> qertbFetch
  1        <- qertbFetch
  1      <- qerhjFetch
  1      -> qertbFetch
  1      <- qertbFetch
  1    <- qerhjFetch
  1  <- qergsFetch
^C

qer*Fetch functions are the Query Execution Runtime (or Rowsource if you like) functions. They are the functions corresponding to lines you see in an execution plan.

So I used the knowledge from Metalink note 175982.1 to write a little sed script which replaces the function name with its description (you need to do this yourself or look into my os_explain shell script):

solaris02$ sed -f os_explain.sed plan.txt
CPU FUNCTION
  1  -> GROUP BY SORT: Fetch
  1    -> HASH JOIN: Fetch
  1      -> HASH JOIN: Fetch
  1        -> TABLE ACCESS: Fetch
  1        <- TABLE ACCESS: Fetch
  1        -> TABLE ACCESS: Fetch
  1        <- TABLE ACCESS: Fetch
  1      <- HASH JOIN: Fetch
  1      -> TABLE ACCESS: Fetch
  1      <- TABLE ACCESS: Fetch
  1    <- HASH JOIN: Fetch
  1  <- GROUP BY SORT: Fetch
solaris02$

Voila, here’s the sequence of execution plan line invocations due the fetch.

Of course there’s more than just that to understand the whole picture, but I hope I demonstrated, tracing plan execution is not a hard topic. If you want more, hire me for a special seminar ;-)

Note that this year’s only Advanced Oracle Troubleshooting class takes place in the end of April/May 2014, so sign up now if you plan to attend this year!

This entry was posted in Cool stuff, Oracle and tagged , , . Bookmark the permalink.

12 Responses to Tracing Oracle SQL plan execution with DTrace

  1. Tom says:

    Tanel,

    Good stuff. Anyway to get an object ID or Object reference with the execution plan?

  2. Tanel Poder says:

    Yep its possible (the 1st parameter to these function calls is the memory address of the rowsource metadata in the execution plan in child cursor). Its possible to do it but I haven’t implemented this yet in a script (I’ve done it manually few times when looking into a specific problem)

  3. Dale says:

    I see this shows the execution plan, but, where does oracle take a trace that shows the data used in the SQL. I have not found any tool or oracle ability to capture the SQL with the data associated with each individual SQL execution.

    Any ideas what tool can do this?

  4. Aingle Pack says:

    Hi Tanel,

    As usual your work is innovative and very useful. I have a question here. I have heard that dtrace has been ported to Linux. Have you tried it on Linux and do you think its functionality is as reliable on Linux as it is on Solaris?

    Regards
    Aingle

  5. Tanel Poder says:

    Hi Aingle,

    I guess you’re talking about this site:
    http://www.crisp.demon.co.uk/blog/

    I’ve kept an eye on this but not tried it out yet as this is not production quality code, thus not fully useful for real-life troubleshooting. This can be useful in testing, experimenting and other hacking though. By the way there is a project called SystemTap which is Linux world’s attempt to come up with something like DTrace, but it can’t do userland tracing as far as I know yet.

  6. Annalyn MArcelo says:

    very useful. As usual your work is innovative and very useful. I have a question here. I have heard that the trace has been ported to Linux. Have you tried it on Linux and do you think its functionality is as reliable on Linux as it is on Solaris?

  7. Annalyn MArcelo says:

    hi there..

  8. Annalyn MArcelo says:

    i’m annalyn marcelo from dlsu-d.

  9. Annalyn MArcelo says:

    i’m annalyn marcelo from dlsu-d. great!

  10. Pingback: DB Optimizer » Getting Started with Dtrace

  11. Pingback: Secret Hacking Session: Find Out How Oracle SQL Plans Are Really Executed! | Tanel Poder's blog: IT & Mobile for Geeks and Pros

  12. Pingback: Kyle Hailey » Getting Started with Dtrace

Leave a Reply

Your email address will not be published. Required fields are marked *

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>