Dion Cho – Oracle Performance Storyteller

We are natural born scientists

Posts Tagged ‘runstats

Do you diff? – The most powerful way to detect performance problem.

with one comment

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!

Written by Dion Cho

February 24, 2009 at 9:01 am

Follow

Get every new post delivered to your Inbox.

Join 61 other followers