Table of contents
Preamble
A performance issue came to me on a Documentum database, the involve table can be find on many blog posts and articles on Internet. The last advice we got from EMC was to set:
optimizer_mode = FIRST_ROWS_10 optimizer_index_cost_adj = 5 optimizer_index_caching = 95 cursor_sharing = FORCE session_cached_cursors = 50 |
It’s quite easy with AWR, dictionary tables (V$SQL, V$SESSION_LONGOPS, V$SESSION_EVENT, …) and system tools (top, glance, nmon, …) to see that all performance issue are linked to an unique SQL statement with sql_id equal to 0t5fw0gtf0665 with plan_hash_value 554605205 (pair to uniquely identify a SQL statement) on my database (HPUX 11iv1, Oracle release 10.2.0.3.0):
SELECT ALL web_document.r_object_id FROM web_document_sp web_document WHERE (web_document.i_chronicle_id IN (SELECT ALL web_document.i_chronicle_id FROM web_document_sp web_document WHERE ((web_document.r_object_id=:"SYS_B_0")) AND web_document.i_is_deleted = :"SYS_B_1" ) AND EXISTS (SELECT r_object_id FROM dm_sysobject_r WHERE web_document.r_object_id = r_object_id AND r_version_label=:"SYS_B_2")) AND web_document.i_is_deleted = :"SYS_B_3" |
With below explain plan:
SQL> col PLAN FOR a180 SQL> SET lines 180 SQL> SET pagesize 100 SQL> SELECT RPAD('(' || p.ID || ' ' || NVL(p.parent_id,'0') || ')',8) || '|' || RPAD(LPAD (' ', 2*p.DEPTH) || p.operation || ' ' || p.options,40,'.') || NVL2(p.object_owner||p.object_name, '(' || p.object_owner|| '.' || p.object_name || ') ', '') || 'Cost:' || p.COST || ' ' || NVL2(p.bytes||p.CARDINALITY,'(' || p.bytes || ' bytes, ' || p.CARDINALITY || ' rows)','') || ' ' || NVL2(p.partition_id || p.partition_start || p.partition_stop,'PId:' || p.partition_id || ' PStart:' || p.partition_start || ' PStop:' || p.partition_stop,'') || 'io cost=' || p.io_cost || ',cpu_cost=' || p.cpu_cost AS PLAN FROM dba_hist_sql_plan p WHERE p.sql_id='0t5fw0gtf0665' AND plan_hash_value='554605205' ORDER BY p.id, p.parent_id; PLAN ------------------------------------------------------------------------------------------------------------------------------------------------ (0 0) |SELECT STATEMENT .......................COST:224047 io COST=,cpu_cost= (1 0) | FILTER ...............................COST: io COST=,cpu_cost= (2 1) | NESTED LOOPS .......................COST:9932 (7856221 bytes, 110651 ROWS) io COST=8864,cpu_cost=1456724904 (3 2) | NESTED LOOPS .....................COST:9926 (6981205 bytes, 126931 ROWS) io COST=8863,cpu_cost=1450061026 (4 3) | SORT UNIQUE.....................COST:5907 (2411689 bytes, 126931 ROWS) io COST=4946,cpu_cost=1310768470 (5 4) | TABLE ACCESS FULL.............(WCMS.DM_SYSOBJECT_R) COST:5907 (2411689 bytes, 126931 ROWS) io COST=4946,cpu_cost=1310768470 (6 3) | TABLE ACCESS BY INDEX ROWID.....(WCMS.DM_SYSOBJECT_S) COST:1 (36 bytes, 1 ROWS) io COST=1,cpu_cost=459 (7 6) | INDEX UNIQUE SCAN.............(WCMS.D_1F0034238000010A) COST:1 ( bytes, 1 ROWS) io COST=1,cpu_cost=53 (8 2) | INDEX UNIQUE SCAN.................(WCMS.D_1F00342380000900) COST:1 (16 bytes, 1 ROWS) io COST=1,cpu_cost=53 (9 1) | NESTED LOOPS .......................COST:2 (52 bytes, 1 ROWS) io COST=2,cpu_cost=1222 (10 9) | INDEX UNIQUE SCAN.................(WCMS.D_1F00342380000900) COST:1 (16 bytes, 1 ROWS) io COST=1,cpu_cost=765 (11 9) | TABLE ACCESS BY INDEX ROWID.......(WCMS.DM_SYSOBJECT_S) COST:1 (36 bytes, 1 ROWS) io COST=1,cpu_cost=458 (12 11) | INDEX UNIQUE SCAN...............(WCMS.D_1F0034238000010A) COST:1 ( bytes, 1 ROWS) io COST=1,cpu_cost=53 13 ROWS selected. |
Instead of tuning it manually I decided to use one of the tool we pay for: SQL Tuning Advisor (STA). This tool can be accessed by DBMS_SQLTUNE package.
Tuning task
First create a tuning task based on the sql_id we identified. Here no need to create a SQL Tuning Set (STS) because we want to tune only one particular statement, working with sql text is also less user friendly:
SQL> DECLARE stmt_task VARCHAR2(64); BEGIN stmt_task:=dbms_sqltune.create_tuning_task(sql_id => '0t5fw0gtf0665', plan_hash_value => '554605205', time_limit => 3600, task_name => 'Tune_0t5fw0gtf0665', description => 'Task to tune 0t5fw0gtf0665 sql_id'); END; / PL/SQL PROCEDURE successfully completed. |
Once created we ask Oracle to effectively execute it:
SQL> EXECUTE dbms_sqltune.execute_tuning_task('Tune_0t5fw0gtf0665'); PL/SQL PROCEDURE successfully completed. |
Remark
The task name is case sensitive.
As it is asynchronous task you can check its completion with:
SQL> ALTER SESSION SET nls_date_format='dd-mon-yyyy hh24:mi:ss'; SESSION altered. SQL> col description FOR a40 SQL> SELECT task_name, description, advisor_name, execution_start, execution_end, status FROM dba_advisor_tasks WHERE owner='YJAQUIER' ORDER BY task_id DESC; TASK_NAME DESCRIPTION ADVISOR_NAME EXECUTION_START EXECUTION_END STATUS ------------------------------ ---------------------------------------- ------------------------------ -------------------- -------------------- ----------- Tune_0t5fw0gtf0665 Task TO tune 0t5fw0gtf0665 sql_id SQL Tuning Advisor 28-sep-2011 17:05:50 28-sep-2011 17:06:03 COMPLETED |
Once completed we display the outcome with:
SQL> SET linesize 200 SQL> SET LONG 999999999 SQL> SET pages 1000 SQL> SET longchunksize 20000 SQL> SELECT dbms_sqltune.report_tuning_task('Tune_0t5fw0gtf0665', 'TEXT', 'ALL') FROM dual; DBMS_SQLTUNE.REPORT_TUNING_TAS ------------------------------------------------------------------------------------------------------------------------------------------------ GENERAL INFORMATION SECTION ------------------------------------------------------------------------------- Tuning Task Name : Tune_0t5fw0gtf0665 Tuning Task Owner : YJAQUIER Tuning Task ID : 57356 Scope : COMPREHENSIVE TIME Limit(seconds) : 3600 Completion Status : COMPLETED Started AT : 09/28/2011 17:05:50 Completed AT : 09/28/2011 17:06:03 NUMBER OF SQL PROFILE Findings : 1 ------------------------------------------------------------------------------- SCHEMA Name: WCMS SQL ID : 0t5fw0gtf0665 SQL Text : SELECT ALL web_document.r_object_id FROM web_document_sp web_document WHERE (web_document.i_chronicle_id IN (SELECT ALL web_document.i_chronicle_id FROM web_document_sp web_document WHERE ((web_document.r_object_id=:"SYS_B_0")) AND web_document.i_is_deleted = :"SYS_B_1" ) AND EXISTS (SELECT r_object_id FROM dm_sysobject_r WHERE web_document.r_object_id = r_object_id AND r_version_label=:"SYS_B_2")) AND web_document.i_is_deleted = :"SYS_B_3" ------------------------------------------------------------------------------- FINDINGS SECTION (1 finding) ------------------------------------------------------------------------------- 1- SQL PROFILE Finding (see EXPLAIN plans section below) -------------------------------------------------------- A potentially better execution PLAN was found FOR this statement. Recommendation (estimated benefit: 99.99%) ------------------------------------------ - Consider accepting the recommended SQL PROFILE. EXECUTE dbms_sqltune.accept_sql_profile(task_name => 'Tune_0t5fw0gtf0665', REPLACE => TRUE); |
------------------------------------------------------------------------------- EXPLAIN PLANS SECTION ------------------------------------------------------------------------------- 1- Original ----------- PLAN hash VALUE: 554605205 ----------------------------------------------------------------------------------------------------- | Id | Operation | Name | ROWS | Bytes | COST (%CPU)| TIME | ----------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 73 | 231K (1)| 00:46:19 | |* 1 | FILTER | | | | | | | 2 | NESTED LOOPS | | 114K| 8150K| 10068 (11)| 00:02:01 | | 3 | NESTED LOOPS | | 129K| 7101K| 10062 (11)| 00:02:01 | | 4 | SORT UNIQUE | | 129K| 2536K| 5923 (17)| 00:01:12 | |* 5 | TABLE ACCESS FULL | DM_SYSOBJECT_R | 129K| 2536K| 5923 (17)| 00:01:12 | |* 6 | TABLE ACCESS BY INDEX ROWID| DM_SYSOBJECT_S | 1 | 36 | 1 (0)| 00:00:01 | |* 7 | INDEX UNIQUE SCAN | D_1F0034238000010A | 1 | | 1 (0)| 00:00:01 | |* 8 | INDEX UNIQUE SCAN | D_1F00342380000900 | 1 | 17 | 1 (0)| 00:00:01 | | 9 | NESTED LOOPS | | 1 | 53 | 2 (0)| 00:00:01 | |* 10 | INDEX UNIQUE SCAN | D_1F00342380000900 | 1 | 17 | 1 (0)| 00:00:01 | |* 11 | TABLE ACCESS BY INDEX ROWID | DM_SYSOBJECT_S | 1 | 36 | 1 (0)| 00:00:01 | |* 12 | INDEX UNIQUE SCAN | D_1F0034238000010A | 1 | | 1 (0)| 00:00:01 | ----------------------------------------------------------------------------------------------------- Query Block Name / Object Alias (IDENTIFIED BY operation id): ------------------------------------------------------------- 1 - SEL$349708FE 5 - SEL$349708FE / DM_SYSOBJECT_R@SEL$5 6 - SEL$349708FE / YB_@SEL$2 7 - SEL$349708FE / YB_@SEL$2 8 - SEL$349708FE / HR_@SEL$2 9 - SEL$07BDC5B4 10 - SEL$07BDC5B4 / HR_@SEL$4 11 - SEL$07BDC5B4 / YB_@SEL$4 12 - SEL$07BDC5B4 / YB_@SEL$4 Predicate Information (IDENTIFIED BY operation id): --------------------------------------------------- 1 - filter( EXISTS (SELECT /*+ */ 0 FROM "WCMS"."WEB_DOCUMENT_S" "HR_","WCMS"."DM_SYSOBJECT_S" "YB_" WHERE "YB_"."R_OBJECT_ID"=:SYS_B_0 AND "YB_"."I_CHRONICLE_ID"=:B1 AND "YB_"."I_IS_DELETED"=:SYS_B_1 AND "HR_"."R_OBJECT_ID"=:SYS_B_0)) 5 - filter("R_VERSION_LABEL"=:SYS_B_2) 6 - filter("YB_"."I_IS_DELETED"=:SYS_B_3) 7 - ACCESS("YB_"."R_OBJECT_ID"="R_OBJECT_ID") 8 - ACCESS("YB_"."R_OBJECT_ID"="HR_"."R_OBJECT_ID") 10 - ACCESS("HR_"."R_OBJECT_ID"=:SYS_B_0) 11 - filter("YB_"."I_CHRONICLE_ID"=:B1 AND "YB_"."I_IS_DELETED"=:SYS_B_1) 12 - ACCESS("YB_"."R_OBJECT_ID"=:SYS_B_0) COLUMN Projection Information (IDENTIFIED BY operation id): ----------------------------------------------------------- 1 - "YB_"."R_OBJECT_ID"[VARCHAR2,16] 2 - (#keys=0) "YB_"."R_OBJECT_ID"[VARCHAR2,16], "YB_"."I_CHRONICLE_ID"[VARCHAR2,16] 3 - (#keys=0) "YB_"."R_OBJECT_ID"[VARCHAR2,16], "YB_"."I_CHRONICLE_ID"[VARCHAR2,16] 4 - (#keys=1) "R_OBJECT_ID"[VARCHAR2,16] 5 - "R_OBJECT_ID"[VARCHAR2,16] 6 - "YB_"."R_OBJECT_ID"[VARCHAR2,16], "YB_"."I_CHRONICLE_ID"[VARCHAR2,16] 7 - "SYS_ALIAS_1".ROWID[ROWID,10], "YB_"."R_OBJECT_ID"[VARCHAR2,16] 9 - (#keys=0) 12 - "YB_".ROWID[ROWID,10] 2- Original WITH Adjusted COST ------------------------------ PLAN hash VALUE: 554605205 ----------------------------------------------------------------------------------------------------- | Id | Operation | Name | ROWS | Bytes | COST (%CPU)| TIME | ----------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 73 | 231K (1)| 00:46:19 | |* 1 | FILTER | | | | | | | 2 | NESTED LOOPS | | 114K| 8150K| 10068 (11)| 00:02:01 | | 3 | NESTED LOOPS | | 129K| 7101K| 10062 (11)| 00:02:01 | | 4 | SORT UNIQUE | | 129K| 2536K| 5923 (17)| 00:01:12 | |* 5 | TABLE ACCESS FULL | DM_SYSOBJECT_R | 129K| 2536K| 5923 (17)| 00:01:12 | |* 6 | TABLE ACCESS BY INDEX ROWID| DM_SYSOBJECT_S | 1 | 36 | 1 (0)| 00:00:01 | |* 7 | INDEX UNIQUE SCAN | D_1F0034238000010A | 1 | | 1 (0)| 00:00:01 | |* 8 | INDEX UNIQUE SCAN | D_1F00342380000900 | 1 | 17 | 1 (0)| 00:00:01 | | 9 | NESTED LOOPS | | 1 | 53 | 2 (0)| 00:00:01 | |* 10 | INDEX UNIQUE SCAN | D_1F00342380000900 | 1 | 17 | 1 (0)| 00:00:01 | |* 11 | TABLE ACCESS BY INDEX ROWID | DM_SYSOBJECT_S | 1 | 36 | 1 (0)| 00:00:01 | |* 12 | INDEX UNIQUE SCAN | D_1F0034238000010A | 1 | | 1 (0)| 00:00:01 | ----------------------------------------------------------------------------------------------------- Query Block Name / Object Alias (IDENTIFIED BY operation id): ------------------------------------------------------------- 1 - SEL$349708FE 5 - SEL$349708FE / DM_SYSOBJECT_R@SEL$5 6 - SEL$349708FE / YB_@SEL$2 7 - SEL$349708FE / YB_@SEL$2 8 - SEL$349708FE / HR_@SEL$2 9 - SEL$07BDC5B4 10 - SEL$07BDC5B4 / HR_@SEL$4 11 - SEL$07BDC5B4 / YB_@SEL$4 12 - SEL$07BDC5B4 / YB_@SEL$4 Predicate Information (IDENTIFIED BY operation id): --------------------------------------------------- 1 - filter( EXISTS (SELECT /*+ LEADING ("HR_" "YB_") OPT_ESTIMATE (TABLE "HR_" SCALE_ROWS=2.987500 ) INDEX ("HR_" "D_1F00342380000900") OPT_ESTIMATE (TABLE "YB_" SCALE_ROWS=4.524585 ) USE_NL ("YB_") INDEX_RS_ASC ("YB_" "D_1F0034238000010A") */ 0 FROM "WCMS"."WEB_DOCUMENT_S" "HR_","WCMS"."DM_SYSOBJECT_S" "YB_" WHERE "YB_"."R_OBJECT_ID"=:SYS_B_0 AND "YB_"."I_CHRONICLE_ID"=:B1 AND "YB_"."I_IS_DELETED"=:SYS_B_1 AND "HR_"."R_OBJECT_ID"=:SYS_B_0)) 5 - filter("R_VERSION_LABEL"=:SYS_B_2) 6 - filter("YB_"."I_IS_DELETED"=:SYS_B_3) 7 - ACCESS("YB_"."R_OBJECT_ID"="R_OBJECT_ID") 8 - ACCESS("YB_"."R_OBJECT_ID"="HR_"."R_OBJECT_ID") 10 - ACCESS("HR_"."R_OBJECT_ID"=:SYS_B_0) 11 - filter("YB_"."I_CHRONICLE_ID"=:B1 AND "YB_"."I_IS_DELETED"=:SYS_B_1) 12 - ACCESS("YB_"."R_OBJECT_ID"=:SYS_B_0) COLUMN Projection Information (IDENTIFIED BY operation id): ----------------------------------------------------------- 1 - "YB_"."R_OBJECT_ID"[VARCHAR2,16] 2 - (#keys=0) "YB_"."R_OBJECT_ID"[VARCHAR2,16], "YB_"."I_CHRONICLE_ID"[VARCHAR2,16] 3 - (#keys=0) "YB_"."R_OBJECT_ID"[VARCHAR2,16], "YB_"."I_CHRONICLE_ID"[VARCHAR2,16] 4 - (#keys=1) "R_OBJECT_ID"[VARCHAR2,16] 5 - "R_OBJECT_ID"[VARCHAR2,16] 6 - "YB_"."R_OBJECT_ID"[VARCHAR2,16], "YB_"."I_CHRONICLE_ID"[VARCHAR2,16] 7 - "SYS_ALIAS_1".ROWID[ROWID,10], "YB_"."R_OBJECT_ID"[VARCHAR2,16] 9 - (#keys=0) 12 - "YB_".ROWID[ROWID,10] 3- USING SQL PROFILE -------------------- PLAN hash VALUE: 3149505603 ------------------------------------------------------------------------------------------------------- | Id | Operation | Name | ROWS | Bytes | COST (%CPU)| TIME | ------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 83 | 6 (17)| 00:00:01 | | 1 | NESTED LOOPS SEMI | | 1 | 83 | 6 (17)| 00:00:01 | | 2 | NESTED LOOPS | | 4 | 252 | 5 (20)| 00:00:01 | | 3 | NESTED LOOPS | | 5 | 230 | 4 (25)| 00:00:01 | | 4 | VIEW | VW_NSO_1 | 1 | 10 | 2 (0)| 00:00:01 | | 5 | NESTED LOOPS | | 1 | 53 | 2 (0)| 00:00:01 | |* 6 | INDEX UNIQUE SCAN | D_1F00342380000900 | 1 | 17 | 1 (0)| 00:00:01 | |* 7 | TABLE ACCESS BY INDEX ROWID| DM_SYSOBJECT_S | 1 | 36 | 1 (0)| 00:00:01 | |* 8 | INDEX UNIQUE SCAN | D_1F0034238000010A | 1 | | 1 (0)| 00:00:01 | |* 9 | TABLE ACCESS BY INDEX ROWID | DM_SYSOBJECT_S | 1953 | 70308 | 1 (0)| 00:00:01 | |* 10 | INDEX RANGE SCAN | D_1F0034238000000E | 4 | | 1 (0)| 00:00:01 | |* 11 | INDEX UNIQUE SCAN | D_1F00342380000900 | 1 | 17 | 1 (0)| 00:00:01 | |* 12 | TABLE ACCESS BY INDEX ROWID | DM_SYSOBJECT_R | 18826 | 367K| 1 (0)| 00:00:01 | |* 13 | INDEX RANGE SCAN | D_1F0034238000010B | 3 | | 1 (0)| 00:00:01 | ------------------------------------------------------------------------------------------------------- Query Block Name / Object Alias (IDENTIFIED BY operation id): ------------------------------------------------------------- 1 - SEL$A6A19A00 4 - SEL$A8541665 / VW_NSO_1@SEL$A6A19A00 5 - SEL$A8541665 6 - SEL$A8541665 / HR_@SEL$4 7 - SEL$A8541665 / YB_@SEL$4 8 - SEL$A8541665 / YB_@SEL$4 9 - SEL$A6A19A00 / YB_@SEL$2 10 - SEL$A6A19A00 / YB_@SEL$2 11 - SEL$A6A19A00 / HR_@SEL$2 12 - SEL$A6A19A00 / DM_SYSOBJECT_R@SEL$5 13 - SEL$A6A19A00 / DM_SYSOBJECT_R@SEL$5 Predicate Information (IDENTIFIED BY operation id): --------------------------------------------------- 6 - ACCESS("HR_"."R_OBJECT_ID"=:SYS_B_0) 7 - filter("YB_"."I_IS_DELETED"=:SYS_B_1) 8 - ACCESS("YB_"."R_OBJECT_ID"=:SYS_B_0) 9 - filter("YB_"."I_IS_DELETED"=:SYS_B_3) 10 - ACCESS("YB_"."I_CHRONICLE_ID"="$nso_col_1") 11 - ACCESS("YB_"."R_OBJECT_ID"="HR_"."R_OBJECT_ID") 12 - filter("R_VERSION_LABEL"=:SYS_B_2) 13 - ACCESS("YB_"."R_OBJECT_ID"="R_OBJECT_ID") COLUMN Projection Information (IDENTIFIED BY operation id): ----------------------------------------------------------- 1 - (#keys=0) "YB_"."R_OBJECT_ID"[VARCHAR2,16] 2 - (#keys=0) "YB_"."R_OBJECT_ID"[VARCHAR2,16] 3 - (#keys=0) "YB_"."R_OBJECT_ID"[VARCHAR2,16] 4 - "$nso_col_1"[VARCHAR2,16] 5 - (#keys=0) "YB_"."I_CHRONICLE_ID"[VARCHAR2,16] 7 - "YB_"."I_CHRONICLE_ID"[VARCHAR2,16] 8 - "YB_".ROWID[ROWID,10] 9 - "YB_"."R_OBJECT_ID"[VARCHAR2,16] 10 - "YB_".ROWID[ROWID,10] 13 - "DM_SYSOBJECT_R".ROWID[ROWID,10] ------------------------------------------------------------------------------- |
Remark
You cannot use the parameter => value when using a procedure in SELECT statement.
I tried to generate it in html but got this strange error:
SQL> SELECT dbms_sqltune.report_tuning_task('Tune_0t5fw0gtf0665', 'HTML', 'ALL') FROM dual; DBMS_SQLTUNE.REPORT_TUNING_TAS ------------------------------------------------------------------------------------------------------------------------------------------------ Error: report TYPE 'HTML' IS NOT supported ------------------------------------------------------------------------------- |
You can also generate the apply script to apply the suggested optimization:
SQL> SELECT dbms_sqltune.script_tuning_task('Tune_0t5fw0gtf0665', 'ALL') FROM dual; DBMS_SQLTUNE.SCRIPT_TUNING_TAS ------------------------------------------------------------------------------------------------------------------------------------------------ ----------------------------------------------------------------- -- Script generated by DBMS_SQLTUNE package, advisor framework -- -- Use this script to implement some of the recommendations -- -- made by the SQL tuning advisor. -- -- -- -- NOTE: this script may need to be edited for your system -- -- (index names, privileges, etc) before it is executed. -- ----------------------------------------------------------------- EXECUTE dbms_sqltune.accept_sql_profile(task_name => 'Tune_0t5fw0gtf0665', REPLACE => TRUE); |
If you are not satisfied with the result you can drop the tuning task with:
SQL> EXECUTE dbms_sqltune.drop_tuning_task('Tune_0t5fw0gtf0665'); PL/SQL PROCEDURE successfully completed. |
DBMS_SQLTUNE result
Accept the profile generated by the tuning task using:
SQL> EXECUTE dbms_sqltune.accept_sql_profile(task_name => 'Tune_0t5fw0gtf0665', description => 'Tuning test for sql_id 0t5fw0gtf0665'); PL/SQL PROCEDURE successfully completed. |
You now see it appearing in dictionary tables:
SQL> SELECT name, created, description, status FROM dba_sql_profiles; NAME CREATED DESCRIPTION STATUS ------------------------------ -------------------- ---------------------------------------- -------- SYS_SQLPROF_014cac2bc5504000 28-sep-2011 17:37:36 Tuning test FOR sql_id 0t5fw0gtf0665 ENABLED |
After a period of time (currently executed statement are not affected) you can check improvement with something like:/
SQL> col CPU_TIME FOR 9999999999999999 SQL> col ELAPSED_TIME FOR 9999999999999999 SQL> col USER_IO_WAIT_TIME FOR 9999999999999999 SQL> SELECT child_number, disk_reads, buffer_gets, user_io_wait_time, optimizer_mode, optimizer_cost, plan_hash_value, cpu_time, elapsed_time FROM v$sql WHERE sql_id='0t5fw0gtf0665' ORDER BY child_number; CHILD_NUMBER DISK_READS BUFFER_GETS USER_IO_WAIT_TIME OPTIMIZER_ OPTIMIZER_COST PLAN_HASH_VALUE CPU_TIME ELAPSED_TIME ------------ ---------- ----------- ----------------- ---------- -------------- --------------- ----------------- ----------------- 0 246529611 1417057982 17226193373 FIRST_ROWS 231043 554605205 58844671977 75733845890 1 205018990 4092335906 13011672325 FIRST_ROWS 231542 554605205 49010342543 59800297462 2 3197 146402 2776854 ALL_ROWS 6 3149505603 3414988 5244194 |
If you really come too late onto database you may use the following:
SQL> SET pages 50 SQL> col begin_interval_time FOR a30 SQL> col sql_profile FOR a30 SQL> SET lines 200 SQL> col cpu_time_total FOR 9999999999999999 SQL> col elapsed_time_total FOR 9999999999999999 SQL> col iowait_total FOR 9999999999999999 SQL> SELECT b.begin_interval_time, a.plan_hash_value, a.optimizer_mode, a.sql_profile, a.disk_reads_total, a.buffer_gets_total, a.cpu_time_total, a.elapsed_time_total, a.iowait_total FROM dba_hist_sqlstat a, dba_hist_snapshot b WHERE sql_id='0t5fw0gtf0665' AND a.snap_id=b.snap_id AND b.begin_interval_time > SYSDATE -2 ORDER BY a.snap_id DESC; BEGIN_INTERVAL_TIME PLAN_HASH_VALUE OPTIMIZER_ SQL_PROFILE DISK_READS_TOTAL BUFFER_GETS_TOTAL CPU_TIME_TOTAL ELAPSED_TIME_TOTAL IOWAIT_TOTAL ------------------------------ --------------- ---------- ------------------------------ ---------------- ----------------- ----------------- ------------------ ----------------- 28-SEP-11 07.00.56.588 PM 554605205 FIRST_ROWS 451548601 1214426592 107855014520 135534143352 30237865698 28-SEP-11 07.00.56.588 PM 3149505603 ALL_ROWS SYS_SQLPROF_014cac2bc5504000 15438 819026 19655352 34112021 19106454 28-SEP-11 06.00.41.537 PM 3149505603 ALL_ROWS SYS_SQLPROF_014cac2bc5504000 9377 433321 11532244 19312691 10478807 28-SEP-11 06.00.41.537 PM 554605205 FIRST_ROWS 451548601 1214426592 107855014520 135534143352 30237865698 28-SEP-11 05.00.26.401 PM 554605205 FIRST_ROWS 451548601 1214426592 107855014520 135534143352 30237865698 28-SEP-11 05.00.26.401 PM 3149505603 ALL_ROWS SYS_SQLPROF_014cac2bc5504000 3197 146402 3414988 5244194 2776854 28-SEP-11 04.00.10.748 PM 554605205 FIRST_ROWS 443356437 877943539 105977430745 133422564399 29800999584 28-SEP-11 03.00.55.746 PM 554605205 FIRST_ROWS 431736486 399423126 103225285835 129997723182 29023692158 28-SEP-11 02.00.40.226 PM 554605205 FIRST_ROWS 420094114 4215593685 100472892252 126642703576 28270668444 28-SEP-11 01.00.25.248 PM 554605205 FIRST_ROWS 407785407 3715283563 97601066578 123202872172 27521628792 28-SEP-11 12.00.08.997 PM 554605205 FIRST_ROWS 395345924 3202455406 94675486249 119775180162 26832126929 28-SEP-11 11.00.53.434 AM 554605205 FIRST_ROWS 383815086 2743091408 91977622082 116312811852 26069450643 12 ROWS selected. |
Let’s compare the explain plans:
SQL> col PLAN FOR a180 SQL> SET lines 180 SQL> SET pagesize 100 SQL> SELECT RPAD('(' || p.ID || ' ' || NVL(p.parent_id,'0') || ')',8) || '|' || RPAD(LPAD (' ', 2*p.DEPTH) || p.operation || ' ' || p.options,40,'.') || NVL2(p.object_owner||p.object_name, '(' || p.object_owner|| '.' || p.object_name || ') ', '') || 'Cost:' || p.COST || ' ' || NVL2(p.bytes||p.CARDINALITY,'(' || p.bytes || ' bytes, ' || p.CARDINALITY || ' rows)','') || ' ' || NVL2(p.partition_id || p.partition_start || p.partition_stop,'PId:' || p.partition_id || ' PStart:' || p.partition_start || ' PStop:' || p.partition_stop,'') || 'io cost=' || p.io_cost || ',cpu_cost=' || p.cpu_cost AS PLAN FROM dba_hist_sql_plan p WHERE p.sql_id='0t5fw0gtf0665' AND plan_hash_value='3149505603' ORDER BY p.id, p.parent_id; PLAN ------------------------------------------------------------------------------------------------------------------------------------------------ (0 0) |SELECT STATEMENT .......................COST:6 io COST=,cpu_cost= (1 0) | NESTED LOOPS SEMI.....................COST:6 (83 bytes, 1 ROWS) io COST=5,cpu_cost=1370140 (2 1) | NESTED LOOPS .......................COST:5 (252 bytes, 4 ROWS) io COST=4,cpu_cost=1366836 (3 2) | NESTED LOOPS .....................COST:4 (230 bytes, 5 ROWS) io COST=3,cpu_cost=1366574 (4 3) | VIEW ...........................(.VW_NSO_1) COST:2 (10 bytes, 1 ROWS) io COST=2,cpu_cost=1222 (5 4) | NESTED LOOPS .................COST:2 (53 bytes, 1 ROWS) io COST=2,cpu_cost=1222 (6 5) | INDEX UNIQUE SCAN...........(WCMS.D_1F00342380000900) COST:1 (17 bytes, 1 ROWS) io COST=1,cpu_cost=765 (7 5) | TABLE ACCESS BY INDEX ROWID.(WCMS.DM_SYSOBJECT_S) COST:1 (36 bytes, 1 ROWS) io COST=1,cpu_cost=458 (8 7) | INDEX UNIQUE SCAN.........(WCMS.D_1F0034238000010A) COST:1 ( bytes, 1 ROWS) io COST=1,cpu_cost=53 (9 3) | TABLE ACCESS BY INDEX ROWID.....(WCMS.DM_SYSOBJECT_S) COST:1 (70308 bytes, 1953 ROWS) io COST=1,cpu_cost=1346 (10 9) | INDEX RANGE SCAN..............(WCMS.D_1F0034238000000E) COST:1 ( bytes, 4 ROWS) io COST=1,cpu_cost=83 (11 2) | INDEX UNIQUE SCAN.................(WCMS.D_1F00342380000900) COST:1 (17 bytes, 1 ROWS) io COST=1,cpu_cost=53 (12 1) | TABLE ACCESS BY INDEX ROWID.........(WCMS.DM_SYSOBJECT_R) COST:1 (376520 bytes, 18826 ROWS) io COST=1,cpu_cost=826 (13 12) | INDEX RANGE SCAN..................(WCMS.D_1F0034238000010B) COST:1 ( bytes, 3 ROWS) io COST=1,cpu_cost=396 14 ROWS selected. |
If you come not too late to check result you can use V$SQL_PLAN_STATISTICS_ALL for cursor cache information but strangely the plan is a bit different (upper SELECT statement missing):
PLAN ------------------------------------------------------------------------------------------------------------------------------------------------ (1 0) | NESTED LOOPS SEMI.....................COST:6 (83 bytes, 1 ROWS) io COST=5,cpu_cost=1370140 (2 1) | NESTED LOOPS .......................COST:5 (252 bytes, 4 ROWS) io COST=4,cpu_cost=1366836 (3 2) | NESTED LOOPS .....................COST:4 (230 bytes, 5 ROWS) io COST=3,cpu_cost=1366574 (4 3) | VIEW ...........................(.VW_NSO_1) COST:2 (10 bytes, 1 ROWS) io COST=2,cpu_cost=1222 (5 4) | NESTED LOOPS .................COST:2 (53 bytes, 1 ROWS) io COST=2,cpu_cost=1222 (6 5) | INDEX UNIQUE SCAN...........(WCMS.D_1F00342380000900) COST:1 (17 bytes, 1 ROWS) io COST=1,cpu_cost=765 (7 5) | TABLE ACCESS BY INDEX ROWID.(WCMS.DM_SYSOBJECT_S) COST:1 (36 bytes, 1 ROWS) io COST=1,cpu_cost=458 (8 7) | INDEX UNIQUE SCAN.........(WCMS.D_1F0034238000010A) COST:1 ( bytes, 1 ROWS) io COST=1,cpu_cost=53 (9 3) | TABLE ACCESS BY INDEX ROWID.....(WCMS.DM_SYSOBJECT_S) COST:1 (70308 bytes, 1953 ROWS) io COST=1,cpu_cost=1346 (10 9) | INDEX RANGE SCAN..............(WCMS.D_1F0034238000000E) COST:1 ( bytes, 4 ROWS) io COST=1,cpu_cost=83 (11 2) | INDEX UNIQUE SCAN.................(WCMS.D_1F00342380000900) COST:1 (17 bytes, 1 ROWS) io COST=1,cpu_cost=53 (12 1) | TABLE ACCESS BY INDEX ROWID.........(WCMS.DM_SYSOBJECT_R) COST:1 (376520 bytes, 18826 ROWS) io COST=1,cpu_cost=826 (13 12) | INDEX RANGE SCAN..................(WCMS.D_1F0034238000010B) COST:1 ( bytes, 3 ROWS) io COST=1,cpu_cost=396 13 ROWS selected. |
Outcome of this example it quite obvious:
- I/O cost divided by 46000.
- CPU cost divided by 1180.
- Execution time from 16 hours to 5 seconds (from Oracle system tables). Means execution time divided by more than 10000.
With Grid Control
Obviously all this would have been possible with Grid Control in few mouse clicks but what a pleasure to do it in PL/SQL isn’t it ? We may anyway use Grid Control to see the performance improvement right after the SQL Profile activation:
Grid Control can also be used to display both explain plan in a graphical manner on one screen:
Robert says:
Thanks, your example resolved a bug issue with 11.2 OEM, that cannot deploy a parallel execution plan.
Yannick Jaquier says:
Welcome !