Dion Cho – Oracle Performance Storyteller

We are natural born scientists

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.

About these ads

Written by Dion Cho

January 28, 2009 at 6:04 am

Posted in Optimizer

Tagged with

2 Responses

Subscribe to comments with RSS.

  1. Nice
    One thing that bugs me is trending sql and going back to a possibly previous execution plan using the outline info is tough if the good plan never showed up in AWR. How do I find the good plan?
    This sounds like a possible way to address the issue and track “good” queries so the info is in AWR if they go bad.

    Kyle Hailey

    May 30, 2010 at 2:48 pm

  2. Just thinking today that once a SQL hits the top SQL collected by AWR, then at that point it would good to collect all execution plans that SQL and the other children of that SQL. Wondering if by chance AWR already collects all the plans and stats for all child cursors or just the ones that reach the limit. Will have to check. If it’s just the child cursor that reach the limit then it would be good to also include the other children.
    More stuff to research!

    Kyle Hailey

    May 31, 2010 at 6:23 pm


Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

Join 58 other followers

%d bloggers like this: