Tuning Pack 11g : Real-Time SQL Monitoring

“Real Time SQL Monitoring” is a 11g Tuning Pack new feature. You can easily access it when the Tuning Pack is set. If a query is a “long” query, if it uses more than 5 seconds of CPU of I/O Wait or if it’s a parallel query (from the documentation), the plan execution statistics are kept by the engine and you can follow the query execution in Real Time. Note that it differs from V$SESSION_LONGOPS which enables you to follow one step of a query or other operations. Anyway, It’s very impressive even if it doesn’t look to be fully functional (Is it me ?). It’s just a shame that I won’t be able to access it for all the databases although we’ve already asked for.

I don’t want to paraphrase the documentation but just build a test case to illustrate this feature. For more information about Real Time SQL Monitoring see :

• Oracle 11.1 – Performance Guide : Real Time SQL Monitoring
  
• Oracle 11.1 – PL/SQL Package and Type Reference DBMS_SQLTUNE
  
• Oracle 11.1 – Reference V$SQL_MONITOR et V$SQL_PLAN_MONITOR

As always I guess Enterprise Manager provides a fantastic GUI for this feature. This post is for you if you don’t always use it…

Step 1 : Configuration, sample Schema and SQL

Check that the tuning pack is set as below :

SQL> show parameter control_management_pack_access
NAME                           VALUE
------------------------------ -----------------
control_management_pack_access DIAGNOSTIC+TUNING

Create a sample table :

create table gark(a number,
                  b number);
begin
  for i in 1..100000 loop
   insert into gark values (mod(i,19), mod(i,17));
  end loop;
  commit;
end;
/

To show how to use “Real Time SQL Monitoring”, we need a query that last minutes. Thanks Oracle to provide HINTs to make plan sub-optimal. Here is the one, I’ll use to show :

select /*+ use_nl(a b) */ count(*)
  from gark a, gark b
 where a.a=b.b;

Before you run it, prepare the battle field to monitor the query. In a real case, you would like to catch the query from a kind of “Top SQL” or “Top Session”. Because we already know what to track, we will not the session sid and serial# before we start. To do that, lets use the SCOTT schema ; grant SELECT on V_$SESSION to SCOTT :

sqlplus / as sysdba
grant select on sys.v_$session
   to scott;

Before we run the query, let’s just note the session sid and serial# :

select sid, serial#, audsid
  from v$session
 where audsid=sys_context('USERENV','SESSIONID');
       SID    SERIAL#     AUDSID
---------- ---------- ----------
       130         99     200038

select /*+ use_nl(a b) */ count(*)
  from gark a, gark b
 where a.a=b.b;

Step 2 : Monitor the query execution

Once the query started and after a while, the time for the feature to trigger, V$SQL_MONITOR will help you to track the query execution. While V$SQL shows cumulative statistics, V$SQL_MONITOR differentiates all the executions and show one row per query if it’s tracked. Moreover, V$SQL_PLAN_MONITOR shows deeper details of the query execution : each step of the plan. Here is a script to that enable you to find the right query from the sid and serial# :

accept v_sid prompt "Enter Session ID : "
130
accept v_serial prompt "Enter Session Serial# : "
200038

col key format 999999999999
set colsep '|'

select key, sql_id, sql_exec_id,
    to_char(max(sql_exec_start) ,'DD/MM/YYYY HH24:Mi:SS')
         sql_exec_start,
    sql_child_address child_address
  from v$sql_monitor
 where sid=&v_sid
   and session_serial#=&v_serial
group by key, sql_id, sql_exec_id, sql_child_address
order by sql_exec_start;
         KEY|SQL_ID       |SQL_EXEC_ID|SQL_EXEC_START     |CHILD_AD
------------|-------------|-----------|-------------------|--------
304942678017|4z9f29d23f72c|   16777216|12/08/2007 03:58:21|305C173C
519691042820|4z9f29d23f72c|   16777217|12/08/2007 06:00:43|331B81F8
408021893126|4z9f29d23f72c|   16777218|12/08/2007 08:05:42|30615618

Once you’ve found the query you want to monitor (SQL_ID, SQL_EXEC_ID and SQL_EXEC_START are a unique key to define the query execution), you can follow the query progress in “Real Time” :

