11GR1出現了一個比較有趣的新特性，“慢查”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會被監控到外，你還可以透過新增hint /*+ MONITOR */的方式來對想要跟蹤的SQL進行監控。
例如：
select /*+ MONITOR */* from a;

與此特性相關的2個動態效能檢視也同時被引入， and R。兩張表中的資料每秒被更新一次（以後的版本可能會改變這一情況），表中非常詳細的記錄了此SQL執行的相關資訊、執行計劃每個步驟所消耗的資源的資訊。可以直接檢視兩個檢視中的相關資訊，也可以透過DBMS_SQLTUNE 包的REPORT_SQL_MONITOR函式來以更加視覺化的方式進行展示和閱讀。
我們來透過幾個例子看看的一些功能。
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

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

預設對超過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的執行資訊。

ORACLE裡的慢查跟蹤 Real Time SQL Monitoring 11GR1 新特性

相關文章