asqlmon.sql: SQL Monitoring-like execution plan line level drilldown into SQL response time

I don’t have much time for a thorough blog post, so I’ll just paste in an example output of my asqlmon.sql script, which uses ASH sql_plan_line columns for displaying where inside your execution plan response time has been spent. Why not just use Oracle’s own SQL Monitoring reports? Well, SQL monitoring is meant for “long running” queries, which are not executed very frequently. In other words, you can’t use SQL Monitoring for drilling down into your frequently executed OLTP-style SQL. I am copying my recent post to Oracle-L mailing list here too:

The main performance impact of the old GATHER_PLAN_STATISTICS / statistics_level = ALL instrumentation came from the fact that expensive timing (gettimeofday()) system calls were used for getting A-Times of row sources.

That’s why the _rowsource_statistics_sampfreq was introduced, to not have to get the timing every switch between row sources, but only at every 128th time (by default). This caused some interesting measurement (or rather extrapolation) errors where the parent row source seemingly used less time than all of its children combined. (By the way, depending on your platform and recency of it, lightweight “fast trap” system calls may be used for getting the current timestamp, which reduces the overhead somewhat – Solaris since long time ago and RHEL 5.4+ for example).

Anyway, the row source timing info in SQL Monitoring comes from ASH sql_plan_line samples, so this instrumentation is always enabled anyway – SQL Monitoring will just query ASH for these records. The other data in V$SQL_MONITOR views doesn’t cause huge overhead – it depends on your query, but a heavy logical IO nested loop (my lotslios.sql) consumed around 0.6% more CPU with MONITOR hint compared to running with NO_MONITOR hint. I tested it on a VM and ran it only a couple of times, so this might just be statistical error or due to some other background activity. Not significant overhead in other words.

Now this was about long running queries, but you should not go and enable SQL Monitoring for all your short (OLTP) queries with a hint now as the SQL Monitoring data has to be kept and updated in a shared pool memory structure – and if all of your 1000 sessions suddenly start updating their monitoring data for every execution of a SQL, you will end up waiting for Real-time plan statistics latch contention (and some CPU overhead because so frequent searching and purging of previous SQL execution’s monitoring data).

The asqlmon (ASH-based SQL Monitoring like report) assumes that the corresponding execution plan is still present in library cache, it will take SQL_ID and child_number as a parameter. It does not show only a single execution as the SQL Monitoring report does, but  rather a plan-line level breakdown across all executions of that SQL/child captured in ASH data (you can change the WHERE clause to change the scope of the measurement):

SQL> @ash/asqlmon 6c45rgjx1myt6 0 

   SECONDS Activity Visual       Line ID Parent ASQLMON_OPERATION                                                                                    SESSION EVENT                                                            OBJ_ALIAS_QBC_NAME                                                                                 ASQLMON_PREDICATES                                                                                   PROJECTION
