11GR1出现了一个比较有趣的新特性Real Time SQL Monitoring，“慢查”SQL的跟踪，可能我说ORACLE里有慢查SQL的跟踪、记录功能，很多DBA会比较陌生，这个功能在MYSQL、POSTGRES、MONGODB里都早已经实现，但是ORACLE里迟迟没有出现慢查的功能，当然有一些变通的手段可以获取当前系统的慢查SQL，比如v$sql，awr等等。ORACLE 11GR1才姗姗来迟的推出这么一个功能。这个功能对运行时间比较长的SQL进行监控和记录。为了启用这个特性，需要确保一下参数设置正确：

STATISTICS_LEVEL需要设置为typical（默认）或着all
CONTROL_MANAGEMENT_PACK_ACCESS需要设置为DIAGNOSTIC+TUNING（默认）

就像上面所提到的，并不是所有的SQL都会被监控到，它默认只对以下两种情况的SQL进行监控和记录：
SQL运行时间超过5秒。通过隐含参数_sqlmon_threshold（单位为s）去控制，默认是5秒。此参数可以在session 和 system级别进行改变。
SQL采用了并行执行。
除了这两种情况SQL会被Real Time SQL Monitoring监控到外，你还可以通过添加hint /*+ MONITOR */的方式来对想要跟踪的SQL进行监控。
例如：
select /*+ MONITOR */* from a;

与此特性相关的2个动态性能视图也同时被引入， V$SQL_MONITOR and V$SQL_PLAN_MONITOR。两张表中的数据每秒被更新一次（以后的版本可能会改变这一情况），表中非常详细的记录了此SQL执行的相关信息、执行计划每个步骤所消耗的资源的信息。可以直接查看两个视图中的相关信息，也可以通过DBMS_SQLTUNE 包的REPORT_SQL_MONITOR函数来以更加可视化的方式进行展示和阅读。
我们来通过几个例子看看Real Time SQL Monitoring的一些功能。
select /*+ parallel(a 2) */ count(*) from test a;
COUNT(*)
----------
200

Elapsed: 00:00:00.27

sys@DLSP>@findsql
Enter value for sql_text: %test a%
Enter value for sql_id:

SQL_ID CHILD PLAN_HASH EXECS AVG_ETIME AVG_LIO SQL_TEXT
-------------------------- ------ ---------- ---------- ------------- ------------ ------------------------------------------------------------
ac935z0tnr3zp 0 2661943167 1 .08 390 select /*+ parallel(a 2) */ count(*) from test a

select username,sql_id,sid,sql_text,cpu_time,buffer_gets,disk_reads from v$sql_monitor where sql_id='ac935z0tnr3zp';
USERNAME SQL_ID SID SQL_TEXT CPU_TIME BUFFER_GETS DISK_READS
--------------- -------------------------- ---- ------------------------------------------------ ---------- ----------- ----------
TEST ac935z0tnr3zp 764 select /*+ parallel(a 2) */ count(*) from test a 4998 5 0
ac935z0tnr3zp 952 3000 154 0
ac935z0tnr3zp 764 2999 176 0

我们看到虽然SQL的执行时间没有5秒，但是由于SQL采用了并行，因此执行信息也会捕获到了。
再看看超过5秒的情况。
select count(*) from dba_objects a ,dba_objects b where rownum<20000000;

COUNT(*)
----------
19999999

Elapsed: 00:00:14.27
select username,sql_id,sid,sql_text,cpu_time,buffer_gets,disk_reads from v$sql_monitor where sql_id='03pnx6pjjsp5a';

USERNAME SQL_ID SID SQL_TEXT CPU_TIME BUFFER_GETS DISK_READS
--------------- -------------------------- ------ ------------------------------------------------ ---------- ----------- ----------
TEST 03pnx6pjjsp5a 2475 select count(*) from dba_objects a ,dba_objects 15539637 257848 0
b where rownum<20000000
不出所料，执行过程信息也被成功捕获到了。

