Dion Cho – Oracle Performance Storyteller

We are natural born scientists

Posts Tagged ‘sql*trace

Automating tkprof on parallel slaves

with one comment

One thing very disappointing on parallel execution is the fact that the trace files of slave sessions are scattered as different files in the background dump directory.

So I built up my own script which automates the execution of tkprof on those scattered trace files.

1. pq_trace.sql generates the series of tkprof command with the input of coordinate session id.

set heading off
set timing off
set feedback off
set verify off
set serveroutput on size 100000

spool generate_pq_tkprof.sql

define __QCID = &1

declare
  v_dir     varchar2(4000);
  v_inst    varchar2(4000);
  v_trcfile varchar2(4000);
  v_cmd     varchar2(4000);
begin
  -- get dump directory
  for v in (select banner from v$version where rownum = 1) loop
    select value into v_dir from v$parameter
        where name = 'background_dump_dest';
  end loop;
  
  -- get instance name
  select value into v_inst from v$parameter
      where name = 'instance_name';
      
  -- generate series of tkprof command
  for s in (select s.sid, p.spid, rownum-1 as server#
        from v$px_session s, v$px_process p
        where
            s.sid = p.sid
            and s.qcsid in (&__QCID)
            and s.sid <> s.qcsid) loop
      
      v_trcfile := v_dir||'\'||v_inst||'_'||'p'||lpad(to_char(s.server#),3,'0')||
              '_'||s.spid||'.trc';
      v_cmd := 'ho tkprof ' || v_trcfile || ' trc' || '_' || s.server# || '.out';
      dbms_output.put_line(v_cmd);
                 
  end loop;
end;
/

spool off
set heading on
set timing on
set feedback on
set verify on
set serveroutput off

ed generate_pq_tkprof


2. The output of pq_trace.sql script is stored as generate_pq_tkprof.sql as following:

ed generate_pq_tkprof.sql

ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p000_2792.trc trc_0.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p001_704.trc trc_1.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p002_4892.trc trc_2.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p003_2728.trc trc_3.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p004_1244.trc trc_4.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p005_2736.trc trc_5.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p006_4508.trc trc_6.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p007_2432.trc trc_7.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p008_3916.trc trc_8.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p009_656.trc trc_9.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p010_5308.trc trc_10.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p011_4880.trc trc_11.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p012_4288.trc trc_12.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p013_4528.trc trc_13.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p014_5852.trc trc_14.out
ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p015_2716.trc trc_15.out



3. Following is a simple demonstration.
# Session A (session id = 130)

alter session set tracefile_identifier = &1;

@trace_on 10046 8

select /*+ parallel(t1 8) */ count(*) from t1, t1
where rownum <= 500000
;

@trace_off



# Session B
While session A executes parallel query

 @pq_trace 130   -- 130 is id of session A



After the parallel query of session A completes.

UKJA@ukja102> @generate_pq_tkprof

TKPROF: Release 11.1.0.6.0 - Production on Thu Mar 12 16:41:06 2009

Copyright (c) 1982, 2007, Oracle.  All rights reserved.
...


UKJA@ukja102> ed trc_5.out

select /*+ parallel(t1 8) */ count(*) from t1, t1
where rownum <= 500000

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1     14.18      58.32          0         16          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2     14.18      58.32          0         16          0           0

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 61     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  SORT AGGREGATE (cr=0 pr=0 pw=0 time=0 us)
      0   COUNT STOPKEY (cr=0 pr=0 pw=0 time=0 us)
      0    PX COORDINATOR  (cr=0 pr=0 pw=0 time=0 us)
      0     PX SEND QC (RANDOM) :TQ10001 (cr=0 pr=0 pw=0 time=0 us)
 500000      COUNT STOPKEY (cr=16 pr=0 pw=0 time=52514746 us)
 500000       MERGE JOIN CARTESIAN (cr=16 pr=0 pw=0 time=32514719 us)
    345        SORT JOIN (cr=0 pr=0 pw=0 time=894433 us)
  10000         PX RECEIVE  (cr=0 pr=0 pw=0 time=701281 us)
      0          PX SEND BROADCAST :TQ10000 (cr=0 pr=0 pw=0 time=0 us)
      0           PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us)
      0            TABLE ACCESS FULL T1 (cr=0 pr=0 pw=0 time=0 us)
 500000        BUFFER SORT (cr=16 pr=0 pw=0 time=13119697 us)
   1452         PX BLOCK ITERATOR (cr=16 pr=0 pw=0 time=118476 us)
   1452          TABLE ACCESS FULL T1 (cr=16 pr=0 pw=0 time=53795 us)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PX Deq: Execution Msg                           6        0.05          0.09
  PX Deq: Table Q Normal                          3        0.09          0.09
  PX Deq Credit: send blkd                        2        0.00          0.00
  PX qref latch                                   2        0.00          0.00



