V$SQL_MONITOR and V$SQL_PLAN_MONITOR

In my recent presentation at UKOUG 2009 in Birmingham I also mentioned the new feature of Oracle11gR1 which is a neat solution for monitoring long running SQL statements. It captures statistics about SQL execution every second.

For parallel execution every process involved gets separate entries in V$SQL_MONITOR and V$SQL_PLAN_MONITOR.

It is enabled by default for long running statements if parameter CONTROL_MANAGEMENT_PACK_ACCESS if it is set to “DIAGNOSTIC+TUNING” and STATISTICS_LEVEL=ALL|TYPICAL

It can be enabled at statement level as well with /*+ MONITOR */ hint or disabled with /*+ NO_MONITOR */ hint.

There are some defaults defined which can be altered by setting hidden parameters:
_sqlmon_max_plan - Maximum number of plans entries that can be monitored. Defaults to 20 per CPU
_sqlmon_max_planlines - Number of plan lines beyond which a plan cannot be monitored (default 300)

Just for demonstration purposes I used a simple performance killing statement which runs quite for a while and could be used to test this new feature.

SQL_ID b0zm3w4h1hbff, child number 0
-------------------------------------
select count(*) from obj$,obj$,obj$ --performance killer

Plan hash value: 3679021907

----------------------------------------------------
| Id | Operation | Name | E-Rows |
----------------------------------------------------
| 1 | SORT AGGREGATE | | 1 |
| 2 | MERGE JOIN CARTESIAN | | 341T|
| 3 | MERGE JOIN CARTESIAN | | 4886M|
| 4 | INDEX FAST FULL SCAN | I_OBJ1 | 69901 |
| 5 | BUFFER SORT | | 69901 |
| 6 | INDEX FAST FULL SCAN| I_OBJ1 | 69901 |
| 7 | BUFFER SORT | | 69901 |
| 8 | INDEX FAST FULL SCAN | I_OBJ1 | 69901 |
----------------------------------------------------

SQL> SELECT status, KEY, SID, sql_id, elapsed_time, cpu_time, fetches, buffer_gets,
2 disk_reads
3 FROM v$sql_monitor where sql_id='b0zm3w4h1hbff';

STATUS KEY SID SQL_ID ELAPSED_TIME CPU_TIME FETCHES BUFFER_GETS DISK_READS
--------- ----------- --- ------------- ------------ ---------- ------- ----------- ----------
EXECUTING 21474836481 170 b0zm3w4h1hbff 674281628 624578125 0 0 0

SQL> SELECT plan_line_id, plan_operation || ' ' || plan_options operation,
2 starts, output_rows
3 FROM v$sql_plan_monitor where key=21474836481
4 ORDER BY plan_line_id;

PLAN_LINE_ID OPERATION STARTS OUTPUT_ROWS
------------ --------------------- ---------- -----------
0 SELECT STATEMENT 1 0
1 SORT AGGREGATE 1 0
2 MERGE JOIN CARTESIAN 1 4283731363
3 MERGE JOIN CARTESIAN 1 156731
4 INDEX FAST FULL SCAN 1 3
5 BUFFER SORT 3 156731
6 INDEX FAST FULL SCAN 1 70088
7 BUFFER SORT 156731 4283731363
8 INDEX FAST FULL SCAN 1 70088

The above result I got after running this statement for about 10 minutes. There are of course more statistics available which I have omitted here as they were useless for my demo case which had all data already in buffer cache.

One can use DBMS_SQLTUNE.REPORT_SQL_MONITOR() function to produce a formatted report of monitoring results. Unfortunately the below report is too wide to be cleary seen. I got it for a statement run by DBMS_STATS package

SQL> set long 10000000
SQL> set longchunksize 10000000
SQL> set linesize 200
SQL> select dbms_sqltune.report_sql_monitor from dual;

SQL Monitoring Report

SQL Text
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
select /*+ no_parallel_index(t, "I_WRI$_OPTSTAT_H_OBJ#_ICOL#_ST") dbms_stats cursor_sharing_exact use_weak_name_resl dynamic_sampling(0) no_monitoring no_expand
index(t,"I_WRI$_OPTSTAT_H_OBJ#_ICOL#_ST") */ count(*) as nrw,count(distinct sys_op_lbid(461,'L',t.rowid)) as nlb,count(distinct
hextoraw(sys_op_descend("OBJ#")||sys_op_descend("INTCOL#")||sys_op_descend(SYS_EXTRACT_UTC("SAVTIME"))||sys_op_descend("COLNAME"))) as ndk,sys_op_countchg(substrb(t.rowid,1,15),1)
as clf from "SYS"."WRI$_OPTSTAT_HISTGRM_HISTORY" t where "OBJ#" is not null or "INTCOL#" is not null or SYS_EXTRACT_UTC("SAVTIME") is not null or "COLNAME" is not null
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

Global Information

Status : DONE (ALL ROWS)
Instance ID : 1
Session ID : 127
SQL ID : 1d7qn8b9wam8h
SQL Execution ID : 16777216
Plan Hash Value : 3428983716
Execution Started : 12/04/2009 01:09:20
First Refresh Time : 12/04/2009 01:09:28
Last Refresh Time : 12/04/2009 01:09:30

--------------------------------------------------------------------
| Elapsed | Cpu | IO | Other | Fetch | Buffer | Reads |
| Time(s) | Time(s) | Waits(s) | Waits(s) | Calls | Gets | |
--------------------------------------------------------------------
| 8.65 | 1.94 | 6.58 | 0.13 | 1 | 1327 | 694 |
--------------------------------------------------------------------


SQL Plan Monitoring Details
=========================================================================================================================================================================
| Id | Operation | Name | Rows | Cost | Time | Start | Starts | Rows | Memory | Activity | Activity Detail |
| | | | (Estim) | | Active(s) | Active | | (Actual) | (Max) | (percent) | (sample #) |
=========================================================================================================================================================================
| 0 | SELECT STATEMENT | | | 1026 | 1 | +10 | 1 | 1 | 274K | | |
| 1 | SORT GROUP BY | | 1 | | 6 | +5 | 1 | 1 | 274K | 37.50 | Cpu (3) |
| 2 | INDEX FULL SCAN | I_WRI$_OPTSTAT_H_OBJ#_ICOL#_ST | 179K | 1026 | 8 | +3 | 1 | 179K | | 62.50 | db file sequential read (5) |
=========================================================================================================================================================================