【系统描述】
操作系统版本：
rhel5.8
数据库版本：
ORACLE 10.2.0.4
数据库名:
TESTDB
【现象】
从数据库TESTDB的EM监控上观察到sysman用户的一条sql执行耗时很长，且伴随着较高的CPU。AWR中看到该sql平均耗时在561s以上：
该sql的sql_id=4d43by1zzjfna，sql_text为：
|
with last_run as ( SELECT all_runs.OWNER, all_runs.JOB_NAME, all_runs.STATUS FROM DBA_SCHEDULER_JOB_RUN_DETAILS all_runs, (SELECT OWNER, JOB_NAME, MAX(ACTUAL_START_DATE) AS START_DATE FROM DBA_SCHEDULER_JOB_RUN_DETAILS GROUP BY OWNER, JOB_NAME) latest_runs WHERE all_runs.OWNER= latest_runs.OWNER AND all_runs.JOB_NAME= latest_runs.JOB_NAME AND all_runs.ACTUAL_START_DATE=latest_runs.START_DATE ) SELECT SUM(broken), SUM(failed) FROM (SELECT DECODE(broken, 'N', 0, 1) broken, DECODE(NVL(failures, 0), 0, 0, 1) failed FROM dba_jobs UNION ALL SELECT DECODE(STATE, 'BROKEN', 1, 0) broken, DECODE(STATUS , 'FAILED', DECODE(STATE, 'BROKEN', 0, 'DISABLED', 0, 1), 0) failed FROM (SELECT all_jobs.OWNER, all_jobs.JOB_NAME, last_run.STATUS, all_jobs.STATE FROM last_run, DBA_SCHEDULER_JOBS all_jobs WHERE last_run.OWNER=all_jobs.OWNER AND last_run.JOB_NAME=all_jobs.JOB_NAME)) |
【分析】
1. Sql分析
（1） 该sql直接查询的视图有两个：DBA_SCHEDULER_JOB_RUN_DETAILS、DBA_SCHEDULER_JOBS，这两个视图指向了更多的系统视图和系统表。
（2） Sql中形成的临时表last_run只有20行，与其联合查询的视图DBA_SCHEDULER_JOBS也只有18行。经测试，临时表的形成语句执行很快。
2. 执行计划
从sql分析来看，好的执行计划应该是先形成临时表，再和DBA_SCHEDULER_JOBS做联合查询，而不是将临时表和视图分解后再演算执行计划。
（1） TESTDB上该sql的执行计划：
|
------------------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time | ------------------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 6 | | 5886K (1)| 19:37:13 |
| 1 | SORT AGGREGATE | | 1 | 6 | | | | | 2 | VIEW | | 16 | 96 | | 5886K (1)| 19:37:13 | | 3 | UNION-ALL | | | | | | | | 4 | TABLE ACCESS FULL | JOB$ | 7 | 28 | | 2 (0)| 00:00:01 | | 5 | NESTED LOOPS OUTER | | 9 | 1512 | | 5886K (1)| 19:37:13 | |* 6 | HASH JOIN | | 9 | 1458 | | 5886K (1)| 19:37:13 | |* 7 | HASH JOIN | | 18 | 1098 | | 44 (3)| 00:00:01 | | 8 | NESTED LOOPS | | 18 | 828 | | 40 (0)| 00:00:01 | | 9 | TABLE ACCESS FULL | SCHEDULER$_JOB | 18 | 252 | | 4 (0)| 00:00:01 | | 10 | TABLE ACCESS BY INDEX ROWID| OBJ$ | 1 | 32 | | 2 (0)| 00:00:01 | |* 11 | INDEX UNIQUE SCAN | I_OBJ1 | 1 | | | 1 (0)| 00:00:01 | | 12 | TABLE ACCESS FULL | USER$ | 107 | 1605 | | 3 (0)| 00:00:01 | | 13 | VIEW | | 432K| 41M| | 5885K (1)| 19:37:12 |
|* 14 | FILTER | | | | | | | | 15 | SORT GROUP BY | | 432K| 54M| 76G| 5885K (1)| 19:37:12 | |* 16 | HASH JOIN | | 563M| 69G| | 5813 (96)| 00:01:10 | | 17 | TABLE ACCESS FULL | SCHEDULER$_JOB_RUN_DETAILS | 24472 | 740K| | 83 (0)| 00:00:02 | |* 18 | HASH JOIN | | 564M| 53G| | 2962 (94)| 00:00:36 | |* 19 | HASH JOIN | | 24472 | 1171K| | 140 (2)| 00:00:02 | | 20 | TABLE ACCESS FULL | SCHEDULER$_JOB_RUN_DETAILS | 24472 | 454K| | 83 (0)| 00:00:02 | |* 21 | TABLE ACCESS FULL | SCHEDULER$_EVENT_LOG | 24523 | 718K| | 55 (0)| 00:00:01 | |* 22 | TABLE ACCESS FULL | SCHEDULER$_EVENT_LOG | 24523 | 1245K| | 55 (0)| 00:00:01 | |* 23 | INDEX UNIQUE SCAN | I_OBJ1 | 1 | 6 | | 1 (0)| 00:00:01 | -------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
6 - access("LAST_RUN"."OWNER"="JU"."NAME" AND "LAST_RUN"."JOB_NAME"="JO"."NAME") 7 - access("JO"."OWNER#"="JU"."USER#") 11 - access("J"."OBJ#"="JO"."OBJ#") 14 - filter(SYS_EXTRACT_UTC("J"."START_DATE")=SYS_EXTRACT_UTC(MAX("J"."START_DATE"))) 16 - access("J"."LOG_ID"="E"."LOG_ID") 18 - access("E"."OWNER"="E"."OWNER" AND DECODE(INSTR("E"."NAME",'"'),0,"E"."NAME",SUBSTR("E"."NAME",1,INSTR("E" ."NAME",'"')-1))=DECODE(INSTR("E"."NAME",'"'),0,"E"."NAME",SUBSTR("E"."NAME",1,INSTR("E"."NAME",'"')-1))) 19 - access("J"."LOG_ID"="E"."LOG_ID") 21 - filter("E"."TYPE#"=66) 22 - filter("E"."TYPE#"=66) 23 - access("J"."CLASS_OID"="CO"."OBJ#"(+)) |
（2） 使用另一个相同版本（10.2.0.4）的库进行对比，该sql执行耗时在2s左右，执行计划与TESTDB上的不同：
|
PLAN_TABLE_OUTPUT -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Plan hash value: 1354652718
----------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | ----------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 6 | 39 (11)| 00:00:01 | | 1 | SORT AGGREGATE | | 1 | 6 | | | | 2 | VIEW | | 5 | 30 | 39 (11)| 00:00:01 | | 3 | UNION-ALL | | | | | | | 4 | TABLE ACCESS FULL | JOB$ | 4 | 16 | 2 (0)| 00:00:01 | | 5 | NESTED LOOPS OUTER | | 1 | 166 | 37 (11)| 00:00:01 | | 6 | NESTED LOOPS | | 1 | 161 | 37 (11)| 00:00:01 | |* 7 | HASH JOIN | | 1 | 146 | 36 (12)| 00:00:01 | | 8 | NESTED LOOPS | | 8 | 360 | 10 (0)| 00:00:01 | | 9 | TABLE ACCESS FULL | SCHEDULER$_JOB | 8 | 112 | 2 (0)| 00:00:01 | | 10 | TABLE ACCESS BY INDEX ROWID| OBJ$ | 1 | 31 | 1 (0)| 00:00:01 | |* 11 | INDEX UNIQUE SCAN | I_OBJ1 | 1 | | 0 (0)| 00:00:01 | | 12 | VIEW | | 219 | 22119 | 26 (16)| 00:00:01 | |* 13 | FILTER | | | | | | | 14 | SORT GROUP BY | | 219 | 29346 | 26 (16)| 00:00:01 | |* 15 | HASH JOIN | | 21820 | 2855K| 24 (9)| 00:00:01 | | 16 | TABLE ACCESS FULL | SCHEDULER$_JOB_RUN_DETAILS | 1637 | 29466 | 6 (0)| 00:00:01 | |* 17 | HASH JOIN | | 21820 | 2471K| 17 (6)| 00:00:01 | |* 18 | TABLE ACCESS FULL | SCHEDULER$_EVENT_LOG | 1637 | 52384 | 5 (0)| 00:00:01 | |* 19 | HASH JOIN | | 1637 | 134K| 12 (9)| 00:00:01 | | 20 | TABLE ACCESS FULL | SCHEDULER$_JOB_RUN_DETAILS | 1637 | 49110 | 6 (0)| 00:00:01 | |* 21 | TABLE ACCESS FULL | SCHEDULER$_EVENT_LOG | 1637 | 88398 | 5 (0)| 00:00:01 | |* 22 | TABLE ACCESS BY INDEX ROWID | USER$ | 1 | 15 | 1 (0)| 00:00:01 | |* 23 | INDEX UNIQUE SCAN | I_USER1 | 1 | | 0 (0)| 00:00:01 | |* 24 | INDEX UNIQUE SCAN | I_OBJ1 | 1 | 5 | 0 (0)| 00:00:01 | -----------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id): ---------------------------------------------------
7 - access("LAST_RUN"."JOB_NAME"="JO"."NAME") 11 - access("J"."OBJ#"="JO"."OBJ#") 13 - filter(SYS_EXTRACT_UTC("J"."START_DATE")=SYS_EXTRACT_UTC(MAX("J"."START_DATE"))) 15 - access("J"."LOG_ID"="E"."LOG_ID") 17 - access("E"."OWNER"="E"."OWNER" AND DECODE(INSTR("E"."NAME",'"'),0,"E"."NAME",SUBSTR("E"."NAME",1,I NSTR("E"."NAME",'"')-1))=DECODE(INSTR("E"."NAME",'"'),0,"E"."NAME",SUBSTR("E"."NAME",1,INSTR("E"."NAME",' "')-1))) 18 - filter("E"."TYPE#"=66) 19 - access("J"."LOG_ID"="E"."LOG_ID") 21 - filter("E"."TYPE#"=66) 22 - filter("JO"."OWNER#"="JU"."USER#") 23 - access("LAST_RUN"."OWNER"="JU"."NAME") 24 - access("J"."CLASS_OID"="CO"."OBJ#"(+)) |
相同版本相同sql在两个库的执行计划不一样，很有可能是数据量相差较大。通过查询，TESTDB上的视图DBA_SCHEDULER_JOB_RUN_DETAILS有2W多行，而对比用的数据库上，该视图只有2K行左右。
（3） 另外发现，11.2.0.4环境上该sql的执行计划和预期相同：
|
Plan Hash Value : 1742644583
-------------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost | Time | -------------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 6 | 986 | 00:00:12 | | 1 | SORT AGGREGATE | | 1 | 6 | | | | 2 | VIEW | | 24 | 144 | 986 | 00:00:12 | | 3 | UNION-ALL | | | | | | | * 4 | TABLE ACCESS FULL | JOB$ | 23 | 437 | 2 | 00:00:01 | | 5 | NESTED LOOPS | | 1 | 202 | 984 | 00:00:12 | | * 6 | HASH JOIN | | 5 | 780 | 939 | 00:00:12 | | 7 | TABLE ACCESS FULL | SCHEDULER$_JOB_RUN_DETAILS | 6404 | 115272 | 25 | 00:00:01 | | * 8 | HASH JOIN | | 2179 | 300702 | 914 | 00:00:11 | | 9 | VIEW | | 6404 | 557148 | 470 | 00:00:06 | | 10 | HASH GROUP BY | | 6404 | 422664 | 470 | 00:00:06 | | * 11 | HASH JOIN | | 6404 | 422664 | 469 | 00:00:06 | | 12 | TABLE ACCESS FULL | SCHEDULER$_JOB_RUN_DETAILS | 6404 | 115272 | 25 | 00:00:01 | | * 13 | TABLE ACCESS FULL | SCHEDULER$_EVENT_LOG | 28868 | 1385664 | 444 | 00:00:06 | | * 14 | TABLE ACCESS FULL | SCHEDULER$_EVENT_LOG | 28868 | 1472268 | 444 | 00:00:06 | | 15 | VIEW | DBA_SCHEDULER_JOBS | 1 | 46 | 9 | 00:00:01 | | 16 | UNION ALL PUSHED PREDICATE | | | | | | | 17 | MERGE JOIN CARTESIAN | | 78 | 9750 | 5 | 00:00:01 | | 18 | NESTED LOOPS OUTER | | 1 | 125 | 5 | 00:00:01 | | 19 | NESTED LOOPS | | 1 | 120 | 4 | 00:00:01 | | 20 | NESTED LOOPS | | 1 | 88 | 3 | 00:00:01 | | 21 | NESTED LOOPS | | 1 | 56 | 1 | 00:00:01 | | 22 | TABLE ACCESS BY INDEX ROWID | USER$ | 1 | 17 | 1 | 00:00:01 | | * 23 | INDEX UNIQUE SCAN | I_USER1 | 1 | | 0 | 00:00:01 | | * 24 | FIXED TABLE FULL | X$KCCDI | 1 | 39 | 0 | 00:00:01 | | * 25 | INDEX RANGE SCAN | I_OBJ2 | 1 | 32 | 2 | 00:00:01 | | * 26 | TABLE ACCESS BY INDEX ROWID | SCHEDULER$_JOB | 1 | 32 | 1 | 00:00:01 | | * 27 | INDEX UNIQUE SCAN | SCHEDULER$_JOB_PK | 1 | | 0 | 00:00:01 | | * 28 | INDEX RANGE SCAN | I_OBJ1 | 1 | 5 | 1 | 00:00:01 | | 29 | BUFFER SORT | | 100 | | 4 | 00:00:01 | | 30 | FIXED TABLE FULL | X$KCCDI2 | 100 | | 0 | 00:00:01 | | 31 | NESTED LOOPS | | 1 | 152 | 4 | 00:00:01 | | 32 | NESTED LOOPS OUTER | | 1 | 143 | 3 | 00:00:01 | | 33 | NESTED LOOPS | | 1 | 138 | 2 | 00:00:01 | | 34 | NESTED LOOPS | | 1 | 60 | 2 | 00:00:01 | | 35 | TABLE ACCESS BY INDEX ROWID | USER$ | 1 | 17 | 1 | 00:00:01 | | * 36 | INDEX UNIQUE SCAN | I_USER1 | 1 | | 0 | 00:00:01 | | 37 | TABLE ACCESS BY INDEX ROWID | SCHEDULER$_LWJOB_OBJ | 1 | 43 | 1 | 00:00:01 | | * 38 | INDEX RANGE SCAN | SCHEDULER$_LOBJ_UK | 1 | | 1 | 00:00:01 | | * 39 | TABLE ACCESS BY INDEX ROWID | SCHEDULER$_LIGHTWEIGHT_JOB | 1 | 78 | 0 | 00:00:01 | | * 40 | INDEX UNIQUE SCAN | SCHEDULER$_LWJOB_PK | 1 | | 0 | 00:00:01 | | * 41 | INDEX RANGE SCAN | I_OBJ1 | 1 | 5 | 1 | 00:00:01 | | * 42 | INDEX RANGE SCAN | I_OBJ1 | 1 | 9 | 1 | 00:00:01 | --------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id): ------------------------------------------ * 4 - filter(BITAND("J"."SCHEDULER_FLAGS",2) IS NULL OR BITAND("J"."SCHEDULER_FLAGS",2)=0) * 6 - access(SYS_EXTRACT_UTC("J"."START_DATE")=SYS_EXTRACT_UTC("LATEST_RUNS"."START_DATE") AND "J"."LOG_ID"="E"."LOG_ID") * 8 - access("E"."OWNER"="LATEST_RUNS"."OWNER" AND "LATEST_RUNS"."JOB_NAME"=DECODE(INSTR("E"."NAME",'"'),0,"E"."NAME",SUBSTR("E"."NAME",1,INSTR("E"."NAME",'"')-1))) * 11 - access("J"."LOG_ID"="E"."LOG_ID") * 13 - filter("E"."TYPE#"=66 AND "E"."DBID" IS NULL) * 14 - filter("E"."TYPE#"=66 AND "E"."DBID" IS NULL) * 23 - access("JU"."NAME"="E"."OWNER") * 24 - filter("DI"."INST_ID"=USERENV('INSTANCE')) * 25 - access("JO"."OWNER#"="JU"."USER#" AND "JO"."NAME"=DECODE(INSTR("E"."NAME",'"'),0,"E"."NAME",SUBSTR("E"."NAME",1,INSTR("E"."NAME",'"')-1))) * 26 - filter("J"."DATABASE_ROLE"=DECODE(BITAND("DI"."DIFL2",32768),32768,'SNAPSHOT STANDBY',DECODE(BITAND("DI"."DIFLG",33554432),33554432,'LOGICAL STANDBY',DECODE(BITAND("DI"."DIFLG",1024),1024,'PHYSICAL STANDBY','PRIMARY'))) OR "J"."DATABASE_ROLE" IS NULL AND DECODE(BITAND("DI"."DIFL2",32768),32768,'SNAPSHOT STANDBY',DECODE(BITAND("DI"."DIFLG",33554432),33554432,'LOGICAL STANDBY',DECODE(BITAND("DI"."DIFLG",1024),1024,'PHYSICAL STANDBY','PRIMARY')))='PRIMARY') * 27 - access("J"."OBJ#"="JO"."OBJ#") * 28 - access("J"."CLASS_OID"="CO"."OBJ#"(+)) * 36 - access("LU"."NAME"="E"."OWNER") * 38 - access("LO"."USERID"="LU"."USER#" AND "LO"."NAME"=DECODE(INSTR("E"."NAME",'"'),0,"E"."NAME",SUBSTR("E"."NAME",1,INSTR("E"."NAME",'"')-1))) * 39 - filter(BITAND("L"."FLAGS",137438953472)=0) * 40 - access("L"."OBJ#"="LO"."OBJ#") * 41 - access("L"."CLASS_OID"="LCO"."OBJ#"(+)) * 42 - access("L"."PROGRAM_OID"="PO"."OBJ#") * 42 - filter(BITAND("L"."FLAGS",8589934592)=0 AND "PO"."TYPE#"=67 OR "PO"."TYPE#"=66 AND BITAND("L"."FLAGS",8589934592)<>0) |
该执行计划和10.2.0.4版本的相差较大，且多了几个系统表。
【解决方案研究】
1. 给sql加入hint
从两个10g的版本对比情况来看，TESTDB上的执行计划第6行使用了hash join，而另一个执行较快的库上使用的是nested loops。TESTDB上第6行的sql_opname为：
|
6 - access("LAST_RUN"."OWNER"="JU"."NAME" AND "LAST_RUN"."JOB_NAME"="JO"."NAME") |
LAST_RUN是临时视图，结果集只有20行，既然执行较快的库上使用了NESTED LOOPS，那么可以考虑TESTDB上也使用NESTED LOOPS。
经过绑定hint（/*+use_nl(t1,t2)*/），执行计划确实使用了NESTED LOOPS但是执行效率依然很差。
2. 将11.2.0.4的SQL执行计划强加给10.2.0.4的SQL
TESTDB上的执行计划第6行中，JO 为视图DBA_SCHEDULER_JOBS 引用的系统表obj$, JU为视图DBA_SCHEDULER_JOBS 引用的系统表user$。说明执行计划并不是预期的临时表last_run和视图DBA_SCHEDULER_JOBS的结果集进行联合，而是将视图DBA_SCHEDULER_JOBS分解后产生的执行计划。11.2.0.4的SQL执行计划是预期的，所以可以考虑将11.2.0.4的sql执行计划强加给TESTDB。方法如下：
（1）在11.2.0.4的环境执行该SQL
（2）之后执行如下SQL：
|
select * from table(dbms_xplan.display_cursor(null,null,'advanced')); |
（3）把outline data部分复制并且加到10G的sql前面
例如：
Outline Data
-------------
/*+
BEGIN_OUTLINE_DATA
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('11.2.0.4')
DB_VERSION('11.2.0.4')
OUTLINE_LEAF(@"SEL$3")
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
OUTLINE_LEAF(@"SEL$5")
OUTLINE_LEAF(@"SEL$6")
OUTLINE_LEAF(@"SEL$1FF6F973")
MERGE(@"SEL$4")
OUTLINE_LEAF(@"SEL$7")
OUTLINE_LEAF(@"SET$1")
OUTLINE_LEAF(@"SEL$1")
OUTLINE(@"SEL$2")
OUTLINE(@"SEL$4")
NO_ACCESS(@"SEL$1" "DBA_OBJECTS"@"SEL$1")
FULL(@"SEL$7" "L"@"SEL$7")
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
...........
.........
*/
（由于没有设置pagesize，所以显示出来的有一些表头“PLAN_TABLE_OUTPUT”，在添加到sql时需要将这些表头删除。）
加入后SQL类似于：
select
/*+
BEGIN_OUTLINE_DATA
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('11.2.0.4')
DB_VERSION('11.2.0.4')
ALL_ROWS
...........
.........
*/
* from ....
测试证明，该方法不管用。
3. 收集统计信息
由于是系统的对象，所以搜集统计信息的命令如下：
|
SQL> exec dbms_stats.GATHER_FIXED_OBJECTS_STATS SQL> EXEC DBMS_STATS.GATHER_DICTIONARY_STATS; |
该方法也不管用。
4. 减小表的大小
（Slow Performance Oracle Enterprise Manager SQL Metrics SQL statement (SQL ID: 4d43by1zzjfna) Automatically Run ( Doc ID 2266608.1 ) ）
视图DBA_SCHEDULER_JOB_RUN_DETAILS查询结果为数据库中定时任务的执行日志，默认保留30天，查询方法：
|
SQL> set serveroutput on SQL> SQL> declare 2 output VARCHAR2(30); 3 begin 4 DBMS_SCHEDULER.GET_SCHEDULER_ATTRIBUTE('log_history',output); 5 dbms_output.put_line(output); 6 end; 7 / 30 PL/SQL procedure successfully completed |
DBMS_SCHEDULER包提供了清理日志的方法PURGE_LOG，执行如下命令清理7天前的日志：
|
SQL>exec DBMS_SCHEDULER.PURGE_LOG(7,which_log=>'JOB_LOG'); SQL>exec DBMS_SCHEDULER.PURGE_LOG(7,which_log=>'WINDOW_LOG'); SQL>exec DBMS_SCHEDULER.PURGE_LOG(log_history => 7, job_name => 'job1, sys.class2'); |
为了避免日志量的增加，可以设置只保留7天的日志：
|
SQL>exec DBMS_SCHEDULER.SET_SCHEDULER_ATTRIBUTE('log_history','7'); |
日志清理后，重新收集一下统计信息：
|
SQL> EXEC DBMS_STATS.GATHER_FIXED_OBJECTS_STATS; SQL> EXEC DBMS_STATS.GATHER_DICTIONARY_STATS; SQL> EXEC DBMS_STATS.GATHER_SCHEMA_STATS ('SYS'); |
该方法实施后，DBA_SCHEDULER_JOB_RUN_DETAILS的行数降到了6K行以下：
|
SQL> select count(*) from DBA_SCHEDULER_JOB_RUN_DETAILS;
COUNT(*) ---------- 5859 |
SQL执行时间缩短到50s，系统CPU消耗大大降低。
来自 “ ITPUB博客 ” ，链接：https://blog.itpub.net/31408974/viewspace-2149602/ ，如需转载，请注明出处，否则将追究法律责任。
