Miladin Modrakovic's Blog: Oraclue

This time I will focus only on one event sql_trace or 10046 .

Oracle 11g greatly extended options for this event.I will start with SQL_ID option.

Now I can set this event to trace only specific sql_id or few of them:

Syntax is :
alter session/system set events ‘sql_trace [sql:<sql_id>|<sql_id>] … rest of event specification ‘;

So if I would like to know what is going on only for one specific sql_id :

SQL> l
  1  select sql_id, sql_text
  2  from v$sql
  3* where sql_text = ‘select * from dual’
SQL> /

SQL_ID        SQL_TEXT
————- ———————————————————————-
a5ks9fhw2v9s1 select * from dual

SQL> alter session set events ‘sql_trace [sql:a5ks9fhw2v9s1]‘;

Session altered.

SQL> select * from dual;

D
-
X

SQL> select count(*) from dba_tables;

  COUNT(*)
———-
      2636

SQL>  alter session set events ‘sql_trace [sql:a5ks9fhw2v9s1] off’;

Session altered.
and here is output:
PARSING IN CURSOR #1 len=18 dep=0 uid=0 oct=3 lid=0 tim=1237831879652913 hv=942515969 ad=’e5f92ab0′ sqlid=’a5ks9fhw2v9s1′
select * from dual
END OF STMT
EXEC #1:c=0,e=56,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1237831879652906
FETCH #1:c=1000,e=62,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1237831879653507
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op=’RESULT CACHE  9p1ghjb9czx4w7vqtuxk5zudg6 (cr=0 pr=0 pw=0 time=0 us)’
STAT #1 id=2 cnt=0 pid=1 pos=1 obj=115 op=’TABLE ACCESS FULL DUAL (cr=0 pr=0 pw=0 time=0 us cost=2 size=2 card=1)’
FETCH #1:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1237831879653934
Although I executed select count(*) from dba_tables my trace file shows only information related to sql_id=a5ks9fhw2v9s1 .I can see sqlid in trace to be sure that’s the one.
This time I will collect trace for both sql_ids:

SQL> select sql_id, hash_value
from v$sql
where sql_text in (‘select * from dual’,'select count(*) from dba_tables’); 

SQL_ID        HASH_VALUE
————- ———-
56bs32ukywdsq 2783852310
a5ks9fhw2v9s1  942515969

SQL> l
  1  select sql_id,sql_text
  2  from v$sql
  3* where sql_text in (‘select * from dual’,'select count(*) from dba_tables’)
SQL> /

SQL_ID        SQL_TEXT
————- ——————————————————————————–
56bs32ukywdsq select count(*) from dba_tables
a5ks9fhw2v9s1 select * from dual

Note char “|” which separates sql_ids and run trace and queries:

SQL> alter session set events ‘sql_trace [sql:a5ks9fhw2v9s1|56bs32ukywdsq]‘;

Session altered.

Run my queries

SQL> select * from dual;

D
-
X

SQL> select count(*) from dba_tables;

  COUNT(*)
———-
      2636
     
     
and finally turn event off:     

SQL> alter session set events ‘sql_trace [sql:a5ks9fhw2v9s1|56bs32ukywdsq] off’;

Session altered.

 
=====================
PARSING IN CURSOR #1 len=18 dep=0 uid=0 oct=3 lid=0 tim=1237832416432899 hv=942515969 ad=’e5f92ab0′ sqlid=’a5ks9fhw2v9s1′
select * from dual
END OF STMT
EXEC #1:c=0,e=57,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1237832416432879
FETCH #1:c=0,e=64,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1237832416433545
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op=’RESULT CACHE  9p1ghjb9czx4w7vqtuxk5zudg6 (cr=0 pr=0 pw=0 time=0 us)’
STAT #1 id=2 cnt=0 pid=1 pos=1 obj=115 op=’TABLE ACCESS FULL DUAL (cr=0 pr=0 pw=0 time=0 us cost=2 size=2 card=1)’
FETCH #1:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1237832416433900
…….
=====================
PARSING IN CURSOR #1 len=31 dep=0 uid=0 oct=3 lid=0 tim=1237832421115866 hv=2783852310 ad=’110353330′ sqlid=’56bs32ukywdsq’
select count(*) from dba_tables
END OF STMT
EXEC #1:c=0,e=165,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1237832421115859
FETCH #1:c=91986,e=99570,p=0,cr=2802,cu=0,mis=0,r=1,dep=0,og=1,tim=1237832421215563
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op=’SORT AGGREGATE (cr=2802 pr=0 pw=0 time=0 us)’
STAT #1 id=2 cnt=2636 pid=1 pos=1 obj=0 op=’HASH JOIN RIGHT OUTER (cr=2802 pr=0 pw=0 time=1028 us cost=771 size=1283040 card=8910)’
STAT #1 id=3 cnt=7935 pid=2 pos=1 obj=14 op=’TABLE ACCESS FULL SEG$ (cr=231 pr=0 pw=0 time=18 us cost=63 size=87285 card=7935)’
STAT #1 id=4 cnt=2636 pid=2 pos=2 obj=0 op=’HASH JOIN RIGHT OUTER (cr=2571 pr=0 pw=0 time=1000 us cost=707 size=352317 card=2649)’
STAT #1 id=5 cnt=88 pid=4 pos=1 obj=47 op=’INDEX FULL SCAN I_USER2 (cr=1 pr=0 pw=0 time=1 us cost=1 size=352 card=88)’
STAT #1 id=6 cnt=2636 pid=4 pos=2 obj=0 op=’HASH JOIN OUTER (cr=2570 pr=0 pw=0 time=978 us cost=705 size=341721 card=2649)’

This tracing was done for my own session.Same thing can be done for other users SQL_IDs  using alter system command.
Here is example:

on different session I am running:

SQL> select count(*) from dba_triggers;

  COUNT(*)
———-
       487

on second window I will get sql_id.I can also use OEM or any other tools to get it:
SQL> l
  1  select sql_id, sql_text
  2      from v$sql
  3*    where sql_text = ‘select count(*) from dba_triggers’
SQL> /

SQL_ID        SQL_TEXT
————- ———————————————————————-
b6z8h59a39gv9 select count(*) from dba_triggers

SQL> alter system set events ‘sql_trace [sql:b6z8h59a39gv9]‘;

System altered.

SQL> alter system set events ‘sql_trace [sql:b6z8h59a39gv9] off’;

System altered.
and again here is output:

=====================
PARSING IN CURSOR #3 len=33 dep=0 uid=0 oct=3 lid=0 tim=1237833092872029 hv=1412743017 ad=’111129950′ sqlid=’b6z8h59a39gv9′
select count(*) from dba_triggers
END OF STMT
EXEC #3:c=0,e=116,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1237833092872020
FETCH #3:c=7999,e=7969,p=0,cr=803,cu=0,mis=0,r=1,dep=0,og=1,tim=1237833092880538
FETCH #3:c=0,e=5,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1237833092881221

 

Second very usefull option for sql_trace is tracing using process information.
Syntax is:

alter session/system set events ‘sql_trace {process : pid = <pid1>, pname = <pname>, orapid = <orapid>} rest of event specification’;

I can trace process using process id, process name or  orapid.Tracing using procesid and orapid are known but tracing using proces is a new option.

Tracing using process id :

alter session set events ‘sql_trace {process:pid}’

where pid  is ospid column from from v$process.
For example I amd tracing my session using process id ( ospid column ):
SQL> l
  1  select
  2    p.pid,
  3    p.spid,
  4    s.sid,
  5    s.username,
  6    s.serial#,
  7    s.sql_hash_value
  8  from
  9    sys.v$session  s,
 10    sys.v$process  p
 11  where
 12    s.sid = (select sid from sys.v_$mystat where rownum = 1) and
 13*   p.addr = s.paddr
SQL> /

       PID SPID                            SID USERNAME                          SERIAL# SQL_HASH_VALUE
———- ———————— ———- —————————— ———- ————–
        46 27173                            31 SYS                                  1490     3889092034

SQL>  alter session set events ‘sql_trace {process:27173}’;

Session altered.

SQL> select * from global_name;

GLOBAL_NAME
————————————————————————————————————————————————————
TEST.WORLD

SQL>  alter session set events ‘sql_trace {process:27173} off’;

Session altered.
and output is here:

PARSING IN CURSOR #1 len=25 dep=0 uid=0 oct=3 lid=0 tim=1237837640466858 hv=2708373143 ad=’e5c12d10′ sqlid=’3039gbyhqwznr’
select * from global_name
END OF STMT
PARSE #1:c=2000,e=4896,p=0,cr=2,cu=0,mis=1,r=0,dep=0,og=1,tim=1237837640466854
EXEC #1:c=1000,e=99,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1237837640467014
FETCH #1:c=0,e=44,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,tim=1237837640467097
FETCH #1:c=0,e=7,p=0,cr=1,cu=0,mis=0,r=0,dep=0,og=1,tim=1237837640467475
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=97 op=’TABLE ACCESS FULL PROPS$ (cr=4 pr=0 pw=0 time=0 us cost=2 size=26 card=1)’
How about tracing my own session and somebody else session or my two session at the same time:

I will use alter system command and concatenate processes.
First session:

SQL> select
  p.pid,
  p.spid,
  s.sid,
  s.username,
  s.serial#,
  s.sql_hash_value
from
  sys.v$session  s,
  sys.v$process  p
where
  s.sid = (select sid from sys.v_$mystat where rownum = 1) and
  p.addr = s.paddr
/ 
SQL>

       PID SPID                            SID USERNAME                          SERIAL# SQL_HASH_VALUE
———- ———————— ———- —————————— ———- ————–
        48 7293                             97 SYS                                 19891     3889092034

Second session:

SQL> /

       PID SPID                            SID USERNAME                          SERIAL# SQL_HASH_VALUE
———- ———————— ———- —————————— ———- ————–
        46 6917                             31 SYS                                  1492     3889092034

SQL> alter system set events ‘sql_trace {process:6917|7293}’;

System altered.

on first session:

SQL> select count(*) from dba_views;

  COUNT(*)
———-
      4764

on second session:

SQL> select * from global_name;

GLOBAL_NAME
————————————————————————————————————————————————————
TEST.WORLD

SQL> alter system set events ‘sql_trace {process:6917|7293} off’;
will generate two trace files:
test1_ora_7293.trc
test1_ora_6917.trc  with trace information.
Trace using orapid:
SQL> /

       PID SPID                            SID USERNAME                          SERIAL# SQL_HASH_VALUE
———- ———————— ———- —————————— ———- ————–
        46 17121                            31 SYS                                  1495     3889092034

SQL>  alter system set events ‘sql_trace {process:orapid= 46}’;
or two process at the same time:
SQL> alter session set events ‘sql_trace {process: orapid=46|48}’;

Session altered.

3thd option is less knows.Tracing  session using process name:

First find process name:
 
 
select name from v$bgprocess
SQL> alter system set events ‘sql_trace {process: pname=dbw0}’;

System altered.

SQL> alter system set events ‘sql_trace {process: pname=dbw0} off’;

System altered.
or dbw and smon together:
 
SQL> alter system set events ‘sql_trace {process: pname=dbw0|smon}’;

this will trace background processess db writter and smon..
 
More usefull is to trace parallel servers.They all start with p00 until p<max_number_of_parallel> :
Query below will list them: 

select inst_id,x.server_name
         , x.status as x_status
         , x.pid as x_pid
         , x.sid as x_sid
    from  gv$px_process x
    order by x.server_name
In this case I will trace PX p000 and p005:

alter system set events ‘sql_trace  {process: pname = p000 | p005}’;

select /*+ FULL(dt) PARALLEL(dt, 20) */
table_name from dba_tables dt;

alter system set events ‘sql_trace  {process: pname = p000 | p005} off’;

 
=====================
PARSING IN CURSOR #1 len=69 dep=1 uid=0 oct=3 lid=0 tim=1237836727163758 hv=1179590906 ad=’fa16fcb8′ sqlid=’g8g8du534y87u’
select /*+ FULL(dt) PARALLEL(dt, 20) */
table_name from dba_tables dt
END OF STMT
EXEC #1:c=20997,e=4863068,p=0,cr=4,cu=0,mis=0,r=0,dep=1,og=1,tim=1237836727163741

 
Now remember  rest of event specification at the beginging of post:

These are the options for sql_trace:

sql_trace wait=true | false, bind=true | false,planstat=never | first_execution | all_executionss|level = 12

 I am sure all familiar with ( waits, binds, level ) .Also included are plan statistics and executions .

so this will trace specific sql_id with waits binds and statistiscs for first execution at level 12:
SQL> alter session set events ‘sql_trace [sql:52k2t5z1anrac] wait=true, bind=true,plan_stat=first_execution,level=12′;

Session altered.

or same only for process id and all_exec

alter session set events ‘sql_trace {process:1234} wait=true, bind=true,plan_stat=all_executions,level=12′;

I am sure that soon there will be a plenty of sql  tracing scripts made based on this events and options.I am glad that I brough some new light to this event.