我们还可以通过SQL调优包DBMS_SQLTUNE的REPORT_SQL_MONITOR函数来获取更加详细的信息：

test@DLSP>select DBMS_SQLTUNE.REPORT_SQL_MONITOR(
2 session_id=>nvl('&&sid',sys_context('userenv','sid')),
3 session_serial=>decode('2475',null,null,
4 sys_context('userenv','sid'),(select serial# from v$session where audsid = sys_context('userenv','sessionid')),
5 null),
6 sql_id=>'03pnx6pjjsp5a',
7 sql_exec_id=>'16777217',
8 report_level=>'ALL')
9 as report
10 from dual;

REPORT
------------------------------------------------------------------------------------------------------------------------------------------------------
SQL Monitoring Report

SQL Text
------------------------------
select count(*) from dba_objects a ,dba_objects b where rownum<20000000

Global Information
------------------------------
Status : DONE (ALL ROWS)
Instance ID : 1
Session : TEST (2475:4035)
SQL ID : 03pnx6pjjsp5a
SQL Execution ID : 16777217
Execution Started : 07/11/2014 14:37:17
First Refresh Time : 07/11/2014 14:37:23
Last Refresh Time : 07/11/2014 14:37:31
Duration : 14s
Module/Action : SQL*Plus/-
Service : SYS$USERS
Program : sqlplus@wxlab30 (TNS V1-V3)
Fetch Calls : 1

Global Stats
=================================================
| Elapsed | Cpu | Other | Fetch | Buffer |
| Time(s) | Time(s) | Waits(s) | Calls | Gets |
=================================================
| 14 | 14 | 0.00 | 1 | 421K |
=================================================

SQL Plan Monitoring Details (Plan Hash Value=3737909826)
===================================================================================================================================================
| Id | Operation | Name | Rows | Cost | Time | Start | Execs | Rows | Mem | Activity | Activity Detail |
| | | | (Estim) | | Active(s) | Active | | (Actual) | (Max) | (%) | (# samples) |
===================================================================================================================================================
| 0 | SELECT STATEMENT | | | | 9 | +6 | 1 | 1 | | | |
| 1 | SORT AGGREGATE | | 1 | | 9 | +6 | 1 | 1 | | | |
| 2 | COUNT STOPKEY | | | | 9 | +6 | 1 | 20M | | | |
| 3 | NESTED LOOPS | | 26G | 443K | 9 | +6 | 1 | 20M | | | |
| 4 | VIEW | DBA_OBJECTS | 1304 | 48 | 9 | +6 | 1 | 1303 | | | |
| 5 | UNION-ALL | | | | 9 | +6 | 1 | 1303 | | | |
| 6 | FILTER | | | | 9 | +6 | 1 | 1303 | | | |
| 7 | HASH JOIN | | 1303 | 47 | 9 | +6 | 1 | 1303 | 2M | | |
| 8 | INDEX FULL SCAN | I_USER2 | 42 | 1 | 1 | +6 | 1 | 42 | | | |
| 9 | HASH JOIN | | 1303 | 46 | 9 | +6 | 1 | 1303 | 1M | | |
| 10 | INDEX FULL SCAN | I_USER2 | 42 | 1 | 1 | +6 | 1 | 42 | | | |
| 11 | TABLE ACCESS FULL | OBJ$ | 1303 | 44 | 9 | +6 | 1 | 1303 | | | |
| 12 | NESTED LOOPS | | 1 | 2 | | | | | | | |
| 13 | INDEX FULL SCAN | I_USER2 | 1 | 1 | | | | | | | |
| 14 | INDEX RANGE SCAN | I_OBJ4 | 1 | 1 | | | | | | | |
| 15 | NESTED LOOPS | | 1 | 1 | | | | | | | |
| 16 | INDEX FULL SCAN | I_LINK1 | 1 | | | | | | | | |
| 17 | INDEX RANGE SCAN | I_USER2 | 1 | 1 | | | | | | | |
| 18 | VIEW | DBA_OBJECTS | 20M | 340 | 9 | +6 | 1303 | 20M | | | |
| 19 | UNION-ALL | | | | 9 | +6 | 1303 | 20M | | | |
| 20 | FILTER | | | | 9 | +6 | 1303 | 20M | | 14.29 | Cpu (2) |
| 21 | HASH JOIN | | 20M | 339 | 13 | +2 | 1303 | 20M | 1M | 42.86 | Cpu (6) |
| 22 | NESTED LOOPS | | 1764 | 12 | 9 | +6 | 1303 | 2M | | | |
| 23 | INDEX FULL SCAN | I_USER2 | 42 | 1 | 9 | +6 | 1303 | 54726 | | | |
| 24 | INDEX FAST FULL SCAN | I_USER2 | 42 | | 12 | +3 | 54726 | 2M | | 7.14 | Cpu (1) |
| 25 | TABLE ACCESS FULL | OBJ$ | 20M | 170 | 14 | +1 | 1303 | 20M | | 35.71 | Cpu (5) |
| 26 | NESTED LOOPS | | 1 | 2 | | | | | | | |
| 27 | INDEX FULL SCAN | I_USER2 | 1 | 1 | | | | | | | |
| 28 | INDEX RANGE SCAN | I_OBJ4 | 1 | 1 | | | | | | | |
| 29 | NESTED LOOPS | | 1 | 1 | | | 1302 | | | | |
| 30 | INDEX FULL SCAN | I_LINK1 | 1 | | | | 1302 | | | | |
| 31 | INDEX RANGE SCAN | I_USER2 | 1 | 1 | | | | | | | |
===================================================================================================================================================

通过v$sql_monitor你还可以非常容易获取SQL语句所使用的绑定变量值。
test@DLSP>var a number
test@DLSP>select count(*) from dba_objects a ,dba_objects b where rownum<^C

test@DLSP>exec :a :=20000000

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
test@DLSP>select count(*) from dba_objects a ,dba_objects b where rownum< :a;

COUNT(*)
----------
19999999

Elapsed: 00:00:15.69
test@DLSP>@findsql
Enter value for sql_text: %:a%
Enter value for sql_id:

SQL_ID CHILD PLAN_HASH EXECS AVG_ETIME AVG_LIO SQL_TEXT
-------------------------- ------ ---------- ---------- ------------- ------------ ------------------------------------------------------------
dbcb4ghxxdxa9 0 2117244413 1 15.69 257,856 select count(*) from dba_objects a ,dba_objects b where rown
um< :a

test@DLSP>select xmltype(binds_xml) a from v$sql_monitor where sql_id='dbcb4ghxxdxa9';

A
--------------------------------------------------------------------------------------

20000000

Real Time SQL Monitoring默认对超过5秒的SQL进行监控，你可能会有些需求，想对某些执行时间小于5秒的SQL进行监控（比如为了获取绑定变量，为了了解这个SQL执行时候的性能状况）你可以通过以下两种方式来达到目的：
修改隐含参数_sqlmon_threshold的阀值来具体设定对执行时间超过设定值的SQL进行监控，不建议以这种方式进行监控。不过就像一开头提到的，此隐含参数的单位为s，对于运行时间小于s的SQL，就无能为力了。
通过为SQL添加hint /*+ monitor */来进行，有多种方式可以在不修改SQL语句的情况下，动态的添加hint到相应的SQL上，例如：sql profile ,baseline,sql patch等等，我最喜欢的是sql profile，对SQL添加 /*+ monitor */ hint后，就可以从相关的数据字典视图获取这个SQL的监控信息，监控完成后，删除sql profile/baseline/sql patch。例如：
test@DLSP>select count(*) from a;

COUNT(*)
----------
15355

Elapsed: 00:00:00.00
test@DLSP>@findsql
Enter value for sql_text: %count(*) from a%
Enter value for sql_id:

SQL_ID CHILD PLAN_HASH EXECS AVG_ETIME AVG_LIO SQL_TEXT
-------------------------- ------ ---------- ---------- ------------- ------------ ------------------------------------------------------------
0a7q9v9nd2qc1 0 3747789477 1 .00 1 select count(*) from association$ where obj# = :1
68bgnf5vcx08y 0 3918351354 2 .01 205 select count(*) from a

@DLSP>select username,sql_id,sid,sql_text,cpu_time,buffer_gets,disk_reads from v$sql_monitor where sql_id='68bgnf5vcx08y';
no rows selected
可以看到由于SQL执行时间太短，还没被监控到。
@DLSP>@profile
Enter value for sql_id: 68bgnf5vcx08y

PLAN_TABLE_OUTPUT
---------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID 68bgnf5vcx08y, child number 0
-------------------------------------
select count(*) from a

Plan hash value: 3918351354

-------------------------------------------------------------------
| Id | Operation | Name | Rows | Cost (%CPU)| Time |
-------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | 21944 (100)| |
| 1 | SORT AGGREGATE | | 1 | | |
| 2 | TABLE ACCESS FULL| A | 1000K| 21944 (1)| 00:04:24 |
-------------------------------------------------------------------

Outline Data
-------------

/*+
BEGIN_OUTLINE_DATA
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('11.2.0.3')
DB_VERSION('11.2.0.3')
OPT_PARAM('_optim_peek_user_binds' 'false')
OPT_PARAM('_optimizer_skip_scan_enabled' 'false')
ALL_ROWS
OUTLINE_LEAF(@"SEL$1")
FULL(@"SEL$1" "A"@"SEL$1")
END_OUTLINE_DATA
*/

30 rows selected.

Enter value for hint_text: monitor
Profile profile_68bgnf5vcx08y_dwrose created.

test@DLSP>select count(*) from a;

COUNT(*)
----------
15355

1 row selected.

select username,sql_id,sid,sql_text,cpu_time,buffer_gets,disk_reads from v$sql_monitor where sql_id='68bgnf5vcx08y';

USERNAME SQL_ID SID SQL_TEXT CPU_TIME BUFFER_GETS DISK_READS
--------------- -------------------------- ---------- ------------------------------------------------ ---------- ----------- ----------
TEST 68bgnf5vcx08y 2475 select count(*) from a 8999 205 15

可以看到添加过/*+ monitor */ hint的SQL已经成功被ORACLE监控到了，最后删除这个SQL的 SQL PROFILE
exec DBMS_SQLTUNE.drop_sql_profile('profile_68bgnf5vcx08y_dwrose')

默认的Real Time SQL Monitoring对于每个捕获的SQL最多捕获480次(11gr1)，640次(11gr2)执行时的信息。此行为通过隐含参数_sqlmon_max_plan来控制，不建议把此值设置的过大，以免占用过多的SGA的内存。
例如以下是我在11GR2下做的测试：
declare
c number;
begin
for i in 1 .. 1000 loop
select /*+ monitor */ count(*) into c from test;
end loop;
end;
/

@DLSP>@findsql
Enter value for sql_text: %from test
Enter value for sql_id:

SQL_ID CHILD PLAN_HASH EXECS AVG_ETIME AVG_LIO SQL_TEXT
-------------------------- ------ ---------- ---------- ------------- ------------ ------------------------------------------------------------
4kn8gdu4v7nxc 0 1950795681 2000 .00 207 SELECT /*+ monitor */ COUNT(*) FROM TEST

@DLSP>select count(*) from v$sql_monitor where sql_id='4kn8gdu4v7nxc';

COUNT(*)
----------
640
虽然SQL执行了1000次，但是v$sql_monitor中只记录了640次此SQL的执行信息。

ITPub博客

ORACLE里的慢查跟踪 Real Time SQL Monitoring 11GR1 新特性

最新文章