These kinds of automation techniques are really time and even life savers. :)

Written by Dion Cho

March 12, 2009 at 8:00 am

Tracing user specific SQL statements

with 4 comments

Assuming following request:

I would like to trace SQL statements of specific Oracle user, not any other users.

My first choice would be the powerful end to end tracing facility of Oracle 10g.
Next one is dbms_xplan package which is not only powerful but also the most important package in Oracle.

1. End to end tracing to trace specific user.

UKJA@ukja102>  -- 1. Create logon trigger in which I give identifier to user's session                                                   
UKJA@ukja102> connect /as sysdba                                                     
Connected.                                                                           
                                                                                     
SYS@ukja10> create or replace trigger logon_trigger                                  
  2  after logon on database                                                         
  3  begin                                                                           
  4    if ora_login_user = 'UKJA' then                                               
  5      dbms_session.set_identifier('ukja');                                       
  6    end if;                                                                       
  7  end;                                                                            
  8  /                                                                               
                                                                                     
Trigger created.                                                                     
                                                                                     
SYS@ukja10> -- 2. Enable sql*trace for given client identifier                                                                       
SYS@ukja10> exec dbms_monitor.client_id_trace_enable(client_id=>'ukja', -            
>           waits=>true, binds=>true);                                               
                                                                                     
PL/SQL procedure successfully completed.                                             
                                                                                     
SYS@ukja10>  -- 3. Logon as UKJA user and execute some queries                                                                         
SYS@ukja10> connect ukja/ukja@ukja102                                                
Connected.                                                                           
                                                                                     
UKJA@ukja102> select count(*) from t1;                                               
                                                                                     
  COUNT(*)                                                                           
----------                                                                           
         0                                                                           
                                                                                     
UKJA@ukja102> connect ukja/ukja@ukja102                                              
Connected.                                                                           
                                                                                     
UKJA@ukja102> select count(*) from t1;                                               
                                                                                     
  COUNT(*)                                                                           
----------                                                                           
         0                                                                           
                                                                                     
UKJA@ukja102> connect ukja/ukja@ukja102                                              
Connected.                                                                           

UKJA@ukja102> select count(*) from t1;                                               
                                                                                     
  COUNT(*)                                                                           
----------                                                                           
         0                                                                           
                                                                                     
UKJA@ukja102> -- 4. Disable sql*trace for given client identifier                                                                      
UKJA@ukja102> connect sys /as sysdba                                                 
Connected.                                                                           
                                                                                     
SYS@ukja10> exec dbms_monitor.client_id_trace_disable(client_id=>'ukja');            
                                                                                     
PL/SQL procedure successfully completed.                                             
                                                                                     
SYS@ukja10>  -- 5. Now the most difficult part. 
Our 3 trace files are scattered in the user dump directory. We should merge it.
The fantastic trcsess tool does this for me.   
                                                                      
SYS@ukja10> col value new_value dump_dir                                             
SYS@ukja10>                                                                          
SYS@ukja10> select value from v$parameter where name = 'user_dump_dest';             
                                                                                     
VALUE                                                                                
--------------------                                                                 
C:\ORACLE\ADMIN\UKJA                                                                 
10\UDUMP                                                                             
                                                                                     
                                                                                     
SYS@ukja10> -- Merge!                                                                         
SYS@ukja10> ho trcsess output=trc1.out clientid=ukja &dump_dir\*.trc                 
                                                                                     