accept v_sql_id prompt "Enter the SQL_ID to look at : "
4z9f29d23f72c
accept v_sql_exec_id prompt "Enter the associated SQL_EXEC_ID to look at : "
16777218
accept v_sql_exec_start prompt "Enter the Execution Start Date (DD/MM/YYYY HH24:MI:SS) : "
12/08/2007 08:05:42

col id format 999
col operation format a25
col object format a6
set colsep '|'
set lines 100

select p.id,
    rpad(' ',p.depth*2, ' ')||p.operation operation,
    p.object_name object,
    p.cardinality card
    p.cost cost,
    substr(m.status,1,4) status,
    m.output_rows
 from v$sql_plan p, v$sql_plan_monitor m
where p.sql_id=m.sql_id
 and p.child_address=m.sql_child_address
 and p.plan_hash_value=m.sql_plan_hash_value
 and p.id=m.plan_line_id
 and m.sql_id='&&v_sql_id'
 and m.sql_exec_id=&&v_sql_exec_id
 and m.sql_exec_start=to_date('&&v_sql_exec_start',
                            'DD/MM/YYYY HH24:MI:SS')
order by p.id;
I|OPERATION                |OBJECT|      CARD|C|STAT|OUTPUT_ROWS
-|-------------------------|------|----------|-|----|-----------
0|SELECT STATEMENT         |      |          |X|EXEC|          0
1|  SORT                   |      |         1| |EXEC|          0
2|    NESTED LOOPS         |      | 543129616|X|EXEC|   19857217
3|      TABLE ACCESS       |GARK  |    100000|X|EXEC|       3772
4|      TABLE ACCESS       |GARK  |      5431|X|EXEC|   19857217

If you re-run the query you can see the OUTPUT_ROWS progress as the STATUS column go from “EXECUTING” to “DONE” and monitor the query as never before :

/
I|OPERATION                |OBJECT|      CARD|C|STAT|OUTPUT_ROWS
-|-------------------------|------|----------|-|----|-----------
0|SELECT STATEMENT         |      |          |X|EXEC|          0
1|  SORT                   |      |         1| |EXEC|          0
2|    NESTED LOOPS         |      | 543129616|X|EXEC|  167404623
3|      TABLE ACCESS       |GARK  |    100000|X|EXEC|      31806
4|      TABLE ACCESS       |GARK  |      5431|X|EXEC|  167404623
/
I|OPERATION                |OBJECT|      CARD|C|STAT|OUTPUT_ROWS
-|-------------------------|------|----------|-|----|-----------
0|SELECT STATEMENT         |      |          |X|DONE|          1
1|  SORT                   |      |         1| |DONE|          1
2|    NESTED LOOPS         |      | 543129616|X|DONE|  526317649
3|      TABLE ACCESS       |GARK  |    100000|X|DONE|     100000
4|      TABLE ACCESS       |GARK  |      5431|X|DONE|  526317649

Step 3 : to continue (and what I didn’t manage to do !)

You can use the hint /*+ MONITOR */ to make the execution statistics available from V$SQL_MONITOR and V$SQL_PLAN_MONITOR. /*+ NO_MONITOR */, on the opposite prevents the informations to be stored.

I don’t know why, there is no data in the WORKAREA_MEM, WORKAREA_MAX_MEM, WORKAREA_TEMPSEG and WORKAREA_MAX_TEMPSEG columns of V$SQL_PLAN_MONITOR. It is probably somehow related to the fact DBMS_SQLTUNE.REPORT_SQL_MONITOR doesn’t show anything either. From the documentation, the steps below would have been even more impressive that my home made query above :

variable v_report CLOB;

set long 10000000
set longchunksize 10000000
set linesize 200

BEGIN
  :v_report :=DBMS_SQLTUNE.REPORT_SQL_MONITOR(
                sql_id=>'&&v_sql_id',
                sql_exec_id=>&&v_sql_exec_id,
                sql_exec_start=>to_date('&&v_sql_exec_start',
                        'DD/MM/YYYY HH24:Mi:SS'),
                report_level=>'ALL');
END;
/
print :v_report

If you make it run with this query or another, I would be very interested ? I expect it has more to do with the DBA (me) limitations rather that the new release…

Step 4 : Before you quit

drop table gark purge;