Posts Tagged ‘runstats’
Do you diff? – The most powerful way to detect performance problem.
One of my favorite tools to troubleshoot Oracle performance problem is DIFF.
The principle is simple
Compare the good one with the bad one. Then you will figure out the problem.
The ability to DIFF is the key philosophy of the famoust package from Tom Kyte called runstats.
The good news is that Oracle applied this principle to AWR as of 10gR2.
- dbms_workload_repository.awr_diff_report_text/html function generates DIFF report between snapshots.
- dbms_workload_repository.awr_sql_report_text/html function generates the reports for multiple execution plans of given SQL.
You can also play with $ORACLE_HOME/rdbms/admin/awrddrpi.sql, awrsqrpi.sql scripts provided by Oracle.
Following is a very simple test case to demonstrate power of these new functions.
UKJA@ukja102> select * from v$version; BANNER ---------------------------------------------------------------- Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Prod PL/SQL Release 10.2.0.1.0 - Production CORE 10.2.0.1.0 Production TNS for 32-bit Windows: Version 10.2.0.1.0 - Production NLSRTL Version 10.2.0.1.0 - Production 5 rows selected. Elapsed: 00:00:00.03 UKJA@ukja102> UKJA@ukja102> drop table t1 purge; Table dropped. Elapsed: 00:00:00.48 UKJA@ukja102> UKJA@ukja102> create table t1(c1, c2) 2 as 3 select level, level 4 from dual 5 connect by level <= 100000 6 ; Table created. Elapsed: 00:00:01.79 UKJA@ukja102> UKJA@ukja102> @gather t1; UKJA@ukja102> exec dbms_stats.gather_table_stats(user, '&1', no_invalidate=>false); PL/SQL procedure successfully completed. Elapsed: 00:00:02.10 UKJA@ukja102> UKJA@ukja102> UKJA@ukja102> var dbid number; UKJA@ukja102> var inid number; UKJA@ukja102> UKJA@ukja102> var bid1 number; UKJA@ukja102> var eid1 number; UKJA@ukja102> var bid2 number; UKJA@ukja102> var eid2 number; UKJA@ukja102> UKJA@ukja102> begin 2 select dbid into :dbid from v$database; 3 select instance_number into :inid from v$instance; 4 end; 5 / PL/SQL procedure successfully completed. Elapsed: 00:00:00.10 UKJA@ukja102> UKJA@ukja102> print dbid DBID ---------- 1415318383 UKJA@ukja102> print inid INID ---------- 1 UKJA@ukja102> UKJA@ukja102> UKJA@ukja102> exec :bid1 := dbms_workload_repository.create_snapshot; PL/SQL procedure successfully completed. Elapsed: 00:00:02.40 UKJA@ukja102> UKJA@ukja102> select /*+ ordered use_nl(x y) */ 2 count(*) 3 from 4 (select level from dual connect by level <= 100) x, 5 (select /*+ no_unnest */ * from t1 where c1 between 1 and 10) y 6 ; COUNT(*) ---------- 1000 1 row selected. Elapsed: 00:00:00.62 UKJA@ukja102> UKJA@ukja102> exec :eid1 := dbms_workload_repository.create_snapshot; PL/SQL procedure successfully completed. Elapsed: 00:00:00.90 UKJA@ukja102> UKJA@ukja102> create index t1_n1 on t1(c1); Index created. Elapsed: 00:00:01.79 UKJA@ukja102> UKJA@ukja102> exec :bid2 := dbms_workload_repository.create_snapshot; PL/SQL procedure successfully completed. Elapsed: 00:00:00.89 UKJA@ukja102> UKJA@ukja102> select /*+ ordered use_nl(x y) */ 2 count(*) 3 from 4 (select level from dual connect by level <= 100) x, 5 (select /*+ no_unnest */ * from t1 where c1 between 1 and 10) y 6 ; COUNT(*) ---------- 1000 1 row selected. Elapsed: 00:00:00.03 UKJA@ukja102> UKJA@ukja102> exec :eid2 := dbms_workload_repository.create_snapshot; PL/SQL procedure successfully completed. Elapsed: 00:00:00.82 UKJA@ukja102>
The SQL report is as following. You can compare the 2 different execution plans and their workloads without any difficulty.
UKJA@ukja102> select * from 2 table(dbms_workload_repository.awr_sql_report_text( 3 :dbid, :inid, :bid1, :eid2, :sql_id 4 )) 5 ; OUTPUT ------------------------------------------------------------------------------------------ WORKLOAD REPOSITORY SQL Report Snapshot Period Summary DB Name DB Id Instance Inst Num Release RAC Host ------------ ----------- ------------ -------- ----------- --- ------------ UKJA10 1415318383 ukja10 1 10.2.0.1.0 NO UKJA Snap Id Snap Time Sessions Curs/Sess --------- ------------------- -------- --------- Begin Snap: 5165 24-Feb-09 17:34:56 17 5.8 End Snap: 5168 24-Feb-09 17:35:02 17 5.8 Elapsed: 0.11 (mins) DB Time: 0.11 (mins) SQL Summary DB/Inst: UKJA10/ukja10 Snaps: 5165-5168 Elapsed SQL Id Time (ms) ------------- ---------- f92v9t2zsx1sz 648 Module: SQL*Plus select /*+ ordered use_nl(x y) */ count(*) from (select level from dual conn ect by level <= 100) x, (select /*+ no_unnest */ * from t1 where c1 between 1 and 10) y ------------------------------------------------------------- SQL ID: f92v9t2zsx1sz DB/Inst: UKJA10/ukja10 Snaps: 5165-5168 -> 1st Capture and Last Capture Snap IDs refer to Snapshot IDs witin the snapshot range -> select /*+ ordered use_nl(x y) */ count(*) from (select level from... Plan Hash Total Elapsed 1st Capture Last Capture # Value Time(ms) Executions Snap ID Snap ID --- ---------------- ---------------- ------------- ------------- -------------- 1 2884841797 621 1 5166 5166 2 1704637568 27 1 5168 5168 ------------------------------------------------------------- Plan 1(PHV: 2884841797) ----------------------- Plan Statistics DB/Inst: UKJA10/ukja10 Snaps: 5165-5168 -> % Total DB Time is the Elapsed Time of the SQL statement divided into the Total Database Time multiplied by 100 Stat Name Statement Per Execution % Snap ---------------------------------------- ---------- -------------- ------- Elapsed Time (ms) 621 620.5 9.3 CPU Time (ms) 596 595.7 13.9 Executions 1 N/A N/A Buffer Gets 20,900 20,900.0 53.6 Disk Reads 0 0.0 0.0 Parse Calls 1 1.0 0.1 Rows 1 1.0 N/A User I/O Wait Time (ms) 0 N/A N/A Cluster Wait Time (ms) 0 N/A N/A Application Wait Time (ms) 0 N/A N/A Concurrency Wait Time (ms) 0 N/A N/A Invalidations 0 N/A N/A Version Count 2 N/A N/A Sharable Mem(KB) 14 N/A N/A ------------------------------------------------------------- Execution Plan ----------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | ----------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | | | 61 (100)| | | 1 | SORT AGGREGATE | | 1 | 5 | | | | 2 | NESTED LOOPS | | 1 | 5 | 61 (5)| 00:00:01 | | 3 | VIEW | | 1 | | 2 (0)| 00:00:01 | | 4 | FILTER | | | | | | | 5 | CONNECT BY WITHOUT FILTERING| | | | | | | 6 | FAST DUAL | | 1 | | 2 (0)| 00:00:01 | | 7 | TABLE ACCESS FULL | T1 | 1 | 5 | 59 (6)| 00:00:01 | ----------------------------------------------------------------------------------------- Plan 2(PHV: 1704637568) ----------------------- Plan Statistics DB/Inst: UKJA10/ukja10 Snaps: 5165-5168 -> % Total DB Time is the Elapsed Time of the SQL statement divided into the Total Database Time multiplied by 100 Stat Name Statement Per Execution % Snap ---------------------------------------- ---------- -------------- ------- Elapsed Time (ms) 27 27.3 0.4 CPU Time (ms) 2 1.7 0.0 Executions 1 N/A N/A Buffer Gets 102 102.0 0.3 Disk Reads 1 1.0 2.1 OUTPUT ------------------------------------------------------------------------------------------ Parse Calls 1 1.0 0.1 Rows 1 1.0 N/A User I/O Wait Time (ms) 10 N/A N/A Cluster Wait Time (ms) 0 N/A N/A Application Wait Time (ms) 0 N/A N/A Concurrency Wait Time (ms) 0 N/A N/A Invalidations 0 N/A N/A Version Count 2 N/A N/A Sharable Mem(KB) 14 N/A N/A ------------------------------------------------------------- Execution Plan ------------------------------------------------------------------------------------------ | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | ------------------------------------------------------------------------------------------ | 0 | SELECT STATEMENT | | | | 3 (100)| | | 1 | SORT AGGREGATE | | 1 | 5 | | | | 2 | NESTED LOOPS | | 1 | 5 | 3 (0)| 00:00:01 | | 3 | VIEW | | 1 | | 2 (0)| 00:00:01 | | 4 | FILTER | | | | | | | 5 | CONNECT BY WITHOUT FILTERING| | | | | | | 6 | FAST DUAL | | 1 | | 2 (0)| 00:00:01 | | 7 | INDEX RANGE SCAN | T1_N1 | 1 | 5 | 1 (0)| 00:00:01 | ------------------------------------------------------------------------------------------ Full SQL Text SQL ID SQL Text ------------ ----------------------------------------------------------------- f92v9t2zsx1s select /*+ ordered use_nl(x y) */ count(*) from (select level fro om dual connect by level <= 100) x, (select /*+ no_unnest */ * fr om t1 where c1 between 1 and 10) y 133 rows selected.
AWR comparison report is quite long that let me show only part of it. The point is that now you have the most comprehensive comparison report ever existed.
UKJA@ukja102>
UKJA@ukja102> select * from
2 table(dbms_workload_repository.awr_diff_report_text(
3 :dbid, :inid, :bid1, :eid1, :dbid, :inid, :bid2, :eid2
4 ))
5 ;
OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
WORKLOAD REPOSITORY COMPARE PERIOD REPORT
Snapshot Set DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
First (1st) 1415318383 ukja10 1 10.2.0.1.0 NO UKJA
Second (2nd) 1415318383 ukja10 1 10.2.0.1.0 NO UKJA
Snapshot Set Begin Snap Id Begin Snap Time End Snap Id End Snap Time Elapsed Time (min) DB Time (min) Avg Active Users
------------ -------------- ------------------ ------------ ------------------ -------------------------- -------------------------- --------------------------
1st 5165 24-Feb-09 17:34:56 5166 24-Feb-09 17:34:59 0.05 0.05 0.99
2nd 5167 24-Feb-09 17:35:01 5168 24-Feb-09 17:35:02 0.02 0.02 0.30
Configuration Comparison
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 1st 2nd %Diff 1st 2nd %Diff
----------- ----------- ------ ---------- ---------- ------
Buffer Cache: 52M 52M 0.00 SGA Target: 0 0 0.00
Std Block Size: 8K 8K 0.00 PGA Aggregate Target: 1,049M 1,049M 0.00
Shared Pool Size: 80M 80M 0.00 Undo Management: AUTO AUTO
Log Buffer: 11,064K 11,064K 0.00
~~~~~~~~~~~~~~~~~~~ 1st Per Sec 2nd Per Sec %Diff 1st Per Txn 2nd Per Txn %Diff
--------------- --------------- ------ --------------- --------------- ------
Redo size: 216,287.50 502,545.84 132.35 82,378.50 58,923.50 -28.47
Logical reads: 10,582.21 2,846.48 -73.10 4,030.50 333.75 -91.72
Block changes: 547.42 1,078.89 97.09 208.50 208.50 0.00
Physical reads: 5.25 28.78 448.19 2.00 3.38 69.00
Physical writes: 1.64 0.00 -100.00 0.63 0.00 -100.00
User calls: 1.64 5.33 225.00 0.63 0.63 0.00
Parses: 169.35 135.39 -20.05 64.50 15.88 -75.38
Hard parses: 43.32 2.13 -95.08 16.50 0.25 -98.48
Sorts: 146.70 46.91 -68.02 55.88 5.50 -90.16
Logons: 0.00 0.00 0.00 0.00 0.00 0.00
Executes: 622.25 221.75 -64.36 237.00 26.00 -89.03
Transactions: 2.63 8.53 224.33
First Second Diff
--------------- --------------- ------
% Blocks changed per Read: 5.17 37.90 32.73
Recursive Call %: 99.98 99.33 -0.65
Rollback per transaction %: 0.00 0.00 0.00
Rows per Sort: 20.98 123.50 102.52
Avg Length of Calls (sec): 0.61 0.61 0.00
Top 5 Timed Events
~~~~~~~~~~~~~~~~~~
--------------------------------------- 1st --------------------------------------- --------------------------------------- 2nd ---------------------------------------
Event Waits Time (s) %DB Time Wait Class Event Waits Time (s) %DB Time Wait Class
------------------------------ ------------ ------------ ------------ ------------- ------------------------------ ------------ ------------ ------------ -------------
CPU time 2.3 74.37 db file sequential read 26 0.3 37.87 User I/O
db file sequential read 39 0.5 15.09 User I/O CPU time 0.3 28.26
control file sequential read 53 0.1 4.30 System I/O control file sequential read 53 0.1 10.40 System I/O
log file parallel write 19 0.0 0.20 System I/O log file parallel write 11 0.0 0.58 System I/O
*control file parallel write 1 0.0 0.03 System I/O *SQL*Net message to client 3 0.0 0.00 Network
------------------------------ ------------ ------------ ------------ ------------- ------------------------------ ------------ ------------ ------------ -------------
-SQL*Net message to client 3 0.0 0.00 Network
....
init.ora Parameters First DB/Inst: UKJA10/ukja10 Snaps: 5165-5166 (Elapsed time: 3.047 sec DB Time: 3.03 sec), Second DB/Inst: UKJA10/ukja10 Snaps: 5167-5168 (Elapsed time: .938 sec DB Time: .92
sec)
-> Only parameters that are set differently are shown for the second period.
Parameter Name 1st End Snap Value 2nd End Snap Value (if different
---------------------------------------------------------------- -------------------------------- --------------------------------
O7_DICTIONARY_ACCESSIBILITY FALSE
__db_cache_size 54525952
__dg_broker_service_names UKJA10_XPT
__java_pool_size 4194304
__large_pool_size 4194304
...
These whole comparison functionalities are quite helpful when dealing with performance degradation over time.
Don’t forget to DIFF!
Dion Cho - Oracle Performance Storyteller 