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 sysdate-1/24 sysdate
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 1: There is also a DBA_HIST_ACTIVE_SESS_HISTORY-using version of this script dasqlmon.sql that takes SQL_ID and PLAN_HASH_VALUE as arguments (in addition to the from_time and to_time).
Update 2: 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).
