sql的执行时间，我们往往可以通过ash中的sample时间，减去sql exec start，得出该sql执行的时间。有一个很不错的sql，可以看某个sql的历次执行时间，历次执行计划。
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 |
SELECT T.SQL_ID, T.SQL_EXEC_ID, CAST(MAX(T.SAMPLE_TIME) AS DATE) EXEC_END_TIME, T.SQL_EXEC_START EXEC_START_TIME, ROUND((CAST(MAX(T.SAMPLE_TIME) AS DATE) - T.SQL_EXEC_START) * 1440, 2) RUN_MINS, T.SQL_PLAN_HASH_VALUE, T.MODULE FROM v$active_session_history T WHERE T.SQL_ID = '&SQL_ID' AND T.SAMPLE_TIME > SYSDATE - 36 GROUP BY T.SQL_ID, T.SQL_EXEC_ID, T.SQL_EXEC_START, T.SQL_PLAN_HASH_VALUE, T.MODULE ORDER BY EXEC_END_TIME DESC; 或者 SELECT T.SQL_ID, T.SQL_EXEC_ID, CAST(MAX(T.SAMPLE_TIME) AS DATE) EXEC_END_TIME, T.SQL_EXEC_START EXEC_START_TIME, ROUND((CAST(MAX(T.SAMPLE_TIME) AS DATE) - T.SQL_EXEC_START) * 1440, 2) RUN_MINS, T.SQL_PLAN_HASH_VALUE, T.MODULE FROM sys.WRH$_ACTIVE_SESSION_HISTORY T WHERE T.SQL_ID = '&SQL_ID' AND T.SAMPLE_TIME > SYSDATE - 36 GROUP BY T.SQL_ID, T.SQL_EXEC_ID, T.SQL_EXEC_START, T.SQL_PLAN_HASH_VALUE, T.MODULE ORDER BY EXEC_END_TIME DESC; |
但是在使用游标的时候，如，在某个procedure中，有将sql的内容载入到游标，后续根据游标的每一行记录再做关联或别的操作。此时，在ash，甚至在sql monitor中去看，这个sql的执行时间都是有问题的。
看下面的这个例子：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 |
--drop table if exist drop table test; drop table test2; drop table runlog; --create 3 new table for testing create table test as select * from dba_objects; insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; commit; create table test2 as select * from dba_objects where 1=2; create table runlog (a varchar2(20),b timestamp); |
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 |
--create procedure for testing Create or REPLACE PROCEDURE nested_loop IS CURSOR a_cur IS select /*+ monitor*/* from test where object_name<>'hjm'; a_rec a_cur%ROWTYPE; BEGIN insert into runlog values('cursor end:',CURRENT_TIMESTAMP); commit; insert into runlog values('insert start:',CURRENT_TIMESTAMP); for v_last in a_cur loop begin insert into test2(object_id) values(v_last.object_id); end; if mod(a_cur%rowcount,5000)=0 then insert into runlog values('commit end:',CURRENT_TIMESTAMP); commit; end if; end loop; insert into runlog values('insert end:',CURRENT_TIMESTAMP); commit; END nested_loop; / |
注意，我们的procedure中，有个游标是做
|
1 |
select /*+ monitor*/* from test where object_name<>'hjm'; |
做完之后，利用游标的结果再做
|
1 |
insert into test2(object_id) values(v_last.object_id); |
其他的insert runlog表只是用来打时间戳。
这种情况其实是一种比较常见的调优场景，我们一个package中不知道那段sql执行的时间最长？是在cursor阶段load的慢，还是已经load到游标中了，后续的循环执行的比较慢？
我们运行上面的已经准备好的代码：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 |
21:12:43 test@ORA11G(192.168.1.37)> exec nested_loop; PL/SQL procedure successfully completed. Elapsed: 00:04:25.36 21:17:09 test@ORA11G(192.168.1.37)> --我们去找那个cursor的执行时间： SQL> select sql_text,sql_id from v$sql where sql_text like '%hjm%' 2 and sql_text not like '%v$sql%' 3 / SQL_TEXT SQL_ID -------------------------------------------------------------------------------- ------------- SELECT /*+ monitor*/* FROM TEST WHERE OBJECT_NAME<>'hjm' 404f94cfj5qfh SQL> SELECT T.SQL_ID, T.SQL_EXEC_ID, 2 CAST(MAX(T.SAMPLE_TIME) AS DATE) EXEC_END_TIME, 3 T.SQL_EXEC_START EXEC_START_TIME, 4 ROUND((CAST(MAX(T.SAMPLE_TIME) AS DATE) - T.SQL_EXEC_START) * 1440, 2) RUN_MINS, 5 T.SQL_PLAN_HASH_VALUE, T.MODULE 6 FROM v$active_session_history T 7 WHERE T.SQL_ID = '404f94cfj5qfh' 8 AND T.SAMPLE_TIME > SYSDATE - 36 9 GROUP BY T.SQL_ID, T.SQL_EXEC_ID, T.SQL_EXEC_START, T.SQL_PLAN_HASH_VALUE, T.MODULE 10 ORDER BY EXEC_END_TIME DESC 11 / SQL_ID SQL_EXEC_ID EXEC_END_TIME EXEC_START_TIME RUN_MINS SQL_PLAN_HASH_VALUE MODULE ------------- ----------- ------------- --------------- ---------- ------------------- ---------------------------------------------------------------- 404f94cfj5qfh 16777216 2013/11/26 21 2013/11/26 21:1 3.62 1357081020 SQL*Plus SQL> |
注意，这里看到，仅仅是select的那个语句，显示竟然运行了3.62分钟。
我们同样去看sql monitor的结果，也是显示264秒：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 |
SQL> select dbms_sqltune.report_sql_monitor('404f94cfj5qfh') from dual; DBMS_SQLTUNE.REPORT_SQL_MONITO -------------------------------------------------------------------------------- SQL Monitoring Report SQL Text ------------------------------ SELECT /*+ monitor*/* FROM TEST WHERE OBJECT_NAME<>'hjm' Global Information ------------------------------ Status : DONE (ALL ROWS) Instance ID : 1 Session : TEST (69:17) SQL ID : 404f94cfj5qfh SQL Execution ID : 16777216 Execution Started : 11/26/2013 21:12:44 First Refresh Time : 11/26/2013 21:12:44 Last Refresh Time : 11/26/2013 21:17:08 Duration : 264s Module/Action : SQL*Plus/- Service : SYS$USERS Program : sqlplus.exe PLSQL Entry Ids (Object/Subprogram) : 87155,1 PLSQL Current Ids (Object/Subprogram) : 87155,1 Fetch Calls : 55077 Global Stats ================================================= | Elapsed | Cpu | Other | Fetch | Buffer | | Time(s) | Time(s) | Waits(s) | Calls | Gets | ================================================= | 12 | 11 | 0.26 | 55077 | 197K | ================================================= SQL Plan Monitoring Details (Plan Hash Value=1357081020) ================================================================================ | Id | Operation | Name | Rows | Cost | Time | Start | Execs | | | | (Estim) | | Active(s) | Active | ================================================================================ | 0 | SELECT STATEMENT | | | | 265 | +0 | 1 | 1 | TABLE ACCESS FULL | TEST | 7M | 21361 | 265 | +0 | 1 ================================================================================ SQL> |
注意看，上面的这个select的sql竟然执行了264s。
其实这是错误的，这个select的sql，只是执行了很短的时间，我们看看之前我们打的时间戳：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 |
test@ORA11G(192.168.1.37)> select * from runlog order by 2; A B ---------------------------------------- --------------------------------------------------- cursor end: 26-NOV-13 09.12.44.544000 PM insert start: 26-NOV-13 09.12.44.546000 PM commit end: 26-NOV-13 09.12.44.844000 PM commit end: 26-NOV-13 09.12.45.104000 PM commit end: 26-NOV-13 09.12.45.318000 PM commit end: 26-NOV-13 09.12.45.519000 PM commit end: 26-NOV-13 09.12.45.720000 PM ……（每5000行commit一次，这部分中间的部分省略） commit end: 26-NOV-13 09.17.06.833000 PM commit end: 26-NOV-13 09.17.07.034000 PM commit end: 26-NOV-13 09.17.07.236000 PM commit end: 26-NOV-13 09.17.07.441000 PM commit end: 26-NOV-13 09.17.07.643000 PM commit end: 26-NOV-13 09.17.07.843000 PM commit end: 26-NOV-13 09.17.09.480000 PM commit end: 26-NOV-13 09.17.09.685000 PM insert end: 26-NOV-13 09.17.09.793000 PM 1104 rows selected. Elapsed: 00:00:01.17 test@ORA11G(192.168.1.37)> |
如果是那个select的游标是21:12:44开始，那么select结束时间应该是09.12.44.544000 PM，即不到1秒就结束了。后面的时间，只是利用游标在做别的事情。
因此，在生产场景，遇到类似这样的问题，其实可能不是游标select做的慢，而是和这个游标相关的后续的操作慢。大家在看ash或者sql monitor的时候，不要被这个迷惑了。