Tracing Oracle SQL plan execution with DTrace

Tanel Poder

2009/04/24

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:

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 ;-)

Comments powered by Talkyard.