{"id":73201,"date":"2014-05-14T18:21:46","date_gmt":"2014-05-14T18:21:46","guid":{"rendered":"https:\/\/www.red-gate.com\/simple-talk\/uncategorized\/execution-plans-part-4-precision-and-timing\/"},"modified":"2021-07-14T13:07:33","modified_gmt":"2021-07-14T13:07:33","slug":"execution-plans-part-4-precision-and-timing","status":"publish","type":"post","link":"https:\/\/www.red-gate.com\/simple-talk\/databases\/oracle-databases\/execution-plans-part-4-precision-and-timing\/","title":{"rendered":"Execution Plans Part 4: Precision and Timing"},"content":{"rendered":"

In part 3 <\/a>of this series we used a simple hash join to introduce the a simple guideline for reading execution plans \u2013 the \u201cfirst child first, recursive descent\u201d<\/em> method. This allowed us to work out the order in which Oracle produced rowsources and (implicitly) the order in which it visited the different physical objects in the query.<\/p>\n

At the start of this series I emphasized the point that this rule doesn’t work in all cases and in part 5 we will be looking at some of the cases where we have to be more subtle; but for part 4 we\u2019re going to stick with the simpler cases to look at some details of the timing and use of predicates as we apply the rule.<\/p>\n

Basics<\/h2>\n

Here\u2019s the basic execution plan for our two-table hash join again:<\/p>\n

--------------------------------------------------------------------------------------\r\n| Id  | Operation                    | Name  | Rows  | Bytes | Cost (%CPU)| Time     |\r\n--------------------------------------------------------------------------------------\r\n|   0 | SELECT STATEMENT             |       |    10 |   300 |    22   (0)| 00:00:01 |\r\n|*  1 |  HASH JOIN                   |       |    10 |   300 |    22   (0)| 00:00:01 |\r\n|   2 |   TABLE ACCESS BY INDEX ROWID| T1    |    10 |   150 |    11   (0)| 00:00:01 |\r\n|*  3 |    INDEX RANGE SCAN          | T1_I1 |    10 |       |     1   (0)| 00:00:01 |\r\n|   4 |   TABLE ACCESS BY INDEX ROWID| T2    |    10 |   150 |    11   (0)| 00:00:01 |\r\n|*  5 |    INDEX RANGE SCAN          | T2_I1 |    10 |       |     1   (0)| 00:00:01 |\r\n--------------------------------------------------------------------------------------\r\n\r\nPredicate Information (identified by operation id):\r\n---------------------------------------------------\r\n   1 - access(\"T2\".\"ID\"=\"T1\".\"ID\")\r\n   3 - access(\"T1\".\"N_1000\"=1)\r\n   5 - access(\"T2\".\"N_1000\"=100)<\/pre>\n
By applying the \u201cfirst child first\u201d<\/em> rule we decided that the run-time engine would start with an index range scan of t1_i1<\/strong><\/em> at line 3, using the rowids it acquired there to select columns from t1<\/strong><\/em> at line 2 and build an in-memory hash table at line 1 from that data; then it would do an index range scan of t2_i1<\/strong><\/em> at line 5, using the rowids it acquired there to select columns from t2<\/strong><\/em> and probe the in-memory hash table to find matches and construct a new rowsource at line 1 that would be passed upwards and onwards to the client program.<\/p>\n
Thinking about this description we can appreciate that there is a difference in the way Oracle handles the two child operations to the hash join. The second child (access to t2<\/strong><\/em>) cannot start until the first child (access to t1<\/strong><\/em>) has completed \u2013 the hash join is an example of a \u201cblocking\u201d<\/em> operation. Once the hash table has been built, however, Oracle can call the second child to return one row at a time, probe the hash table, and pass each surviving row in turn up to its parent operation \u2013 so there is a piecewise flow of data from that moment onwards.<\/p>\n
I have occasionally seen the suggestion that because of this blocking operation the optimizer can\u2019t do a hash join when using the\u00a0first_rows(n)<\/em><\/strong> \u2013 or even the old first_rows<\/strong><\/em> \u2013 optimization mode. This isn’t true \u2013 if the optimizer thinks that it can build the hash table very quickly and find the first row from the second table very cheaply then a hash join may still turn out to be the lowest cost path it can find to return the first N rows.<\/p>\n
We can compare the blocking effects of a hash join with a different join option by hinting the optimizer into a merge join \u2013 which gives us this plan:<\/p>\n
---------------------------------------------------------------------------------------\r\n| Id  | Operation                     | Name  | Rows  | Bytes | Cost (%CPU)| Time     |\r\n---------------------------------------------------------------------------------------\r\n|   0 | SELECT STATEMENT              |       |    10 |   300 |    24   (9)| 00:00:01 |\r\n|   1 |  MERGE JOIN                   |       |    10 |   300 |    24   (9)| 00:00:01 |\r\n|   2 |   SORT JOIN                   |       |    10 |   150 |    12   (9)| 00:00:01 |\r\n|   3 |    TABLE ACCESS BY INDEX ROWID| T1    |    10 |   150 |    11   (0)| 00:00:01 |\r\n|*  4 |     INDEX RANGE SCAN          | T1_I1 |    10 |       |     1   (0)| 00:00:01 |\r\n|*  5 |   SORT JOIN                   |       |    10 |   150 |    12   (9)| 00:00:01 |\r\n|   6 |    TABLE ACCESS BY INDEX ROWID| T2    |    10 |   150 |    11   (0)| 00:00:01 |\r\n|*  7 |     INDEX RANGE SCAN          | T2_I1 |    10 |       |     1   (0)| 00:00:01 |\r\n---------------------------------------------------------------------------------------\r\n\r\nPredicate Information (identified by operation id):\r\n---------------------------------------------------\r\n   4 - access(\"T1\".\"N_1000\"=1)\r\n   5 - access(\"T2\".\"ID\"=\"T1\".\"ID\")\r\n       filter(\"T2\".\"ID\"=\"T1\".\"ID\")\r\n   7 - access(\"T2\".\"N_1000\"=100)<\/pre>\n
In this plan we see a merge join operation in line 1 which has two child operations, the sort join in line 2 and a second sort join in line 5. Applying \u201cfirst child first\u201d<\/em>\u00a0recursively we infer that Oracle starts with an index range scan on t1_i1<\/strong><\/em>, accesses data we might want from t1<\/strong><\/em>, and sorts it (on the id<\/strong><\/em> column since that\u2019s the join column) at line 2. If we\u2019re lucky, the sorted data set will fit in memory (in the session\u2019s PGA) at line 1: the first child is a blocking operation \u2013 we can\u2019t start the second child until that sort is complete.<\/p>\n
Then we go to the second child and, following \u201cfirst child first\u201d<\/em> again, we see that we do an index range scan of t2_i1<\/strong><\/em>, visit t2<\/strong><\/em>, and sort the resulting data set (again on the id<\/strong><\/em> column and again, we hope, into memory): the second child is also a blocking operation \u2013 the merge join itself can\u2019t get started until the sort completes.<\/p>\n
When the two sorted rowsources are available the merge join can walk through the first rowsource one row at a time, probing the second rowsource for matches and constructing result rows to pass upwards to its parent. Since the second rowsource is sorted the amount of work that Oracle has to do to find each set of matching rows is at worst o(log(N))<\/em><\/strong> \u2013 where N is the number of rows in the second rowsource; Oracle can do a binary chop (using log2(N)<\/strong><\/em> checks) to find the first matching row and then scan sequentially onwards from there (though, in fact, the code is smarter than that and takes advantage of the fact that the probes are coming from data that is also sorted which means the code can reduce the work by \u201cremembering\u201d where it started from on the previous probe \u2013 see, for example this blog post of mine<\/a> <\/strong><\/em>on merge joins.<\/p>\n
In fact this strategy for a merge join gives us our very first case of an execution path that doesn’t quite describe exactly what\u2019s going on, and it\u2019s a case where calling on \u201crowsource execution statistics\u201d<\/em> gives us some interesting new information. Let\u2019s run the query and use a slightly more more sophisticated call to the dbms_xplan<\/strong><\/em> package to see how often the different steps of the plan are called. (Note: the following output came from 11.2.0.4, but I’ve edited out the Buffers<\/strong><\/em>, A-time<\/strong><\/em> and \u201cmemory\u201d<\/strong><\/em> columns.)<\/p>\n
alter session set statistics_level = all;\r\nset linesize 156\r\nset trimspool on\r\nset pagesize 60\r\nset serveroutput off\r\n\r\nselect\r\n        \/*+\r\n                leading(t1, t2)\r\n                use_merge(t2)\r\n        *\/\r\n        t1.v1, t2.v1\r\nfrom\r\n        t1, t2\r\nwhere\r\n        t1.n_1000 = 1\r\nand     t2.id     = t1.id\r\nand     t2.n_1000 = 100\r\n;\r\n\r\nselect * from table(dbms_xplan.display_cursor(null,null,'iostats last'));\r\n\r\n--------------------------------------------------------------------------\r\n| Id  | Operation                     | Name  | Starts | E-Rows | A-Rows |\r\n--------------------------------------------------------------------------\r\n|   0 | SELECT STATEMENT              |       |      1 |        |      0 |\r\n|   1 |  MERGE JOIN                   |       |      1 |     10 |      0 |\r\n|   2 |   SORT JOIN                   |       |      1 |     10 |     10 |\r\n|   3 |    TABLE ACCESS BY INDEX ROWID| T1    |      1 |     10 |     10 |\r\n|*  4 |     INDEX RANGE SCAN          | T1_I1 |      1 |     10 |     10 |\r\n|*  5 |   SORT JOIN                   |       |     10 |     10 |      0 |\r\n|   6 |    TABLE ACCESS BY INDEX ROWID| T2    |      1 |     10 |     10 |\r\n|*  7 |     INDEX RANGE SCAN          | T2_I1 |      1 |     10 |     10 |\r\n--------------------------------------------------------------------------\r\n\r\nPredicate Information (identified by operation id):\r\n---------------------------------------------------\r\n   4 - access(\"T1\".\"N_1000\"=1)\r\n   5 - access(\"T2\".\"ID\"=\"T1\".\"ID\")\r\n       filter(\"T2\".\"ID\"=\"T1\".\"ID\")\r\n   7 - access(\"T2\".\"N_1000\"=100)<\/pre>\n
The thing to look at in this output is the Starts<\/strong><\/em> column \u2013 where the little detail that might raise a question is the number of starts of line 5: the second sort. Apparently Oracle sorted the data from the second table 10 times; but since the developers at Oracle are clearly rather clever people we can be fairly sure that that\u2019s NOT what really happened: we need a better interpretation of the sort join<\/strong><\/em> operation and a clearer understanding of how it fits into the execution plan.<\/p>\n
The second sort join<\/strong><\/em> operation really comprises two components \u2013 one component probes a sorted data set based on a supplied value, while the other really does sort a data set. Perhaps a more appropriate name for the operation should be \u201cprobe an in-memory sorted data set, but acquire it and sort it if it\u2019s not already in memory\u201d<\/em>. It\u2019s worth remembering that a line in an execution plan can include higher level logic of the form \u201cif condition X is met do A else do B\u201d \u2013 the ability of a sort join to do, or not do, sorting is just one example of this.<\/p>\n
Checking the A-rows value for line 2 (the number of rows coming back from the first child) we can see that it\u2019s 10 \u2013 which explains why Oracle called the second child 10 times: just like a nested loop the second child is called once for each row from the first child. We acquire and sort the entire data set once, then reuse the sorted data, ultimately probing it a total 10 times.<\/p>\n
It\u2019s at this point that we can make an initial comment about interpreting the Predicate Information<\/strong><\/em>. If you examine line 5 you will see that it uses both an \u201caccess\u201d<\/em> predicate and a \u201cfilter\u201d<\/em> predicate \u2013 and both predicates use exactly the same expression.<\/p>\n
The difference between the two types of predicate is, loosely speaking, that an access predicate tells us how to \u201cgo and find\u201d items (rows) of data, and a filter predicate tells us how to check\u2013 after we’ve done the work of finding it \u2013 whether it was the item (row) we really wanted.<\/p>\n
In the case of the second sort join operation, the access predicate tells us how to find the position of the first matching row in the sorted data set, and the filter predicate tells us how to check each row as we walk along the sorted data set in order so that we can stop when eventually we get to a row that fails the filter predicate test.<\/p>\n
As a very informal guideline \u2013 if you think you\u2019re accessing all the tables in the right order using the right indexes, but still seem to be doing too much work while executing a query, it\u2019s possible that you\u2019re accessing too much data and then using a filter predicate to throw a lot of it away.<\/p>\n
We can take our examination of the merge join and the business of blocking and timing a little further if we have suitable indexes in place, specifically indexes on the join columns. In this case (possibly through hinting, because the optimizer seems fairly resistant to using merge joins) our execution plan could look like this:<\/p>\n
--------------------------------------------------------------------------\r\n| Id  | Operation                     | Name  | Starts | E-Rows | A-Rows |\r\n--------------------------------------------------------------------------\r\n|   0 | SELECT STATEMENT              |       |      1 |        |      0 |\r\n|   1 |  MERGE JOIN                   |       |      1 |     10 |      0 |\r\n|*  2 |   TABLE ACCESS BY INDEX ROWID | T1    |      1 |     10 |     10 |\r\n|   3 |    INDEX FULL SCAN            | T1_PK |      1 |  10000 |  10000 |\r\n|*  4 |   SORT JOIN                   |       |     10 |     10 |      0 |\r\n|*  5 |    TABLE ACCESS BY INDEX ROWID| T2    |      1 |     10 |     10 |\r\n|   6 |     INDEX FULL SCAN           | T2_PK |      1 |  10000 |  10000 |\r\n--------------------------------------------------------------------------\r\n\r\nPredicate Information (identified by operation id):\r\n---------------------------------------------------\r\n   2 - filter(\"T1\".\"N_1000\"=1)\r\n   4 - access(\"T2\".\"ID\"=\"T1\".\"ID\")\r\n       filter(\"T2\".\"ID\"=\"T1\".\"ID\")\r\n   5 - filter(\"T2\".\"N_1000\"=100)<\/pre>\n
In this example the \u201cPK\u201d<\/em> indexes are based on the id<\/strong><\/em> column, which means the two index full scan operations at lines 3 and 6 are accessing the data in exactly the order we need to avoid sorting. We can see from the plan that Oracle doesn’t sort the first (t1<\/strong><\/em>) data set it simple gets the rows in order, and uses a filter predicate at line 2 to eliminate all the rows it doesn’t need.<\/p>\n
Looking at the A-rows in line 3 and comparing it with the A-rows in line 2 we can see that we have generated a rowsource of 10,000 items (rowids, basically) at line 3 and used the filter predicate in line 2 to discard all but 10 rows after visiting the table (10,000 times – oops!) to acquire the corresponding rows \u2013 potentially a hugely inefficient thing to do.<\/p>\n
The same level of inefficiency is visible in lines 5 and 6 \u2013 we do an index full scan, returning 10,000 rowids in line 6, and then use a filter predicate after visiting table t2<\/strong><\/em> in line 5, discarding 9,990 of the rows. The strangest thing about the treatment of table t2<\/strong><\/em>, though, is that we sort the resulting rowsource in line 4 \u2013 even though we should know that it is already in the correct sorted order for the merge join. The explanation for this apparently redundant sort is that it\u2019s a convenient way of getting the data out of the buffer cache and into a private work area; it\u2019s not really being done to re-arrange the data into the right order.<\/p>\n
This plan shows another variation in the way that blocking operations can appear. The way we access the first table is not a blocking operations, it\u2019s only as we access the second table that a blocking operation (the sort) appears. The pattern of execution in this plan is:<\/p>\n
    \n
  1. Start the index full scan for t1<\/strong><\/em>, find the first eligible row for the join<\/span><\/li>\n
  2. Do an index full scan for t2<\/strong><\/em>, find all eligible rows for the join, transfer them (through a redundant sort) into the private work area; probe the work area for the first matching row and return subsequent matches for the merge<\/span><\/li>\n
  3. Fetch the second candidate row from t1<\/strong><\/em> (stepping along the index, visiting the table and discarding as necessary)<\/span><\/li>\n
  4. Probe the work area for the starting match for the second row etc.<\/span><\/li>\n
  5. Repeat from (3)<\/span><\/li>\n<\/ol>\n
    We could move on to nested loops to see more examples of how the shape of the plan affects our interpretation of what Oracle is doing, and how the predicate timing can have a significant effect on how the work is done; however, there are several different execution plans for a simple nested loop, and we could easily spend too much time on the topic, so I\u2019ll refer you to an item I wrote recently on nested loops through the ages<\/strong><\/em><\/a>\u00a0and pick up a few details in passing in future articles in this series.<\/p>\n
    The key points to take away from this article are: timing is important; the operations in an execution plan don\u2019t always describe exactly what\u2019s going on; the predicate section is an important aid to understanding the work that the optimizer is expecting to happen, and the rowsource (run-time) execution statistics can be a very great aid in seeing what\u2019s really happening.<\/p>\n
     <\/p>\n","protected":false},"excerpt":{"rendered":"
    In part 3 of this series we used a simple hash join to introduce the a simple guideline for reading execution plans \u2013 the \u201cfirst child first, recursive descent\u201d method. This allowed us to work out the order in which Oracle produced rowsources and (implicitly) the order in which it visited the different physical objects in the query. At t…<\/p>\n","protected":false},"author":101205,"featured_media":0,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[143533],"tags":[4783,48506],"coauthors":[],"class_list":["post-73201","post","type-post","status-publish","format-standard","hentry","category-oracle-databases","tag-execution-plans","tag-sort-join-operations"],"acf":[],"_links":{"self":[{"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts\/73201","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/users\/101205"}],"replies":[{"embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/comments?post=73201"}],"version-history":[{"count":1,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts\/73201\/revisions"}],"predecessor-version":[{"id":91687,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts\/73201\/revisions\/91687"}],"wp:attachment":[{"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/media?parent=73201"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/categories?post=73201"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/tags?post=73201"},{"taxonomy":"author","embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/coauthors?post=73201"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}