In the previous post in this series, I showed how my scripts xb.sql and xbi.sql (eXplain Better and eXplain Better, by sqlId) help you see Oracle execution plan details in a more complete way.
Here are the features that I currently plan to cover:
- More detailed access/filter predicate info next to plan tree data (Part 1)
- More intelligent row-source level execution statistics presentation (Part 2, this post)
- Calculate Optimizer Cost misestimation factor and demo its effects (Part 3, coming soon)
More intelligent row-source level execution statistics presentation
Look into the following example output by DBMS_XPLAN.DISPLAY_CURSOR, I ran it on a random benchmark query (that had rowsource level metrics collection enabled using statistics_level=all). I have truncated some output columns below, so that the output wouldn’t be that wide, but you still may need to scroll right to see the A-Time, Buffers, Reads columns:
SQL> @xi czxpthmzk8nnd 0 eXplain the execution plan for sqlid czxpthmzk8nnd child 0... ... ------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | A-Rows | A-Time | Buffers | Reads | ------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 20 |00:00:03.22 | 125K| 9391 | | 1 | SORT ORDER BY | | 1 | 20 |00:00:03.22 | 125K| 9391 | | 2 | HASH GROUP BY | | 1 | 245 |00:00:03.22 | 125K| 9391 | |* 3 | HASH JOIN | | 1 | 9056 |00:00:03.22 | 125K| 9391 | |* 4 | TABLE ACCESS FULL | DATE_DIM | 1 | 6000 |00:00:00.01 | 1456 | 0 | | 5 | NESTED LOOPS | | 1 | 112K|00:00:03.18 | 123K| 9391 | | 6 | NESTED LOOPS | | 1 | 112K|00:00:00.09 | 11240 | 77 | |* 7 | TABLE ACCESS FULL | ITEM | 1 | 160 |00:00:00.03 | 10374 | 0 | |* 8 | INDEX RANGE SCAN | STORE_SALES_PK_IDX | 160 | 112K|00:00:00.04 | 866 | 77 | | 9 | TABLE ACCESS BY GLOBAL I| STORE_SALES | 112K| 112K|00:00:03.06 | 112K| 9314 | -------------------------------------------------------------------------------------------------------------
I intentionally omitted the predicate section of this plan, as I covered predicates in the previous post and want to focus only on the metrics here.
The highlighted metrics above are cumulative. This means a few things:
- The parent node in the execution plan includes whatever time and resources its children/grandchildren have consumed (A-Time, Buffers, Reads).
- If you want to find out the time consumed by an execution plan line alone (self-time, self-value), you will have to do some math, deduct the sum of all direct children’s metrics from the cumulative metrics of their parent to compute the number that the parent itself was using.
- The root node of a plan tree shows the plan totals, cumulatively including all time and resource consumption of the plan steps.
- The leaf nodes of the plan tree show only the self-times of these leaves, as they don’t have any child nodes whose metrics to cumulatively add up.
With simple plans like above, you can just visually follow the “tree” structure and see where the biggest numbers in the plan totals originate from. The plan total A-Time for the root node SELECT STATEMENT is 3.22 seconds and its immediate child node also reports 3.22 seconds. Therefore, there was no (noticeable) extra time spent in the SELECT STATEMENT step itself.
We descend deeper into the tree and see that plan line #3, HASH JOIN reports 3.22 seconds spent in+under it, but when we add the direct child times together 0.01 seconds from #4 - TABLE ACCESS FULL [DATE_DIM] and 3.18 seconds from #5 - NESTED LOOPS, we get 0.01 + 3.18 = 3.19 seconds only. We are “missing” 30 milliseconds and this delta is the time spent inside the parent HASH JOIN step itself.
You can follow this logic step by step throughout all child nodes in the tree - or just eyeball and see what are the deepest areas of the tree with the biggest cumulative values. This becomes error-prone (and not-so-systematic), especially with plans where siblings at a certain level don’t fit onto the same screen anymore, etc.
XB-scripts to the rescue!
That’s why my xb scripts do this math for you! Now you can see the self-values consumed on each plan line immediatelly, without having to do math-eyeballing all the time.
Warning, the output is very wide, you will need either a horizontally scrolling terminal (or properly configured cmd.exe on Windows), use SQL*Developer (that can horizontally scroll script output) or just spool your sqlplus output to a file and keep it open in a text editor.
Here’s the xbi.sql output (it takes SQL_ID and child# as arguments) - scroll right to see the whole story:
SQL> @xbi czxpthmzk8nnd 0
-- xbi.sql: eXplain Better v1.01 for sql_id=czxpthmzk8nnd child=0 - by Tanel Poder (https://blog.tanelpoder.com)
SQL_ID CHLD ADDRESS Plan Hash Value First Load Time
-------- ------------- ----- ---------------- --------------- --------------------------------------------------------------------------------------------------------------------------------------------------------------
Cursor: czxpthmzk8nnd 0 000000049451AFB8 2501019660 Statement first parsed at: 2022-03-17/01:21:20 - 37 seconds ago
Pred Op Par. #Sib Query Block ms spent in Consistent Rowsource Real #rows Est. rows Opt. Card. Current Physical Physical Memory Workarea Optimizer
#Col ID ID ling Row Source name this operation gets starts returned total misestimate gets read blks write blks used (MB) Passes Cost
----- ----- ----- ----- -------------------------------------------- -------------------- -------------- ---------- ---------- ----------- ------------- --------------- ---------- ---------- ---------- ------------- ------------- -----------
0 SELECT STATEMENT >>> Plan totals >>> 3,220.09 125211 1 20 0 9391 0 121263
1 0 1 SORT ORDER BY SEL$1 .07 0 1 20 114030 5701x 0 0 0 .00 OPTIMAL 121263
2 1 1 HASH GROUP BY 3.89 0 1 245 114030 465x 0 0 0 5.54 OPTIMAL 121263
A 3 2 1 HASH JOIN 28.78 0 1 9056 114030 13x 0 0 0 1.63 OPTIMAL 117113
F 4 3 1 TABLE ACCESS FULL [DATE_DIM] SEL$1 4.02 1456 1 6000 6000 1x 0 0 0 229
5 3 2 NESTED LOOPS 39.05 0 1 112576 114030 1x 0 0 0 116883
6 5 1 NESTED LOOPS 13.67 0 1 112576 114345 1x 0 0 0 116883
F 7 6 1 TABLE ACCESS FULL [ITEM] SEL$1 31.71 10374 1 160 165 1x 0 0 0 1670
A#1 8 6 2 INDEX RANGE SCAN [STORE_SALES_PK_IDX] SEL$1 43.44 866 160 112576 110880 -1x 0 77 0 5
9 5 2 TABLE ACCESS BY GLOBAL INDEX ROWID [ST SEL$1 3,055.46 112515 112576 112576 78015168 693x 0 9314 0 698
The >>> Plan totals >>> line (root of the tree) is the only line where I still show the total, cumulative metrics of the entire plan (so you’d know how much the complete plan execution took). On all other lines, the highlighted columns have some basic math applied and show the non-cumulative self-time and self-values of the metrics:
- ms spent in this operation (A-Time, shown more precisely)
- consistent gets (Buffers, but see below)
- current gets (xb.sql reports consistent & current gets separately, unlike DBMS_XPLAN’s Buffers that combines both)
- physical read blks (Reads - unit in blocks read, not IO operations)
- physical write blks (Writes - unit in blocks written, not IO operations)
Where do I get the raw numbers from? I do not use DBMS_XPLAN at all, but go straight to the source - V$SQL_PLAN and V$SQL_PLAN_STATISTICS_ALL.
So, this makes your life easier, you can just scroll through these highlighted columns and see where the biggest numbers are, in our case operation #9 - TABLE ACCESS BY GLOBAL INDEX ROWID that used 3,055.46 ms of A-Time out of the Plan total of 3,220.09ms. Other steps in the plan clearly consumed some time too, but not significantly compared to the main troublemaker. Similarly, you can scroll right to other cumulative metrics (consistent gets, physical reads) and easily identify where most of the I/Os come from.
Here’s another slightly edited example. Let’s say you want to quickly identify where most of the logical I/Os (Buffers) come from. Scroll right and try to follow the plan tree with your eyes and parse the numbers (where some are in “Kilo” units and some not):
-------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | A-Rows | A-Time | Buffers | Reads | -------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 20 |00:00:02.90 | 170K| 153K| | 1 | TEMP TABLE TRANSFORMATION | | 1 | 20 |00:00:02.90 | 170K| 153K| | 2 | LOAD AS SELECT (CURSOR DURA| SYS_TEMP_0FD9D66BC_ | 1 | 0 |00:00:02.79 | 155K| 153K| | 3 | HASH GROUP BY | | 1 | 64004 |00:00:02.77 | 155K| 153K| |* 4 | HASH JOIN | | 1 | 2057K|00:00:02.52 | 155K| 153K| | 5 | VIEW | VW_GBF_7 | 1 | 365 |00:00:00.01 | 1456 | 0 | |* 6 | TABLE ACCESS FULL | DATE_DIM | 1 | 365 |00:00:00.01 | 1456 | 0 | | 7 | PARTITION RANGE ALL | | 1 | 11M|00:00:02.27 | 153K| 153K| | 8 | TABLE ACCESS FULL | STORE_RETURNS | 22 | 11M|00:00:02.25 | 153K| 153K| | 9 | SORT ORDER BY | | 1 | 20 |00:00:00.11 | 14987 | 0 | |* 10 | HASH JOIN | | 1 | 25597 |00:00:00.10 | 14987 | 0 | |* 11 | TABLE ACCESS FULL | STORE | 1 | 12 |00:00:00.01 | 18 | 0 | |* 12 | HASH JOIN | | 1 | 25597 |00:00:00.10 | 14968 | 0 | |* 13 | HASH JOIN | | 1 | 25597 |00:00:00.01 | 1 | 0 | | 14 | VIEW | VW_SQ_1 | 1 | 11 |00:00:00.01 | 0 | 0 | | 15 | HASH GROUP BY | | 1 | 11 |00:00:00.01 | 0 | 0 | | 16 | VIEW | | 1 | 64004 |00:00:00.01 | 0 | 0 | | 17 | TABLE ACCESS FULL | SYS_TEMP_0FD9D66BC_ | 1 | 64004 |00:00:00.01 | 0 | 0 | | 18 | VIEW | | 1 | 64004 |00:00:00.01 | 0 | 0 | | 19 | TABLE ACCESS FULL | SYS_TEMP_0FD9D66BC_ | 1 | 64004 |00:00:00.01 | 0 | 0 | | 20 | TABLE ACCESS FULL | CUSTOMER | 1 | 709K|00:00:00.05 | 14966 | 0 | --------------------------------------------------------------------------------------------------------------
And now look at the same plan using the xbi.sql tool:
SQL> @xbi bpt7vm7wbsn42 0
Pred Op Par. #Sib Query Block ms spent in Consistent Rowsource Real #rows Est. rows Opt. Card. Current Physical Physical Memory Workarea Optimizer
#Col ID ID ling Row Source name this operation gets starts returned total misestimate gets read blks write blks used (MB) Passes Cost
----- ----- ----- ----- ----------------------------------------- -------------------- -------------- ---------- ---------- ----------- ------------- --------------- ---------- ---------- ---------- ------------- ------------- -----------
0 SELECT STATEMENT >>> Plan totals >>> 2,901.67 170271 1 20 2 153524 0 44144
1 0 1 TEMP TABLE TRANSFORMATION SEL$2980E977 .06 0 1 20 1 0 0
2 1 1 LOAD AS SELECT (CURSOR DURATION MEMORY) SEL$F6D5D92C 22.31 0 1 0 1 0 0 .00 OPTIMAL
3 2 1 HASH GROUP BY 246.10 0 1 64004 2096755 33x 0 0 0 75.58 OPTIMAL 37556
A 4 3 1 HASH JOIN 253.99 1 1 2057505 2096755 1x 0 0 0 1.69 OPTIMAL 23776
5 4 1 VIEW [VW_GBF_7] SEL$7502D05D .02 0 1 365 365 1x 0 0 0 229
F 6 5 1 TABLE ACCESS FULL [DATE_DIM] SEL$7502D05D 4.35 1456 1 365 365 1x 0 0 0 229
7 4 2 PARTITION RANGE ALL 10.82 0 1 11500560 11500560 1x 0 0 0 23491
8 7 1 TABLE ACCESS FULL [STORE_RETURNS] SEL$F6D5D92C 2,254.94 153827 22 11500560 253012320 22x 0 153524 0 23491
9 1 2 SORT ORDER BY 5.03 0 1 20 100470 5024x 0 0 0 .84 OPTIMAL 6588
A 10 9 1 HASH JOIN 7.16 1 1 25597 100470 4x 0 0 0 1.22 OPTIMAL 5271
F 11 10 1 TABLE ACCESS FULL [STORE] SEL$2980E977 .04 18 1 12 12 1x 0 0 0 20
A 12 10 2 HASH JOIN 31.20 1 1 25597 104838 4x 0 0 0 4.00 OPTIMAL 5251
FA 13 12 1 HASH JOIN 4.19 1 1 25597 104838 4x 0 0 0 1.21 OPTIMAL 2535
14 13 1 VIEW [VW_SQ_1] SEL$8F9407EC .02 0 1 11 11 1x 0 0 0 1311
15 14 1 HASH GROUP BY SEL$8F9407EC 6.07 0 1 11 11 1x 0 0 0 1.01 OPTIMAL 1311
16 15 1 VIEW SEL$D67CB2D2 .05 0 1 64004 2096755 33x 0 0 0 1213
17 16 1 TABLE ACCESS FULL [SYS_TEMP_0FD9 SEL$D67CB2D2 1.86 0 1 64004 2096755 33x 0 0 0 1213
18 13 2 VIEW SEL$D67CB2D3 .05 0 1 64004 2096755 33x 0 0 0 1213
19 18 1 TABLE ACCESS FULL [SYS_TEMP_0FD9D6 SEL$D67CB2D3 1.79 0 1 64004 2096755 33x 0 0 0 1213
20 12 2 TABLE ACCESS FULL [CUSTOMER] SEL$2980E977 51.62 14966 1 709015 709015 1x 0 0 0 2284
It’s easy to spot whatever is the biggest number in a column. I typically highlight the biggest value by triple-clicking it in my terminal (so the entire plan line is highlighted and I can scroll left and right without losing the context).
Oracle requirements/limitations
Oracle requires you to use the gather_plan_statistics hint or use statistics_level=all to see these row-source level metrics (DBMS_XPLAN.DISPLAY_CURSOR is no different). You then need to run your query and either wait for it to complete (get full execution metrics) or CTRL+C or kill the session when you don’t want to wait anymore. This way you will get partial metrics up to however far the plan execution had progressed by then.
If you kill/cancel the query, then thanks to the abrupt exit, some of the top level node metrics & A-Time values do not get populated and the parent nodes will show less time/resources used compared to their children combined. The XB scripts in this case may show negative values for some operations. That’s just an Oracle instrumentation’s shortcoming when killing/canceling queries. Nevertheless, looking for the biggest (positive) values in the output still points you to the right direction.
For long enough running queries, you could just use Oracle’s SQL Monitoring feature (I have a few hacking session videos about it on YouTube) and you don’t have to deal with re-running your queries with proper instrumentation enabled. However, SQL Monitoring does not always kick in (it’s designed for long-running queries), so one more “always-on” plan-line level profiling tool in your toolbelt should be my asqlmon.sql script.
That’s all for today!
