{"id":73170,"date":"2015-03-26T09:04:05","date_gmt":"2015-03-26T09:04:05","guid":{"rendered":"https:\/\/www.red-gate.com\/simple-talk\/uncategorized\/execution-plans-part-14-sql-monitoring\/"},"modified":"2021-07-14T13:07:25","modified_gmt":"2021-07-14T13:07:25","slug":"execution-plans-part-14-sql-monitoring","status":"publish","type":"post","link":"https:\/\/www.red-gate.com\/simple-talk\/databases\/oracle-databases\/execution-plans-part-14-sql-monitoring\/","title":{"rendered":"Execution Plans Part 14: SQL Monitoring"},"content":{"rendered":"<p>This is the last part of my series on Execution plans, and features an option which is only available if you have licensed the Diagnostic and Performance Packs. It\u2019s a feature that allows you to watch the flow of data through an execution plan as the query is running, typically through the graphic interface supplied by Enterprise Manager \u00a0(or Grid Control, or Cloud Control). There is, however, a command line interface to the tool that you can use to get a text snapshot of a query as it runs, reporting the state either as flat text, an (unreadable) HTML file, or in a form that reproduces the graphic images supplied through EM \/ GC \/ CC.<\/p>\n<h2>Example<\/h2>\n<p>The command line interface to SQL Monitoring comes through the package <em><strong>dbms_sqltune<\/strong><\/em> (hence the need for the licensing) in two major functions: <em><strong>report_sql_monitor_list()<\/strong><\/em> and <em><strong>report_sql_monitor()<\/strong> <\/em>; these functions return a CLOB but there are two related functions that return XMLTYPE; both functions have a large number of parameters (11 and 19 respectively for the list and detail functions) but the functions all have default values so, in the simplest case, you could run a script like the following (the output is, unfortunately, extremely wide):<\/p>\n<pre>set long 250000\r\n\r\nset linesize 254\r\nset pagesize 100\r\nset trimspool on\r\n\r\nset heading off\r\n\r\ncolumn text_line format a254\r\n\r\nselect \r\n\tdbms_sqltune.report_sql_monitor_list() text_line \r\nfrom\tdual\r\n;\r\n\r\nselect \r\n\tdbms_sqltune.report_sql_monitor() text_line \r\nfrom\tdual\r\n;<\/pre>\n<p>The output from this code will produce a text of all the SQL statements that have been monitored in the recent past and are still available in the library cache, followed by the execution plan and actual resource usage of just the single most recently executed statement. If you want to produce an HTML output that you can view through a web browser then add the parameter type = &gt; \u2018HTML\u2019 to the two calls; or, if you want a more advanced browser display that emulates the OEM output, add the parameter type =&gt; \u2018ACTIVE\u2019.<\/p>\n<p>Although there are far more parameters available, it\u2019s likely that the most commonly useful one would be the one that allows you to identify a specific SQL statement by referencing its SQL_ID: sql_id =&gt; \u2018{some sql_id}\u2019<\/p>\n<p>Here\u2019s an example of the output from an 11.2.0.4 instance where I\u2019ve selected a single sql_id for a parallel &#8220;create table as select&#8221;. First the \u201clist\u201d section:<\/p>\n<pre>                                                                                SQL Monitoring List\r\n                                                                               =====================\r\n\r\n===================================================================================================================================================================================\r\n|    Status    | Duration |    SQL Id     | Exec Id  |        Start        |   User    | Module\/Action | Dop | DB Time | IOs  |                     SQL Text                      |\r\n===================================================================================================================================================================================\r\n| DONE         |     372s | g12jqmxu3vqhu | 16777216 | 03\/02\/2015 21:50:34 | TEST_USER | SQL*Plus\/-    |  2  |    713s | 8560 | create table t3 as select \/*+ use_merge(t2)       |\r\n|              |          |               |          |                     |           |               |     |         |      | leading(t1 t2) monitor parallel(2) *\/             |\r\n|              |          |               |          |                     |           |               |     |         |      | t1.object_name obj1, t2.object_name obj2,         |\r\n|              |          |               |          |                     |           |               |     |         |      | count(*) ct from t1, t2 where t2.owner = t1.owner |\r\n|              |          |               |          |                     |           |               |     |         |      | group by t1.object_na...                          |\r\n\r\n===================================================================================================================================================================================\r\n\r\nSQL Monitoring Report<\/pre>\n<p>You\u2019ll notice in the SQL text that I\u2019ve included the hint <em><strong>\/*+ monitor *\/<\/strong><\/em>. This wasn\u2019t necessary for my example as Oracle will automatically monitor any parallel statement and any statement that it estimates will take more than 6 seconds to complete. I created the <em><strong>t1<\/strong><\/em> and <em><strong>t2<\/strong><\/em> tables as <em>\u201cselect * from all_objects where rownum &lt;= 5000\u201d<\/em>, so the join on \u201cowner\u201d is going to do something a little nasty. And here\u2019s the detail of what happened:<\/p>\n<pre>SQL Monitoring Report\r\n\r\nSQL Text\r\n------------------------------\r\ncreate table t3 as select \/*+ use_merge(t2) leading(t1 t2) monitor parallel(2) *\/ t1.object_name obj1, t2.object_name obj2, count(*) ct from t1, t2 where t2.owner = t1.owner group by t1.object_name, t2.object_name\r\n\r\nGlobal Information\r\n------------------------------\r\n Status              :  DONE\r\n Instance ID         :  1\r\n Session             :  TEST_USER (20:3335)\r\n SQL ID              :  g12jqmxu3vqhu\r\n SQL Execution ID    :  16777216\r\n Execution Started   :  03\/02\/2015 21:50:34\r\n First Refresh Time  :  03\/02\/2015 21:50:34\r\n Last Refresh Time   :  03\/02\/2015 21:56:46\r\n Duration            :  372s\r\n Module\/Action       :  SQL*Plus\/-\r\n Service             :  SYS$USERS\r\n Program             :  sqlplus@linux11 (TNS V1-V3)\r\n\r\nGlobal Stats\r\n=================================================================================================\r\n| Elapsed |   Cpu   |    IO    | Concurrency |  Other   | Buffer | Read | Read  | Write | Write |\r\n| Time(s) | Time(s) | Waits(s) |  Waits(s)   | Waits(s) |  Gets  | Reqs | Bytes | Reqs  | Bytes |\r\n=================================================================================================\r\n|     713 |      21 |      407 |        1.63 |      284 |  80856 | 4052 | 933MB |  4508 |   1GB |\r\n=================================================================================================\r\n\r\nParallel Execution Details (DOP=2 , Servers Allocated=4)\r\n==================================================================================================================================================================================\r\n|      Name      | Type  | Server# | Elapsed |   Cpu   |    IO    | Concurrency |  Other   | Buffer | Read | Read  | Write | Write |                 Wait Events                 |\r\n|                |       |         | Time(s) | Time(s) | Waits(s) |  Waits(s)   | Waits(s) |  Gets  | Reqs | Bytes | Reqs  | Bytes |                 (sample #)                  |\r\n==================================================================================================================================================================================\r\n| PX Coordinator | QC    |         |    0.48 |    0.03 |     0.03 |        0.07 |     0.35 |    170 |    2 | 16384 |       |     . | log file sync (1)                           |\r\n| p000           | Set 1 |       1 |     350 |    8.43 |      196 |        1.02 |      144 |  40290 | 2011 | 463MB |  2241 | 747MB | buffer busy waits (1)                       |\r\n|                |       |         |         |         |          |             |          |        |      |       |       |       | log buffer space (19)                       |\r\n|                |       |         |         |         |          |             |          |        |      |       |       |       | log file switch (archiving needed) (117)    |\r\n|                |       |         |         |         |          |             |          |        |      |       |       |       | log file switch (checkpoint incomplete) (5) |\r\n|                |       |         |         |         |          |             |          |        |      |       |       |       | rdbms ipc reply (1)                         |\r\n|                |       |         |         |         |          |             |          |        |      |       |       |       | direct path read temp (157)                 |\r\n|                |       |         |         |         |          |             |          |        |      |       |       |       | direct path write (2)                       |\r\n|                |       |         |         |         |          |             |          |        |      |       |       |       | direct path write temp (24)                 |\r\n|                |       |         |         |         |          |             |          |        |      |       |       |       | flashback log file sync (1)                 |\r\n| p001           | Set 1 |       2 |     359 |    8.47 |      211 |        0.55 |      139 |  40300 | 2039 | 469MB |  2267 | 753MB | buffer busy waits (1)                       |\r\n|                |       |         |         |         |          |             |          |        |      |       |       |       | log buffer space (16)                       |\r\n|                |       |         |         |         |          |             |          |        |      |       |       |       | log file switch (archiving needed) (117)    |\r\n|                |       |         |         |         |          |             |          |        |      |       |       |       | log file switch (checkpoint incomplete) (4) |\r\n|                |       |         |         |         |          |             |          |        |      |       |       |       | log file switch completion (1)              |\r\n|                |       |         |         |         |          |             |          |        |      |       |       |       | control file sequential read (2)            |\r\n|                |       |         |         |         |          |             |          |        |      |       |       |       | db file sequential read (4)                 |\r\n|                |       |         |         |         |          |             |          |        |      |       |       |       | direct path read temp (175)                 |\r\n|                |       |         |         |         |          |             |          |        |      |       |       |       | direct path write temp (30)                 |\r\n| p002           | Set 2 |       1 |    2.34 |    1.99 |          |             |     0.35 |     51 |      |     . |       |     . |                                             |\r\n| p003           | Set 2 |       2 |    1.81 |    1.60 |          |             |     0.21 |     45 |      |     . |       |     . |                                             |\r\n==================================================================================================================================================================================\r\n\r\nSQL Plan Monitoring Details (Plan Hash Value=3638022418)\r\n====================================================================================================================================================================================================================\r\n| Id |           Operation            |   Name   |  Rows   | Cost  |   Time    | Start  | Execs |   Rows   | Read | Read  | Write | Write |  Mem  | Temp  | Activity |               Activity Detail               |\r\n|    |                                |          | (Estim) |       | Active(s) | Active |       | (Actual) | Reqs | Bytes | Reqs  | Bytes | (Max) | (Max) |   (%)    |                 (# samples)                 |\r\n====================================================================================================================================================================================================================\r\n|  0 | CREATE TABLE STATEMENT         |          |         |       |       313 |    +60 |     5 |        2 |      |       |       |       |       |       |     1.41 | log file sync (1)                           |\r\n|    |                                |          |         |       |           |        |       |          |      |       |       |       |       |       |          | buffer busy waits (2)                       |\r\n|    |                                |          |         |       |           |        |       |          |      |       |       |       |       |       |          | rdbms ipc reply (1)                         |\r\n|    |                                |          |         |       |           |        |       |          |      |       |       |       |       |       |          | control file sequential read (2)            |\r\n|    |                                |          |         |       |           |        |       |          |      |       |       |       |       |       |          | db file sequential read (4)                 |\r\n|  1 |   PX COORDINATOR               |          |         |       |         1 |   +372 |     5 |        2 |      |       |       |       |       |       |          |                                             |\r\n|  2 |    PX SEND QC (RANDOM)         | :TQ10002 |      6M | 36152 |        10 |   +363 |     2 |        2 |      |       |       |       |       |       |          |                                             |\r\n|  3 |     LOAD AS SELECT             |          |         |       |       329 |    +44 |     2 |        2 |      |       |   571 | 570MB |    8M |       |    40.70 | log buffer space (35)                       |\r\n|    |                                |          |         |       |           |        |       |          |      |       |       |       |       |       |          | log file switch (archiving needed) (234)    |\r\n|    |                                |          |         |       |           |        |       |          |      |       |       |       |       |       |          | log file switch (checkpoint incomplete) (9) |\r\n|    |                                |          |         |       |           |        |       |          |      |       |       |       |       |       |          | log file switch completion (1)              |\r\n|    |                                |          |         |       |           |        |       |          |      |       |       |       |       |       |          | Cpu (7)                                     |\r\n|    |                                |          |         |       |           |        |       |          |      |       |       |       |       |       |          | direct path write (2)                       |\r\n|    |                                |          |         |       |           |        |       |          |      |       |       |       |       |       |          | flashback log file sync (1)                 |\r\n|  4 |      HASH GROUP BY             |          |      6M | 36152 |       371 |     +2 |     2 |      13M | 3839 | 930MB |  3839 | 930MB |  101M |  721M |    57.04 | Cpu (19)                                    |\r\n|    |                                |          |         |       |           |        |       |          |      |       |       |       |       |       |          | direct path read temp (332)                 |\r\n|    |                                |          |         |       |           |        |       |          |      |       |       |       |       |       |          | direct path write temp (54)                 |\r\n|  5 |       PX RECEIVE               |          |      6M |    35 |        44 |     +1 |     2 |      13M |      |       |       |       |       |       |     0.14 | Cpu (1)                                     |\r\n|  6 |        PX SEND HASH            | :TQ10001 |      6M |    35 |        40 |     +2 |     2 |      13M |      |       |       |       |       |       |          |                                             |\r\n|  7 |         MERGE JOIN             |          |      6M |    35 |        40 |     +2 |     2 |      13M |      |       |       |       |       |       |          |                                             |\r\n|  8 |          SORT JOIN             |          |    5000 |    12 |        40 |     +2 |     2 |     5000 |      |       |       |       |  225K |       |          |                                             |\r\n|  9 |           PX BLOCK ITERATOR    |          |    5000 |    11 |         1 |     +2 |     2 |     5000 |      |       |       |       |       |       |          |                                             |\r\n| 10 |            TABLE ACCESS FULL   | T1       |    5000 |    11 |         1 |     +2 |    32 |     5000 |      |       |       |       |       |       |          |                                             |\r\n| 11 |          SORT JOIN             |          |    5000 |    12 |        41 |     +1 |  5000 |      13M |      |       |       |       |  422K |       |     0.70 | Cpu (5)                                     |\r\n| 12 |           PX RECEIVE           |          |    5000 |    11 |         1 |     +2 |     2 |    10000 |      |       |       |       |       |       |          |                                             |\r\n| 13 |            PX SEND BROADCAST   | :TQ10000 |    5000 |    11 |         1 |     +2 |     2 |    10000 |      |       |       |       |       |       |          |                                             |\r\n| 14 |             PX BLOCK ITERATOR  |          |    5000 |    11 |         1 |     +2 |     2 |     5000 |      |       |       |       |       |       |          |                                             |\r\n| 15 |              TABLE ACCESS FULL | T2       |    5000 |    11 |         1 |     +2 |    32 |     5000 |      |       |       |       |       |       |          |                                             |\r\n====================================================================================================================================================================================================================<\/pre>\n<p>I&#8217;ve picked a parallel example to give you some idea of how much information about the parallelism is available above and beyond the details supplied by <em><strong>dbms_xplan.display_cursor()<\/strong><\/em>, but I&#8217;m going talk about the details in a fairly generic fashion.<\/p>\n<p>I captured this text output after the CTAS has completed, but you can run the report while a statement is still executing \u2013 unlike the <em><strong>dbms_xplan.display_cursor()<\/strong><\/em> strategy you don&#8217;t have to wait for a statement to complete. Here&#8217;s the initial OEM display for the same query, partway through execution:<\/p>\n<div id=\"attachment_5472\" style=\"width: 1883px\" class=\"wp-caption alignnone\"><a href=\"https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2015\/03\/OEM_xplan.jpg\"><img loading=\"lazy\" decoding=\"async\" class=\"size-full wp-image-5472\" title=\"OEM Display\" alt=\"OEM_xplan\" src=\"https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2015\/03\/OEM_xplan.jpg\" width=\"1873\" height=\"654\" srcset=\"https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2015\/03\/OEM_xplan.jpg 1873w, https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2015\/03\/OEM_xplan-300x104.jpg 300w, https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2015\/03\/OEM_xplan-1024x357.jpg 1024w\" sizes=\"auto, (max-width: 1873px) 100vw, 1873px\" \/><\/a><\/p>\n<p class=\"wp-caption-text\">Click the image to enlarge<\/p>\n<\/div>\n<h2>Things to note (OEM)<\/h2>\n<p>In the <em><strong>Overview<\/strong> <\/em>section you can see at the top left that this query ran parallel 2; the <em>\u201cTime and Wait Statistics\u201d<\/em> show that the elapsed time (so far) was 4.4 minutes while the DB time was 8.3 minutes (which means, roughly, that at any moment one set of PX slaves was active and the other inactive); of the DB time nearly half was User I\/O (dark blue) and half was \u201cOther\u201d (light blue), with a small fraction spent on CPU. Fortunately we also have the <em>&#8220;Wait Activity %&#8221;<\/em> bar showing us a (rare) big pink splash that explains the \u201cOther\u201d: my archivelog destination was full so the CTAS stopped until I freed some space. On a live screen you can hover the mouse over these bars to see what each colour represents. The <em>\u201cIO Statistics\u201d<\/em> gives you a summary of logical and physical I\/O (the darker brown is writes, the lighter\/yellow is reads).<\/p>\n<p>At the top of the Details section you can see there are 5 buttons which give you different pieces of data &#8211; including the information about PX slaves that is printed in the text output. This is followed by the execution plan with all the detail of work down and time spent for each line of the plan. The time information (<em><strong>CPU Activity%<\/strong><\/em> and <strong><em>Wait Activity%<\/em><\/strong>) comes from <em><strong>v$active_session_history<\/strong><\/em> (ASH). At the left of the plan you can see little clusters of &#8220;people&#8221; which mark the operations that have operated in parallel (I think there really ought to be a marker on the PX SEND QC (RANDOM) operation as well); and on the 4th and 5th lines of the plan you can see a pair of green arrows identifying the lines of the plan that are currently active. I&#8217;m going to read through the plan (in order of rowsource generation) describing the detail.<\/p>\n<p>In the last few lines of the plan, PX slave set 1 does a parallel tablescan of <em><strong>t2<\/strong><\/em> and <em><strong>broadcasts<\/strong><\/em> the rows to PX slave set 2 (every slave gets every row). There are 5,000 rows in <em><strong>t2<\/strong><\/em>, which is why the <em>&#8220;Actual Rows&#8221;<\/em> is 5,000 for the scan and (since we&#8217;re parallel 2) 10,000 for the send and receive. Generally we see 2 executions of most operations because there are two slaves in a slave set &#8211; however we can infer that the tablescan was split into 16 rowid ranges per slave when we see the 32 executions of the TABLE ACCESS FULL operations. (Parallel execution means that the cardinality check that <em>&#8220;Estimated rows * Executions = Actual rows&#8221;<\/em> doesn&#8217;t apply &#8211; you have to think very carefully about what&#8217;s happening.) Looking at the <em>&#8220;Timeline&#8221;<\/em> column we can see that both tablescans started almost immediately the statement started, and ended very quickly (The time-granularity is only down to 1 second, so there&#8217;s plenty of room for little errors to appear).<\/p>\n<p>After the first scan and broadcast, though, we see the parallel sort at line 12 apparently lasting a long time &#8211; claiming 28% of the CPU time of the whole query and generating 13M rows because it executed 5,000 times! This is a misleading feature of the way execution plans (including serial ones) display the <em><strong>merge join<\/strong><\/em>. Ideally I&#8217;d like to see this &#8220;SORT JOIN&#8221; line split into two operations; it would be nice to see a &#8220;SORT JOIN&#8221; line that sorts 5,000 rows very quickly, and then a parent called something like &#8220;MERGE PROBE&#8221; which is the operation that would be executed once for every row in the first rowsource. As it is the &#8220;SORT JOIN&#8221; line sorts once (for each slave in PX Slave set 2) copying the data into memory in sorted order after which each slave will scan chunks of table <em><strong>t1<\/strong><\/em> and, for each row, probe their private memory copies of the sorted <em><strong>t2<\/strong><\/em> data. (Remember there are 5,000 rows in <em><strong>t1<\/strong><\/em>, which is why we get 5,000 executions of the probe.)<\/p>\n<p>The 13M rows generated by the merge join at line 8 are then distributed by hash back to the slaves in PX Slave set 1. The PX RECEIVE at operation 6 claims to use 5.56% of the CPU of the whole query, but that&#8217;s probably subject to some bad luck in sampling &#8211; in reality the CPU time is probably spread between the send and the receive, and some of the CPU time for the HASH GROUP BY should probably have been allocated to the PX RECEIVE, but ASH samples once per second and for a very small number of samples you have to assume that there are some sampling anomalies around the edges.<\/p>\n<p>As PX Slave Set 1 receives the join data each slave starts doing a HASH GROUP BY; from the colour bars you can see that this takes a lot of reads and writes (to temp) and a lot of CPU. We can also see from the <em>&#8220;Timeline&#8221;<\/em> that the HASH GROUP BY started very shortly after the statement started to execute: the tablescans were very quick and the hash group by can start as soon as the first few rows are joined; we can see then that the hash group by goes on for a very long time after the merge join has finished sending its data. There are two reasons for this: first is simply that the volume of data for the group by is large and spills to disc and has to be re-read before the group by can complete \u2013 but the merge join (along with the two sort joins that feed it) ends when it has supplied all its data to the hash group by. The <em>&#8220;Timeline&#8221;<\/em>\u00a0tells us that the LOAD AS SELECT started very soon after the MERGE JOIN ended; I am a little puzzled by this but I think it\u2019s an indication that the hash group by spilled to disc in a large number of small partitions, and was therefore able to produce the very first set of aggregate results immediately after the last row of the incoming data set appeared.<\/p>\n<p>The second reason that the group by goes on after the merge join (and would do, even if the group by completed in memory) is that it has to feed its result set to the LOAD AS SELECT operation and can&#8217;t complete until the data is written to disc, and the writing has taken a long time. The reason for the exaggerated completion time shows up in the pink <em>Wait I\/O<\/em>\u00a0bar &#8211; there&#8217;s a huge amount of time lost to <em>&#8220;log file switch (archiving needed)&#8221;<\/em>; I was running in archivelog mode with FORCE LOGGING enabled and my <em><strong>fast_recovery_area<\/strong><\/em> was full, so everything stopped until I noticed that something was wrong and cleared some space.<\/p>\n<p>I said at the outset that I snapped this picture from OEM before the statement had completed. That\u2019s why the 2nd and 3rd lines of the plan have an empty <em>Timeline<\/em> \u2013 they haven\u2019t yet done anything. I\u2019ll have to admit to being puzzled by the fact that the 1st line (create table) seems to start a little while after the 4th (load as select) \u2013 but perhaps this is an indication of the moment when the first space allocations in the tablespace were made as the hash group by produced its first batch of data.<\/p>\n<p>You\u2019ll notice two things about the first few lines of the plan \u2013 their <em>Actual Rows<\/em> is zero, they haven\u2019t produced anything yet; ultimately (because we are running parallel 2) we will see that they all produce 2 rows. The other little oddity is that the first two lines of the plan show 5 executions rather than 2 \u2013 but that\u2019s an effect of the <em>\u201cshared parallel cursor\u201d<\/em> \u2013 there are actually 5 sessions sharing the same child cursor as this query runs.<\/p>\n<h2>Things to note (Text)<\/h2>\n<p>There isn\u2019t really a lot extra to say about the text output. It\u2019s nice that you can generate it if you don\u2019t have access to OEM; and it\u2019s nice that it can make the list of wait events much clearer in complicated cases (the little patches of colour that show up in OEM for rare cases can be too small to notice or click on).<\/p>\n<p>In my example I ran the text report after the CTAS has completed, so the final figures are different \u2013 but for the completed lines the printed figures in the <em>\u201cStart Active\u201d<\/em> (how many seconds through the execution were we before this operation started) and <em>\u201cTime Active (s)\u201d<\/em> (for how long was this operation active) give you a little better precision in terms of sequencing.<\/p>\n<p>The summary of parallel activity is very nice \u2013 and in this case shows that one set of PX slaves did almost all the work; but that information is also available through OEM if you click on the \u201cParallel\u201d button.<\/p>\n<h2>Conclusion<\/h2>\n<p>This closing article in the series on reading Execution plans covered an option that is available only if you\u2019ve got the relevant licenses. Although hinting with <strong><em>\/*+ gather_plan_statistics *\/<\/em><\/strong> or setting the parameter <em><strong>statistics_level<\/strong><\/em> to <em><strong>all<\/strong><\/em> can give you a summary of the work done when a query completes, the <strong>SQL Monitor<\/strong> features adds two key benefits \u2013 it can show you the workload accumulating as the query runs so you can choose to terminate a statement if you can see that it\u2019s going to take a very long time to complete, and it gives you the detail of the underlying ASH data for each line of the plan so you know far more about how the time is being used. The extremely visual nature of the OEM display also makes it very easy to spot unexpected patterns of behaviour that you might not predict or expect from reading the bare text of what might seem to be a reasonable execution plan.<\/p>\n<p>&nbsp;<\/p>\n","protected":false},"excerpt":{"rendered":"<p>This is the last part of my series on Execution plans, and features an option which is only available if you have licensed the Diagnostic and Performance Packs. It\u2019s a feature that allows you to watch the flow of data through an execution plan as the query is running, typically through the graphic interface supplied by Enterprise Manager \u00a0(or Grid&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":[4783],"coauthors":[],"class_list":["post-73170","post","type-post","status-publish","format-standard","hentry","category-oracle-databases","tag-execution-plans"],"acf":[],"_links":{"self":[{"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts\/73170","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=73170"}],"version-history":[{"count":1,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts\/73170\/revisions"}],"predecessor-version":[{"id":91661,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts\/73170\/revisions\/91661"}],"wp:attachment":[{"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/media?parent=73170"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/categories?post=73170"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/tags?post=73170"},{"taxonomy":"author","embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/coauthors?post=73170"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}