{"id":73190,"date":"2014-08-19T12:00:56","date_gmt":"2014-08-19T12:00:56","guid":{"rendered":"https:\/\/www.red-gate.com\/simple-talk\/uncategorized\/execution-plans-part-8-cost-time-etc\/"},"modified":"2021-07-14T13:07:30","modified_gmt":"2021-07-14T13:07:30","slug":"execution-plans-part-8-cost-time-etc","status":"publish","type":"post","link":"https:\/\/www.red-gate.com\/simple-talk\/databases\/oracle-databases\/execution-plans-part-8-cost-time-etc\/","title":{"rendered":"Execution Plans Part 8: Cost, time, etc."},"content":{"rendered":"<p><span style=\"font-size: 13px;\">It\u2019s time to move away from the <em><strong>shape<\/strong><\/em> of an execution plan and turn our attention to some of the numerical information we get from the plan. In this article we\u2019re going to look only at the predictions that the optimizer makes (<em><strong>explain plan<\/strong><\/em>), postponing any investigation of actual run-time figures (<em><strong>v$sql_plan_statistics_all<\/strong><\/em>) for future instalments.<\/span><\/p>\n<h2>Getting Started<\/h2>\n<p>As a reference point we\u2019re going to start with a very simple query and plan (from an instance of 11.2.0.4):<\/p>\n<pre>explain plan for\r\nselect\r\n        t1.id, t2.id\r\nfrom\r\n        t2, t1\r\nwhere\r\n        t2.n1 = 15\r\nand     t1.n1 = t2.n2\r\n;\r\n\r\nselect * from table(dbms_xplan.display(null, null, 'projection'));\r\n\r\n--------------------------------------------------------------------------------------\r\n| Id  | Operation                    | Name  | Rows  | Bytes | Cost (%CPU)| Time     |\r\n--------------------------------------------------------------------------------------\r\n|   0 | SELECT STATEMENT             |       |   225 |  4500 |    35   (6)| 00:00:01 |\r\n|*  1 |  HASH JOIN                   |       |   225 |  4500 |    35   (6)| 00:00:01 |\r\n|   2 |   TABLE ACCESS BY INDEX ROWID| T2    |    15 |   180 |    16   (0)| 00:00:01 |\r\n|*  3 |    INDEX RANGE SCAN          | T2_I1 |    15 |       |     1   (0)| 00:00:01 |\r\n|   4 |   TABLE ACCESS FULL          | T1    |  3000 | 24000 |    18   (6)| 00:00:01 |\r\n--------------------------------------------------------------------------------------\r\n\r\nPredicate Information (identified by operation id):\r\n---------------------------------------------------\r\n   1 - access(\"T1\".\"N1\"=\"T2\".\"N2\")\r\n   3 - access(\"T2\".\"N1\"=15)\r\n\r\nColumn Projection Information (identified by operation id):\r\n-----------------------------------------------------------\r\n   1 - (#keys=1) \"T2\".\"ID\"[NUMBER,22], \"T1\".\"ID\"[NUMBER,22]\r\n   2 - \"T2\".\"ID\"[NUMBER,22], \"T2\".\"N2\"[NUMBER,22]\r\n   3 - \"T2\".ROWID[ROWID,10]\r\n   4 - \"T1\".\"ID\"[NUMBER,22], \"T1\".\"N1\"[NUMBER,22]<\/pre>\n<p>If you&#8217;ve worked through the previous instalments in this series you&#8217;ve probably worked out very quickly that the run-time order of operation for this plan is 3, 2, 4, 1, 0: we do an index range scan (line 3) to get data from table <em><strong>t2<\/strong><\/em> (line 2) to build an in-memory hash table, then do a full scan of table <em><strong>t1<\/strong><\/em> (line 4) to probe the hash table for matching data (line 1) passing the result on to the end user (line 0). What we\u2019re going to spend time on in this article is interpreting the numeric data \u2013 the columns headed Rows, Bytes, Cost (%CPU), and Time.<\/p>\n<p>A key point to remember when looking at the predictions made by explain plan is that the numbers on a line of a plan describe one execution of that line (the same is not true when you look at the row source execution statistics from the view v$sql_plan_statistics_all); a second, equally important, point is that the Cost and Time figures accumulate upwards from child operation to parent operation.<\/p>\n<p>A final, less helpful, point is that there are plenty of defects that make it hard to produce an accurate interpretation of the numbers \u2013 rounding blurs the issue, some figures are missing, some numbers appear on the wrong line, some of the numbers in the plan are not consistent with the numbers you can find in the corresponding 10053 traces. For various reasons you\u2019re likely to find cases (and I will be showing you some very simple cases in later instalments) where the description I give seems to be broken around the edges.<\/p>\n<p>Note: In this example I&#8217;ve included the &#8220;projection&#8221; information from the plan table in the output; that\u2019s not something I usually do but I&#8217;ll be talking about it later on in the worked example.<\/p>\n<h2>Basic explanation<\/h2>\n<p>Here\u2019s a quick summary of the columns:<\/p>\n<table border=\"1\" cellspacing=\"0\" cellpadding=\"0\">\n<tbody>\n<tr>\n<td valign=\"top\" width=\"104\">Rows<\/td>\n<td valign=\"top\" width=\"765\">The predicted number of rows supplied to its parent by one execution of this operation<\/td>\n<\/tr>\n<tr>\n<td valign=\"top\" width=\"104\">Bytes<\/td>\n<td valign=\"top\" width=\"765\">The predicted number of bytes (rows x expected row size) supplied to its parent by one execution of this operation<\/td>\n<\/tr>\n<tr>\n<td valign=\"top\" width=\"104\">Cost<\/td>\n<td valign=\"top\" width=\"765\">The prediction of resources required for one execution of this operation \u2013 including the resources required for every execution of every descendent of this operation that would be needed for this operation to complete once. The figure in parentheses (%CPU) is the fraction of the resource usage that can be attributed to CPU activity. As we will see below, there are two ways of interpreting the cost.<\/td>\n<\/tr>\n<tr>\n<td valign=\"top\" width=\"104\">Time<\/td>\n<td valign=\"top\" width=\"765\">The predicted elapsed time (hours:minutes:seconds) required to execute this operation just once. As with cost, the time for a single execution of the operation includes the time spent in all the executions of all the child operations needed to complete one execution of this operation.<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n<p>&nbsp;<\/p>\n<p>I<span style=\"font-size: 13px;\">\u2019ve been a bit heavy-handed with my use of the word <em>\u201cpredicted\u201d<\/em> and the phrase <em>\u201cone execution\u201d<\/em>\u00a0but it\u2019s important to remember that predictions can be (often are) wrong; and that part of the prediction the optimizer makes &#8211; and it&#8217;s a part that is sometime hidden &#8211; is <em>\u201chow many times will this operation execute\u201d<\/em>, so the figures for one execution of one operation become an important aspect of understanding the totals for the whole plan.<\/span><\/p>\n<p><span style=\"font-size: 13px;\">I made the point that there are two ways of interpreting the \u201ccost\u201d column. I&#8217;ve argued for many years that the optimizer\u2019s cost figure represents the predicted time to run: (see, for example, <a href=\"http:\/\/jonathanlewis.wordpress.com\/2006\/12\/11\/cost-is-time\/\"><strong><em>\u201cCost is time\u201d<\/em><\/strong><\/a>). If you take the cost figure from the execution plan output, multiply it by the single block read time (<em><strong>sreadtim<\/strong><\/em>) from the system statistics table (<em><strong>aux_stats$<\/strong><\/em>) then \u2013 allowing for rounding \u2013 the answer you produce will be the time reported in the execution plan. Alternatively, if you don\u2019t want to believe that cost represents time, you could interpret the cost figure, informally, by saying <em>\u201cthe resource impact of this query is equivalent to this many (real) single block random reads\u201d<\/em>.<\/span><\/p>\n<h2>Example<\/h2>\n<p><span style=\"font-size: 13px;\">With that background, let\u2019s apply what we&#8217;ve learned to the example at the start of the article. It\u2019s a particularly easy example to start with because each line of the plan executes exactly once. As we saw earlier, the order of operation is: line 3, line 2, line 4, line 1, line 0<\/span><\/p>\n<ul>\n<li><span style=\"font-size: 13px;\">Line 3: index range scan \u2013 predicts 15 rows returned, but no bytes! The \u201cprojection\u201d information that I requested from dbms_xplan.display() tells us something about the columns produced and forwarded by each line of the plan. In line 3 we can see that the only \u201ccolumn\u201d returned by this operation is described as <em>&#8220;T2&#8221;.ROWID[ROWID,10]<\/em>. I don\u2019t know why this didn&#8217;t reveal itself in the bytes column with a value of 150 (15 * 10), but perhaps it\u2019s because the rowid is a pseudo-column and doesn\u2019t have an entry in <em><strong>dba_tab_columns<\/strong><\/em> to give the optimizer a value for <em><strong>avg_col_len <\/strong><\/em>(average column length). The cost for this range scan is 1 \u2013 it\u2019s a very small index (root block and 7 leaf blocks), the optimizer has assumed the root block will be cached and that it will do one physical read to find a single leaf block. The predicted time is 1 * sreadtim \u2013 which happens to be 6 milliseconds in my case \u2013 rounded up to one second.<\/span><\/li>\n<\/ul>\n<ul>\n<li><span style=\"font-size: 13px;\">Line 2: table access by rowid \u2013 the optimizer thinks the 15 rowids we get from line 3 will allow line 2 to acquire 15 table rows and, since there are no filter operations, forward all of them. According to the bytes column the data we acquire from those 15 rows will have an average row length of 12 bytes (12 * 15 = 180). Checking the projection information we see that the columns projected will be: <em>&#8220;T2&#8221;.&#8221;ID&#8221;[NUMBER,22], &#8220;T2&#8221;.&#8221;N2&#8243;[NUMBER,22]<\/em>, and checking the data dictionary for these columns we see that both have an avg_row_len of 4 bytes, which leaves me wondering why the bytes column didn\u2019t report 120 rather than 180 (perhaps the optimizer is erroneously including in its calculation the <em><strong>t2.n1<\/strong><\/em> column &#8211; also with an avg_row_len of 4 &#8211; which we used in line 3). The cost of this operation is 16, which is 1 carried forward from line 3 (cost accumulates upwards from child to parent) plus 15 because the optimizer thinks the 15 rows will be scattered across 15 table blocks which will be subject to physical read requests. The predicted time is 16 * sreadtim which is 96 milliseconds, which again rounds up to one second.<\/span><\/li>\n<\/ul>\n<ul>\n<li><span style=\"font-size: 13px;\">Line 4: table access full of t1 \u2013 there are 3,000 rows in the table and the operation doesn&#8217;t filter out any of them. The bytes column is 24,000 which is an average of 8 bytes per row; this is good because when we check the projection information we see that the operation returns: <em>&#8220;T1&#8221;.&#8221;ID&#8221;[NUMBER,22], &#8220;T1&#8221;.&#8221;N1&#8243;[NUMBER,22]<\/em> and a check of the data dictionary shows that both columns have an avg_row_len of 4 \u2013 in this case the arithmetic is consistent with our expectation. The cost is 18 which, by one definition, means the resource requirement is equivalent to 18 single block random reads \u2013 even though we know that Oracle will be using multiblock (probably non-random) reads to scan the table \u2013 but the optimizer has some built-in arithmetic to adjust between single block and multiblock reads (See, for example, <a href=\"http:\/\/jonathanlewis.files.wordpress.com\/2010\/11\/cpu_costing.pdf\"><em><strong>this<\/strong> <strong>article<\/strong><\/em><\/a> I wrote for Oracle Magazine 10 years ago). In this case, though we see that 6% of the cost has been attributed to CPU usage \u2013 that\u2019s an interesting reminder that tablescans don\u2019t just consume disc resources, examining every row in a table can use up a lot of CPU. If we want to look more closely at the detail we could query the <em><strong>plan_table<\/strong><\/em> directly to check the columns <em><strong>cost<\/strong><\/em>, <em><strong>io_cost<\/strong><\/em>, and <em><strong>cpu_cost<\/strong><\/em> which, in my case, held: (18, 17, 1108201). That article explains how CPU time is factored into the final cost, so I won\u2019t repeat the details here. Again, the result of the conversion from cost to time evaluates to 1 second.<\/span><\/li>\n<\/ul>\n<ul>\n<li><span style=\"font-size: 13px;\">Line 1: the hash join \u2013 you&#8217;ll have to take my word for it that the optimizer has actually predicted the row count correctly, I was expecting 225 rows from the join (I happen to know that each row in <em><strong>t2<\/strong><\/em> corresponds to 15 rows in <em><strong>t1<\/strong><\/em>). Again, though, there\u2019s an anomaly in the bytes calculation \u2013 the prediction gives us an average of 20 bytes per row when the projection tells us it\u2019s just two columns which the data dictionary says each have an avg_col_len of 4; and again it looks as if the optimizer has factored in every column (all 5 of them) used in the plan up to that point. The cost figure is a little interesting \u2013 it should be accumulating up the plan from child to parent so, at first glance, you might expect it to be the sum of the costs of lines 2 and 4 (which happen once each for each execution of line 1), but 16 + 18 = 34, not 35. The explanation for the difference comes from the work inherent in doing the hash join itself. If we look at the <em><strong>cost<\/strong><\/em>, <em><strong>io_cost<\/strong><\/em>, and <em><strong>cpu_cost<\/strong><\/em> for those three lines we see the following:<\/span><\/li>\n<\/ul>\n<pre style=\"padding-left: 60px;\">ID OBJECT_NAME       COST   IO_COST  CPU_COST\r\n-- --------------- ------ --------- ---------\r\n 2 T2                  16         16   120643\r\n 4 T1                  18         17  1108201\r\n 1                     35         33  2131094<\/pre>\n<ul>\n<li><span style=\"font-size: 13px;\">The I\/O costs show a simple accumulation \u2013 the hash join itself doesn&#8217;t (in this case) introduce any further I\/O \u2013 but the sum of the CPU costs of lines 2 and 4 comes to just 1,228,844 which doesn&#8217;t match the reported CPU cost for line 1 (2131094); the CPU cost inherent in the hash join is a further 902,250. With scaling and rounding, this adds 2 to the total I\/O cost to get us to the final cost. The extra CPU for the hash join also explains why the CPU component of cost is still 6%: (35 \u2013 33)\/35 = 0.057.<\/span><\/li>\n<\/ul>\n<p>If you&#8217;re wondering why I&#8217;ve been making so much fuss about the oddities in the bytes column I can give you two reasons &#8211; firstly it&#8217;s just a convenience that in this very simple sample I can use the column to show that the information that&#8217;s supposed to be in a plan can be wrong; secondly, and more importantly, the optimizer&#8217;s decision on whether or not to use a hash join, and which input to use as the build and which the probe is (in part) dependent on the data volume i.e. the bytes prediction. \u00a0The fuss I&#8217;ve been making about the detail of the bytes column might explain some of the cases where you&#8217;ve seen Oracle picking the wrong execution plan.<\/p>\n<h2>Summary<\/h2>\n<p>We&#8217;ve taken a very simple query, and walked through each line of the plan thinking about where the numbers come from and what they mean. In this simple example we&#8217;ve seen how cost and time accumulate up the plan and described the relationship between these two numbers; we&#8217;ve also seen how the cost is made up of an I\/O cost and a CPU cost and noted that the CPU cost can (quite reasonably) be a significant fraction of the total cost.<\/p>\n<p>Our example was so simple that we haven\u2019t really had an opportunity to examine the consequences of the fact that the figures reported for an operation represent a single execution of that operation, and that\u2019s something we will address in the next instalment. Even in this very simple example, though, we have managed to highlight a couple anomalies with the numbers (fortunately only in the bytes column, so far) which may be missing, or might be misleading. As we examine further examples we\u2019ll see increasing numbers of anomalies that can confuse the issue if we stick too rigidly to the basic rules for interpreting the plan \u2013 a little flexibility and forgiveness will be needed.<\/p>\n","protected":false},"excerpt":{"rendered":"<p>It\u2019s time to move away from the shape of an execution plan and turn our attention to some of the numerical information we get from the plan. In this article we\u2019re going to look only at the predictions that the optimizer makes (explain plan), postponing any investigation of actual run-time figures (v$sql_plan_statistics_all) for future instalments. Getting Started As a referenc&hellip;<\/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":[48384,4783,48539],"coauthors":[],"class_list":["post-73190","post","type-post","status-publish","format-standard","hentry","category-oracle-databases","tag-costings","tag-execution-plans","tag-walkthrough"],"acf":[],"_links":{"self":[{"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts\/73190","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=73190"}],"version-history":[{"count":1,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts\/73190\/revisions"}],"predecessor-version":[{"id":91678,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts\/73190\/revisions\/91678"}],"wp:attachment":[{"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/media?parent=73190"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/categories?post=73190"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/tags?post=73190"},{"taxonomy":"author","embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/coauthors?post=73190"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}