---------- -------- ------------ ------- ------ ---------------------------------------------------------------------------------------------------- ------- ---------------------------------------------------------------- -------------------------------------------------------------------------------------------------- ---------------------------------------------------------------------------------------------------- --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
                  % |          |       0        SELECT STATEMENT
         5   10.4 % |#         |       1      0  SORT AGGREGATE                                                                                      ON CPU                                                                    [SEL$1]                                                                                                                                                                                                (#keys=0) COUNT(*)[22]
         3    6.3 % |#         |       2      1   COUNT STOPKEY                                                                                      ON CPU                                                                                                                                                                      [F:]ROWNUM<=1000000000
                  % |          |       3      2    MERGE JOIN CARTESIAN
                  % |          |       4      3     VIEW  [DBA_SOURCE]                                                                                                                                                        DBA_SOURCE@SEL$1 [SET$1]
                  % |          |       5      4      UNION-ALL                                                                                                                                                                 [SET$1]
                  % |          |       6      5       FILTER                                                                                                                                                                   [SEL$335DD26A]                                                                                    [F:](("O"."TYPE#"<>4 AND "O"."TYPE#"<>5 AND "O"."TYPE#"<>7 AND "O"."TYPE#"<>8 AND "O"."TYPE#"<>9 AND
                                                                                                                                                                                                                                                                                                                                 "O"."TYPE#"<>10 AND "O"."TYPE#"<>11 AND "O"."TYPE#"<>12 AND "O"."TYPE#"<>13 AND "O"."TYPE#"<>14 AND
                                                                                                                                                                                                                                                                                                                                 "O"."TYPE#"<>22 AND "O"."TYPE#"<>87 AND "O"."TYPE#"<>88) OR BITAND("U"."SPARE1",16)=0 OR
                                                                                                                                                                                                                                                                                                                                 (INTERNAL_FUNCTION("O"."TYPE#") AND ((SYS_CONTEXT('userenv','current_edition_name')='ORA$BASE' AND
                                                                                                                                                                                                                                                                                                                                 "U"."TYPE#"<>2) OR ("U"."TYPE#"=2 AND
                                                                                                                                                                                                                                                                                                                                 "U"."SPARE2"=TO_NUMBER(SYS_CONTEXT('userenv','current_edition_id'))) OR  IS NOT NULL)))

                  % |          |       7      6        HASH JOIN                                                                                                                                                                                                                                                                 [A:] "O"."OBJ#"="S"."OBJ#"                                                                           (#keys=1) "O"."OBJ#"[NUMBER,22], "U"."SPARE2"[NUMBER,22], "U"."TYPE#"[NUMBER,22], "U"."SPARE1"[NUMBER,22], "O"."TYPE#"[NUMBER,22]
                  % |          |       8      7         HASH JOIN                                                                                                                                                                                                                                                                [A:] "O"."SPARE3"="U"."USER#"                                                                        (#keys=1) "U"."SPARE2"[NUMBER,22], "U"."TYPE#"[NUMBER,22], "U"."SPARE1"[NUMBER,22], "O"."OBJ#"[NUMBER,22], "O"."TYPE#"[NUMBER,22]
                  % |          |       9      8          INDEX FULL SCAN [I_USER2]                                                                                                                                            U@SEL$2 [SEL$335DD26A]                                                                                                                                                                                  "U"."USER#"[NUMBER,22]
                  % |          |      10      8          HASH JOIN                                                                                                                                                                                                                                                               [A:] "O"."OWNER#"="U"."USER#"                                                                        (#keys=1) "U"."SPARE2"[NUMBER,22], "U"."TYPE#"[NUMBER,22], "U"."SPARE1"[NUMBER,22], "O"."OBJ#"[NUMBER,22], "O"."SPARE3"[NUMBER,22], "O"."TYPE#"[NUMBER,22]
                  % |          |      11     10           INDEX FULL SCAN [I_USER2]                                                                                                                                           U@SEL$3 [SEL$335DD26A]                                                                                                                                                                                  "U"."USER#"[NUMBER,22], "U"."TYPE#"[NUMBER,22], "U"."SPARE1"[NUMBER,22], "U"."SPARE2"[NUMBER,22]
         1    2.1 % |          |      12     10           INDEX FAST FULL SCAN [I_OBJ2]                                                              ON CPU                                                                   O@SEL$3 [SEL$335DD26A]                                                                             [F:](("O"."TYPE#"=13 AND "O"."SUBNAME" IS NULL) OR INTERNAL_FUNCTION("O"."TYPE#"))                   "O"."OBJ#"[NUMBER,22], "O"."OWNER#"[NUMBER,22], "O"."TYPE#"[NUMBER,22], "O"."SPARE3"[NUMBER,22]
                  % |          |      13      7         INDEX FAST FULL SCAN [I_SOURCE1]                                                                                                                                      S@SEL$2 [SEL$335DD26A]                                                                                                                                                                                  "S"."OBJ#"[NUMBER,22]
                  % |          |      14      6        NESTED LOOPS                                                                                                                                                            [SEL$5]
                  % |          |      15     14         INDEX SKIP SCAN [I_USER2]                                                                                                                                             U2@SEL$5 [SEL$5]                                                                                   [A:] "U2"."TYPE#"=2 AND "U2"."SPARE2"=TO_NUMBER(SYS_CONTEXT('userenv','current_edition_id'))         "U2"."USER#"[NUMBER,22]
                                                                                                                                                                                                                                                                                                                                 [F:]("U2"."TYPE#"=2 AND "U2"."SPARE2"=TO_NUMBER(SYS_CONTEXT('userenv','current_edition_id')))

                  % |          |      16     14         INDEX RANGE SCAN [I_OBJ4]                                                                                                                                             O2@SEL$5 [SEL$5]                                                                                   [A:] "O2"."DATAOBJ#"=:B1 AND "O2"."TYPE#"=88 AND "O2"."OWNER#"="U2"."USER#"
                  % |          |      17      5       NESTED LOOPS                                                                                                                                                             [SEL$68B588A0]
                  % |          |      18     17        NESTED LOOPS                                                                                                                                                                                                                                                                                                                                                                   "O"."SPARE3"[NUMBER,22]
                  % |          |      19     18         NESTED LOOPS                                                                                                                                                                                                                                                                                                                                                                  "O"."OWNER#"[NUMBER,22], "O"."TYPE#"[NUMBER,22], "O"."SPARE3"[NUMBER,22]
                  % |          |      20     19          FIXED TABLE FULL [X$JOXSCD]                                                                                                                                          S@SEL$6 [SEL$68B588A0]                                                                                                                                                                                  "S"."JOXFTOBN"[NUMBER,22]
                  % |          |      21     19          TABLE ACCESS BY INDEX ROWID [OBJ$]                                                                                                                                   O@SEL$7 [SEL$68B588A0]                                                                                                                                                                                  "O"."OWNER#"[NUMBER,22], "O"."TYPE#"[NUMBER,22], "O"."SPARE3"[NUMBER,22]
                  % |          |      22     21           INDEX RANGE SCAN [I_OBJ1]                                                                                                                                           O@SEL$7 [SEL$68B588A0]                                                                             [A:] "O"."OBJ#"="S"."JOXFTOBN" AND "O"."TYPE#"=28 [F:]"O"."TYPE#"=28                                 "O".ROWID[ROWID,10], "O"."OWNER#"[NUMBER,22], "O"."TYPE#"[NUMBER,22]
                  % |          |      23     18         INDEX RANGE SCAN [I_USER2]                                                                                                                                            U@SEL$7 [SEL$68B588A0]                                                                             [A:] "O"."OWNER#"="U"."USER#" [F:](("O"."TYPE#"<>4 AND "O"."TYPE#"<>5 AND "O"."TYPE#"<>7 AND
                                                                                                                                                                                                                                                                                                                                 "O"."TYPE#"<>8 AND "O"."TYPE#"<>9 AND "O"."TYPE#"<>10 AND "O"."TYPE#"<>11 AND "O"."TYPE#"<>12 AND
                                                                                                                                                                                                                                                                                                                                 "O"."TYPE#"<>13 AND "O"."TYPE#"<>14 AND "O"."TYPE#"<>22 AND "O"."TYPE#"<>87 AND "O"."TYPE#"<>88) OR
                                                                                                                                                                                                                                                                                                                                 BITAND("U"."SPARE1",16)=0)

                  % |          |      24     17        INDEX RANGE SCAN [I_USER2]                                                                                                                                             U@SEL$6 [SEL$68B588A0]                                                                             [A:] "O"."SPARE3"="U"."USER#"
        39   81.3 % |########  |      25      3     BUFFER SORT                                                                                      ON CPU                                                                                                                                                                                                                                                                           (#keys=0)
                  % |          |      26     25      VIEW  [DBA_OBJECTS]                                                                                                                                                      DBA_OBJECTS@SEL$1 [SET$2]
                  % |          |      27     26       UNION-ALL                                                                                                                                                                [SET$2]
                  % |          |      28     27        FILTER                                                                                                                                                                  [SEL$18BE6699]                                                                                    [F:](("O"."TYPE#"<>4 AND "O"."TYPE#"<>5 AND "O"."TYPE#"<>7 AND "O"."TYPE#"<>8 AND "O"."TYPE#"<>9 AND
                                                                                                                                                                                                                                                                                                                                 "O"."TYPE#"<>11 AND "O"."TYPE#"<>12 AND "O"."TYPE#"<>13 AND "O"."TYPE#"<>14 AND "O"."TYPE#"<>22 AND
                                                                                                                                                                                                                                                                                                                                 "O"."TYPE#"<>87 AND "O"."TYPE#"<>88) OR BITAND("U"."SPARE1",16)=0 OR (INTERNAL_FUNCTION("O"."TYPE#")
                                                                                                                                                                                                                                                                                                                                 AND ((SYS_CONTEXT('userenv','current_edition_name')='ORA$BASE' AND "U"."TYPE#"<>2) OR ("U"."TYPE#"=2
                                                                                                                                                                                                                                                                                                                                 AND "U"."SPARE2"=TO_NUMBER(SYS_CONTEXT('userenv','current_edition_id'))) OR  IS NOT NULL)))

                  % |          |      29     28         HASH JOIN                                                                                                                                                                                                                                                                [A:] "O"."SPARE3"="U"."USER#"                                                                        (#keys=1) "U"."SPARE2"[NUMBER,22], "U"."TYPE#"[NUMBER,22], "U"."SPARE1"[NUMBER,22], "O"."OBJ#"[NUMBER,22], "O"."TYPE#"[NUMBER,22]
                  % |          |      30     29          INDEX FULL SCAN [I_USER2]                                                                                                                                            U@SEL$10 [SEL$18BE6699]                                                                                                                                                                                 "U"."USER#"[NUMBER,22]
                  % |          |      31     29          HASH JOIN                                                                                                                                                                                                                                                               [A:] "O"."OWNER#"="U"."USER#"                                                                        (#keys=1) "U"."SPARE2"[NUMBER,22], "U"."TYPE#"[NUMBER,22], "U"."SPARE1"[NUMBER,22], "O"."OBJ#"[NUMBER,22], "O"."SPARE3"[NUMBER,22], "O"."TYPE#"[NUMBER,22]
                  % |          |      32     31           INDEX FULL SCAN [I_USER2]                                                                                                                                           U@SEL$12 [SEL$18BE6699]                                                                                                                                                                                 "U"."USER#"[NUMBER,22], "U"."TYPE#"[NUMBER,22], "U"."SPARE1"[NUMBER,22], "U"."SPARE2"[NUMBER,22]
                  % |          |      33     31           TABLE ACCESS FULL [OBJ$]                                                                                                                                            O@SEL$12 [SEL$18BE6699]                                                                            [F:]("O"."TYPE#"<>10 AND BITAND("O"."FLAGS",128)=0 AND "O"."NAME"<>'_NEXT_OBJECT' AND                "O"."OBJ#"[NUMBER,22], "O"."OWNER#"[NUMBER,22], "O"."TYPE#"[NUMBER,22], "O"."SPARE3"[NUMBER,22]
                                                                                                                                                                                                                                                                                                                                 "O"."NAME"<>'_default_auditing_options_' AND "O"."LINKNAME" IS NULL)

                  % |          |      34     28         NESTED LOOPS                                                                                                                                                           [SEL$14]
                  % |          |      35     34          INDEX SKIP SCAN [I_USER2]                                                                                                                                            U2@SEL$14 [SEL$14]                                                                                 [A:] "U2"."TYPE#"=2 AND "U2"."SPARE2"=TO_NUMBER(SYS_CONTEXT('userenv','current_edition_id'))         "U2"."USER#"[NUMBER,22]
                                                                                                                                                                                                                                                                                                                                 [F:]("U2"."TYPE#"=2 AND "U2"."SPARE2"=TO_NUMBER(SYS_CONTEXT('userenv','current_edition_id')))

                  % |          |      36     34          INDEX RANGE SCAN [I_OBJ4]                                                                                                                                            O2@SEL$14 [SEL$14]                                                                                 [A:] "O2"."DATAOBJ#"=:B1 AND "O2"."TYPE#"=88 AND "O2"."OWNER#"="U2"."USER#"
                  % |          |      37     27        NESTED LOOPS                                                                                                                                                            [SEL$15]
                  % |          |      38     37         INDEX FULL SCAN [I_LINK1]                                                                                                                                             L@SEL$15 [SEL$15]                                                                                                                                                                                       "L"."OWNER#"[NUMBER,22]
                  % |          |      39     37         INDEX RANGE SCAN [I_USER2]                                                                                                                                            U@SEL$15 [SEL$15]                                                                                  [A:] "L"."OWNER#"="U"."USER#"

40 rows selected.

The output is deliberately very wide – as I like to have relevant info to a plan line on the same text line visually. I navigate around such plans by visually identifying where most of the time was spent (Activity% and Visual columns), then double or triple-click that line in my terminal window to highlight the whole line (it becomes like a marker) and then scroll left-right to see more info about it, such as the filter conditions and projection etc.

Note that this script does not give you all the info that a SQL Monitoring report (or the old-fashioned SQL Plan Profiling would give), like A-rows and Starts, because ASH just doesn’t provide data at this scope. But again, this approach works with frequently executed OLTP-style queries and does not require you to enable any session settings or add hints for getting quick overview of on which execution plan line does your SQL spend the most of its time.

Update: I also have a RAC-aware / GV$-using gasqlmon.sql script, but I haven’t kept it up to date for a while, so it might return incorrect output at the moment (there are some notable challenges as the child# of interest may not be the same on all instances, so for simplicity I look into a single instance at a time – non-parallel SQL tuning rarely requires a whole cluster overview in one script).

Note that this year’s only Advanced Oracle Troubleshooting class takes place in the end of April/May 2014, so sign up now if you plan to attend this year!

This entry was posted in Oracle. Bookmark the permalink.

22 Responses to asqlmon.sql: SQL Monitoring-like execution plan line level drilldown into SQL response time

  1. Dear!

    May you guide me how I could not execute asqlmon as

    “sys@cloud> @asqlmon ar0g8gkhhb359 0
    , ash.session_state
    *
    ERROR at line 31:
    ORA-00904: “ASH”.”SQL_PLAN_OPTIONS”: invalid identifier

    Elapsed: 00:00:00.01″

    Thank you very much!

  2. Laimis N says:

    That one is good. The rationale “In other words, you can’t use SQL Monitoring for drilling down into your frequently executed OLTP-style SQL” is still vary valid given todays mature OLTP systems and the focus on DW. Tuning at 1 second precision is still a challange.

  3. Hi Tanel,

    I had to comment one line in order to run the query of asqlmon.sql without error:

    , LPAD(TO_CHAR(TO_NUMBER(ROUND(RATIO_TO_REPORT(sq.samples) OVER (PARTITION BY sq.sql_id, sq.sql_plan_hash_value) * 100, 1), 999.9))||’ %’,8) pct_child
    *
    ERROR at line 39:
    ORA-01722: invalid number

    Any idea? I can’t spot the problem.

    Thanks.

    • Tanel Poder says:

      Did you save the file with “Save as…” or just copy&paste to an editor? Try Save as if you haven’t done so yet, as sometimes copy&paste to an editor messes up things.

    • Tanel Poder says:

      Ok looks like there was a bug. I removed the TO_NUMBER and brackets (the TO_CHAR’s 999.9 format parameter was applied in a wrong function). Please re-download the script and try again.

      • Thanks Tanel.

        I’ve removed the to_number my self, because I can’t see the change in http://blog.tanelpoder.com/files/scripts/ash/asqlmon.sql.

        One more question. Why do you claim Tuning pack is needed in the header of asqlmon.sql?

        • Tanel Poder says:

          You probably saw the script cached in your browser (or proxy) cache. If you hit refresh, you should see the new ver.

          I mentioned Tuning Pack in the script header as at some point I used V$SQL_MONITOR views there too, which are licensed under the Tuning pack IIRC. But yep just for ASH view only Diag pack was enough last time I checked. (Btw, I haven’t seen any customers with only Diag pack without Tuning one so far).

  4. max says:

    Tanel,

    As usual awesome work. This question has nothing to do with your tool but wanted to find out what terminal window do you use ??

    i have been searching for a terminal window were i could just double/tripe click and highlight the entire line…this works in putty(high light part) but you obviously do not have the option of making your width long so you cannot scroll left to right….

    when i run this using windows cmd prompt…i can make the width long enough to scroll left to right but the high light part do not work….you have to manually click and hight light the entire line to read that(there is no double/triple click option to highlight the entire line)…

    i have seen some of your demo session, where you just double/triple click to high light the line….so wanted to find out what do you use?…. if i am not wrong you are on your Mac Book…..anything windows related ( i have tried cygwin but there is no option in cygwin to scroll left to right)…

  5. Max says:

    thank you…that is what i am looking for…i have been using it for 30 mins and i am already in love with it…Thanks Tanel.

  6. Max says:

    updates for Terminator or updates to your awesome tools (snapper and stuff) ??

    • Tanel Poder says:

      Um… it looks like I’ve replied to a “wrong” comment :) All I saw this was the asqlmon post and replied to that … not realizing it was about the Terminator :-)

      I don’t plan any updates for Terminator – I’m pretty happy with it as well :)

  7. Max says:

    if its the terminator, can you just give me a ball park figure as to when you will release those update(if you plan to release it to public)…reason why i asked it…it take a little while for my company to push out new software to our work laptop…as i was going to request terminator for my work latop…if u have something it works i would love to get that….

    • Tanel Poder says:

      nope, not terminator… I got you wrong :-)

      • Tanel Poder says:

        but have you read about it’s Terminfo file topics? ideally you’d need to copy its terminfo file to all servers for best results (otherwise tools like vi may have some trouble drawing the screen and navigating etc). that’s the price for limitless horizontal scrolling while allowing terminal visible window info remain window-length…

        • Yousuf says:

          Hi Tanel,

          Just wanted one clarification.

          I have one table which is having 1.2 millions of rows & did the gather stats. after gather stats dba_tables shows same count as live table.

          The Question is Oracle Optimizer will look Live table data or dba_tables information to generate execution plan?

          Thanks

          Yousuf,

          • Tanel Poder says:

            It’s complicated in modern versions. Search up articles about “dynamic sampling” and “cardinality feedback” for example.

          • Yousuf says:

            Hi

            The dynamic sampling” and “cardinality feedback” will come in picture if you do not have proper stats gather on table..

            My Live table is gather stats on time & no issue. the row count of dba_Tables and Live table is same.. Hence my gather stats is fine.

            But the question is Oracle Optimizer will look Live table data or dba_tables information to generate execution plan?

            Please correct me if am wrong thinking..

            Thanks

            Yousuf,

          • Tanel Poder says:

            As I said, things have changed a lot since 9i when dyn sampling was introduced. In the old days, yes, when you had optimizer stats gathered, then optimizer used the stats from data dictionary (and dynamic sampling did not kick in). Things have changed, check this article for example:

            https://blogs.oracle.com/optimizer/entry/dynamic_sampling_and_its_impact_on_the_optimizer

            From Oracle Database 11g Release 2 onwards the optimizer will automatically decide if dynamic sampling will be useful and what dynamic sampling level will be used for SQL statements executed in parallel. This decision is based on size of the tables in the statement and the complexity of the predicates.

            Similarly, the cardinality feedback can kick in and adjust your rowcounts even when you have statistics gathered on tables (doesn’t really matter if you have stats or not on tables – the card feedback may kick in on later executions nevertheless)

  8. Pingback: SQL Developer Child Reports and Drill Down | Vishal desai's Oracle Blog

Leave a Reply

Your email address will not be published. Required fields are marked *

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>