SYS@ukja10> -- And tkprof                                                                          
SYS@ukja10> ho tkprof trc1.out tk1.out                                               

 -- Tkprof report. The result(3 executions from different sessions) was merged successfully! 
select count(*) 
from
 t1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        3      0.00       0.00          0          0          0           0
Execute      3      0.00       0.00          0          0          0           0
Fetch        6      0.00       0.00          0          9          0           3
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       12      0.00       0.00          0          9          0           3                                                                                     



This end to end tracing is quite flexible and powerful. Love it!

2. DBMS_XPLAN.DISPLAY_CURSOR to trace specific user.

UKJA@ukja102>  -- Following simple query would capture the queries
which start with 'select /*+ gather_plan_statistics */ count(*)%' and
executed by UKJA user
UKJA@ukja102> select                                                                 
  2      cursor(select * from table(                                                 
  3          dbms_xplan.display_cursor(s.sql_id, s.child_number, 'allstats last')))  
  4  from v$sql s                                                                    
  5  where s.parsing_schema_name = 'UKJA'                                            
  6        and s.sql_text like 'select /*+ gather_plan_statistics */ count(*) %'     
  7  ;                                                                               
                                                                                     
CURSOR(SELECT*FROMTA                                                                 
--------------------                                                                 
CURSOR STATEMENT : 1                                                                 
                                                                                     
CURSOR STATEMENT : 1                                                                 
                                                                                     
PLAN_TABLE_OUTPUT                                                                    
-------------------------------------------------------------------------------------
SQL_ID  fuynj2z4vdjks, child number 0                                                
-------------------------------------                                                
select /*+ gather_plan_statistics */ count(*) from t3                                
                                                                                     
Plan hash value: 463314188                                                           
                                                                                     
-------------------------------------------------------------------------------------
| Id  | Operation          | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------
|   1 |  SORT AGGREGATE    |      |      1 |      1 |      1 |00:00:00.01 |       7 |
|   2 |   TABLE ACCESS FULL| T3   |      1 |   1000 |   1000 |00:00:00.01 |       7 |
-------------------------------------------------------------------------------------
                                                                                     
CURSOR STATEMENT : 1                                                                 
                                                                                     
CURSOR STATEMENT : 1                                                                 
                                                                                     
PLAN_TABLE_OUTPUT                                                                    
-------------------------------------------------------------------------------------
SQL_ID  5cunshnzqa8vb, child number 0                                                
-------------------------------------                                                
select /*+ gather_plan_statistics */ count(*) from t2                                
                                                                                     
Plan hash value: 3321871023                                                          
                                                                                     
-------------------------------------------------------------------------------------
| Id  | Operation          | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------
|   1 |  SORT AGGREGATE    |      |      1 |      1 |      1 |00:00:00.01 |       3 |
|   2 |   TABLE ACCESS FULL| T2   |      1 |      1 |      0 |00:00:00.01 |       3 |
-------------------------------------------------------------------------------------
                                                                                     
CURSOR STATEMENT : 1                                                                 
                                                                                     
CURSOR STATEMENT : 1                                                                 
                                                                                     
PLAN_TABLE_OUTPUT                                                                    
-------------------------------------------------------------------------------------
SQL_ID  cz662tawx6sbt, child number 0                                                
-------------------------------------                                                
select /*+ gather_plan_statistics */ count(*) from t1                                
                                                                                     
Plan hash value: 3724264953                                                          
                                                                                     
-------------------------------------------------------------------------------------
| Id  | Operation          | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------
|   1 |  SORT AGGREGATE    |      |      1 |      1 |      1 |00:00:00.01 |       3 |
|   2 |   TABLE ACCESS FULL| T1   |      1 |      1 |      0 |00:00:00.01 |       3 |
-------------------------------------------------------------------------------------
                                                                                     



Again, very easy and powerful.

Written by Dion Cho

March 10, 2009 at 6:57 am

Posted in Misc.

Tagged with , ,

Follow

Get every new post delivered to your Inbox.

Join 59 other followers