Dion Cho – Oracle Performance Storyteller

We are natural born scientists

Posts Tagged ‘colored sql

Colored SQL – innovative way to capture your own top SQLs

with 2 comments

In previous post,  I discussed how Oracle 10g captures the top SQLs.

But there is one serious problem. For instance, let’s assume that I have following request.

I know that one of my queries does not belong to top SQL, but I really like to track my query historically.

On 10g, this is not a simple request. We might have to increase the threshold(default is 30 per SQL criteria) to a very high number, which would make the overwhole snapshot performance degraded.

For this reason, Oracle 11g added new functionally called colored sql. If a specific query is colored, Oracle would capture it  even when it is a quite trivial one.

Following is a simple test case to demonstrate how colored SQL works.

Works only on 11g+.

UKJA@ukja116>
UKJA@ukja116> select * from v$version;

BANNER                                                                         
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.1.0.6.0 - Production         
PL/SQL Release 11.1.0.6.0 - Production                                         
CORE    11.1.0.6.0    Production                                                     
TNS for 32-bit Windows: Version 11.1.0.6.0 - Production                        
NLSRTL Version 11.1.0.6.0 - Production

Let’s create very simple objects including table and index.

UKJA@ukja116>
UKJA@ukja116> drop table t1 purge;

Table dropped.

Elapsed: 00:00:00.04
UKJA@ukja116>
UKJA@ukja116> create table t1(c1, c2)
  2  as
  3  select level, level
  4  from dual
  5  connect by level <= 1000
  6  ;

Table created.

Elapsed: 00:00:00.12
UKJA@ukja116>
UKJA@ukja116> create index t1_n1 on t1(c1);

Index created.

Elapsed: 00:00:00.01
UKJA@ukja116>
UKJA@ukja116> @gather t1
UKJA@ukja116> exec dbms_stats.gather_table_stats(user, '&1', no_invalidate=>false);

PL/SQL procedure successfully completed.
Elapsed: 00:00:00.12

This is a really trivial query, but I like to capture it into AWR repository.

UKJA@ukja116> select /* trivial */ * from t1 where c1 = 1;

        C1         C2                                                          
---------- ----------                                                          
         1          1                                                           

Elapsed: 00:00:00.00
UKJA@ukja116>
UKJA@ukja116> col sql_id new_value v_sql_id
UKJA@ukja116> col dbid new_value v_db_id
UKJA@ukja116> col instance_number new_value v_inst_num
UKJA@ukja116> var b_snap_id number;
UKJA@ukja116> var e_snap_id number;
UKJA@ukja116>
UKJA@ukja116> select dbid, instance_number
  2  from dba_hist_snapshot
  3  where rownum = 1;

      DBID INSTANCE_NUMBER                                                     
---------- ---------------                                                     
1376656966               1                                                      

Elapsed: 00:00:00.00
UKJA@ukja116>
UKJA@ukja116> select sql_id from v$sql where sql_text like 'select /* trivial */ * from t1 where c1 = 1%';

SQL_ID                                                                         
---------------------------------------                                        
7906d3063ma9f                                                                   

Elapsed: 00:00:00.03
UKJA@ukja116>
UKJA@ukja116> exec dbms_workload_repository.remove_colored_sql('&v_sql_id');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
UKJA@ukja116>
UKJA@ukja116> commit;

Commit complete.

Elapsed: 00:00:00.00
UKJA@ukja116>
UKJA@ukja116>
UKJA@ukja116> exec :b_snap_id := dbms_workload_repository.create_snapshot;

PL/SQL procedure successfully completed.

Elapsed: 00:00:01.37
UKJA@ukja116>
UKJA@ukja116> select /* trivial */ * from t1 where c1 = 1;

        C1         C2                                                          
---------- ----------                                                          
         1          1                                                           

Elapsed: 00:00:00.00
UKJA@ukja116>
UKJA@ukja116> exec :e_snap_id := dbms_workload_repository.create_snapshot;

PL/SQL procedure successfully completed.

Elapsed: 00:00:01.60

As the dbms_workload_repository.awr_sql_report_text function cleary shows, the query was not captured, which is quite natural for trivial SQL.

UKJA@ukja116>
UKJA@ukja116> select * from table(dbms_workload_repository.awr_sql_report_text
  (&v_db_id, &v_inst_num, :b_snap_id, :e_snap_id, '&v_sql_id'));

OUTPUT                                                                         
--------------------------------------------------------------------------------
WORKLOAD REPOSITORY SQL Report                                                  

Snapshot Period Summary                                                         

DB Name         DB Id    Instance     Inst Num Startup Time    Release     RAC 
------------ ----------- ------------ -------- --------------- ----------- --- 
UKJA11        1376656966 ukja11              1 25-Jan-09 17:54 11.1.0.6.0  NO   

              Snap Id      Snap Time      Sessions Curs/Sess                   
            --------- ------------------- -------- ---------                   
Begin Snap:      3396 28-Jan-09 14:37:23        23       1.8                   
  End Snap:      3397 28-Jan-09 14:37:25        23       1.8                   
   Elapsed:                0.02 (mins)                                         
   DB Time:                0.02 (mins)                                          

SQL Summary                           DB/Inst: UKJA11/ukja11  Snaps: 3396-3397  

                  No data exists for this section of the report.               
          -------------------------------------------------------------         

SQL ID: 7906d3063ma9f                 DB/Inst: UKJA11/ukja11  Snaps: 3396-3397  

                  No data exists for this section of the report.               
          -------------------------------------------------------------         

Full SQL Text                                                                   

                  No data exists for this section of the report.                

28 rows selected.

Elapsed: 00:00:00.10

Now we COLOR the sql simply by calling dbms_workload_repository.add_colored_sql.

UKJA@ukja116>
UKJA@ukja116> select /* trivial */ * from t1 where c1 = 1;

        C1         C2                                                          
---------- ----------                                                          
         1          1                                                           

Elapsed: 00:00:00.00

UKJA@ukja116> exec dbms_workload_repository.add_colored_sql('&v_sql_id');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
UKJA@ukja116>
UKJA@ukja116> commit;

Commit complete.

Elapsed: 00:00:00.00
UKJA@ukja116>
UKJA@ukja116>
UKJA@ukja116> exec :b_snap_id := dbms_workload_repository.create_snapshot;

PL/SQL procedure successfully completed.

Elapsed: 00:00:01.17
UKJA@ukja116>
UKJA@ukja116> select /* trivial */ * from t1 where c1 = 1;

        C1         C2                                                          
---------- ----------                                                          
         1          1                                                           

Elapsed: 00:00:00.00
UKJA@ukja116>
UKJA@ukja116> exec :e_snap_id := dbms_workload_repository.create_snapshot;

PL/SQL procedure successfully completed.

Elapsed: 00:00:01.14

Now Oracle captured my trivial query just because it was COLORED.

UKJA@ukja116>
UKJA@ukja116> select * from table(dbms_workload_repository.awr_sql_report_text
(&v_db_id, &v_inst_num, :b_snap_id, :e_snap_id, '&v_sql_id'));

OUTPUT                                                                         
--------------------------------------------------------------------------------
WORKLOAD REPOSITORY SQL Report                                                  

Snapshot Period Summary                                                         

DB Name         DB Id    Instance     Inst Num Startup Time    Release     RAC 
------------ ----------- ------------ -------- --------------- ----------- --- 
UKJA11        1376656966 ukja11              1 25-Jan-09 17:54 11.1.0.6.0  NO   

              Snap Id      Snap Time      Sessions Curs/Sess                   
            --------- ------------------- -------- ---------                   
Begin Snap:      3398 28-Jan-09 14:37:26        23       1.8                   
  End Snap:      3399 28-Jan-09 14:37:28        23       1.8                   
   Elapsed:                0.02 (mins)                                         
   DB Time:                0.02 (mins)                                          

SQL Summary                           DB/Inst: UKJA11/ukja11  Snaps: 3398-3399  

                Elapsed                                                        
   SQL Id      Time (ms)                                                       
------------- ----------                                                       
7906d3063ma9f          0                                                       
Module: SQL*Plus                                                               
select /* trivial */ * from t1 where c1 = 1                                     

          -------------------------------------------------------------         

SQL ID: 7906d3063ma9f                 DB/Inst: UKJA11/ukja11  Snaps: 3398-3399 
-> 1st Capture and Last Capture Snap IDs                                       
   refer to Snapshot IDs witin the snapshot range                              
-> select /* trivial */ * from t1 where c1 = 1                                  

    Plan Hash           Total Elapsed                 1st Capture   Last Capture
#   Value                    Time(ms)    Executions       Snap ID        Snap ID
--- ---------------- ---------------- ------------- ------------- --------------
1   1420382924                      0             1          3399           3399
          -------------------------------------------------------------         

Plan 1(PHV: 1420382924)                                                        
-----------------------                                                         

Plan Statistics                       DB/Inst: UKJA11/ukja11  Snaps: 3398-3399 
-> % 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)                                 0            0.1     0.0     
CPU Time (ms)                                     0            0.0     0.0     
Executions                                        1            N/A     N/A     
Buffer Gets                                       4            4.0     0.1     
Disk Reads                                        0            0.0     0.0     
Parse Calls                                       1            1.0     0.6     
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)                                 12            N/A     N/A     
          -------------------------------------------------------------         

Execution Plan                                                                 
--------------------------------------------------------------------------------
-----                                                                           

| Id  | Operation                   | Name  | Rows  | Bytes | Cost (%CPU)| Time
    |                                                                           

--------------------------------------------------------------------------------
-----                                                                           

|   0 | SELECT STATEMENT            |       |       |       |     2 (100)|     
    |                                                                           

|   1 |  TABLE ACCESS BY INDEX ROWID| T1    |     1 |     7 |     2   (0)| 00:00
:01 |                                                                           

|   2 |   INDEX RANGE SCAN          | T1_N1 |     1 |       |     1   (0)| 00:00
:01 |                                                                           

--------------------------------------------------------------------------------
-----                                                                           

Full SQL Text                                                                   

SQL ID       SQL Text                                                          
------------ ----------------------------------------------------------------- 
7906d3063ma9 select /* trivial */ * from t1 where c1 = 1                        

81 rows selected.

Very cool feature which would help people track the historical query performance problem.

Written by Dion Cho

January 28, 2009 at 6:04 am

Posted in Optimizer

Tagged with

Follow

Get every new post delivered to your Inbox.

Join 61 other followers