Skip to Content

Hello All,

I am here to share some scripts that might be useful for some situations. For creating regular SQL trace on Oracle generation we usually have transaction ST05. In case it is unavailable there, is an option to create it directly on sqlplus. To make it easier in case of need, here are the scripts to be used for that.

First to do is to identify which is the session that needs to be traced. This code bellow will create the command for enabling the SQL trace for all sessions of a specific user on the database. Since SAP uses only one user account on the database level it may be necessary to check what is the correct SID that we are investigating.

select ‘EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=> ‘|| sid || ‘, serial# =>’ || serial# || ‘, sql_trace=>TRUE);’

from v$session where username = upper(‘&usr’)

/

Sample output:

Enter value for usr: SAPSR3

old   2: from v$session where username = upper(‘&usr’)

new   2: from v$session where username = upper(‘SAPSR3’)

‘EXECDBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(SID=>’||SID||’,SERIAL#=>’||SERIAL#||’,SQL_TRACE=>TRUE);’

————————————————————————————————EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=> 17, serial# =>31, sql_trace=>TRUE);

EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=> 28, serial# =>15, sql_trace=>TRUE);

EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=> 29, serial# =>27, sql_trace=>TRUE);

EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=> 30, serial# =>13, sql_trace=>TRUE);

EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=> 33, serial# =>7, sql_trace=>TRUE);

EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=> 34, serial# =>9, sql_trace=>TRUE);

EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=> 35, serial# =>23, sql_trace=>TRUE);

EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=> 36, serial# =>9, sql_trace=>TRUE);

EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=> 37, serial# =>9, sql_trace=>TRUE);

EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=> 38, serial# =>7, sql_trace=>TRUE);

EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=> 39, serial# =>43, sql_trace=>TRUE);

EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=> 40, serial# =>9, sql_trace=>TRUE);

EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=> 45, serial# =>19, sql_trace=>TRUE);

EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=> 46, serial# =>3, sql_trace=>TRUE);

EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=> 47, serial# =>23, sql_trace=>TRUE);

EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=> 48, serial# =>11, sql_trace=>TRUE);

EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=> 49, serial# =>5, sql_trace=>TRUE);

For identifying the correct session, the following script may be helpful:

  select sid

       , serial#

       , username

       , osuser

       , machine appserver

       , module

       , status

    from v$session

where username = upper(‘&user’)

order by status

       , username

/

This can be helpful in case you know all the sessions from the same application server are the ones to be traced, so you can enable all SIDs from this specific host. When prompted type in the user id for the SAP schema on the database.

After that, you can execute the command lines generated on the first query for the desired SIDs.

SQL> EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=> 40, serial# =>9, sql_trace=>TRUE);

PL/SQL procedure successfully completed.

Once the session completes the action you need to check the trace, you can disable it with the code bellow:

set serveroutput on

set verify off

declare

  cursor c_1 is

    select  a.spid, b.sid, b.serial#

         from v$process a, v$session b

     where a.addr   = b.paddr

       and b.username = ‘&usr’;

     

  crow c_1%rowtype;

  dbname varchar2(20);

begin

  select instance_name

    into dbname

       from v$instance;

  open c_1;

  loop

  

       fetch c_1 into crow;

     

       exit when c_1%notfound;

     

       dbms_output.put_line(‘exec dbms_system.set_sql_trace_in_session(sid=> ‘|| crow.sid || ‘, serial# =>’ || crow.serial# || ‘,sql_trace=>FALSE);’);

       dbms_output.put_line(‘tkprof ‘ || dbname || ‘_ora_’ || crow.spid || ‘.trc tkprof.out explain=sys/<password> table=sys.plan_table sort=exeela’);

       dbms_output.put_line(‘–‘);

  end loop;

end;

/

set verify on

The output will show all sessions for the desired user as well (on this example I used SAPSR3), as bellow:

Enter value for usr: SAPSR3

exec dbms_system.set_sql_trace_in_session(sid=> 38, serial# =>7,sql_trace=>FALSE);

tkprof ISC_ora_5686.trc tkprof.out explain=sys/<password> table=sys.plan_table sort=exeela

exec dbms_system.set_sql_trace_in_session(sid=> 34, serial# =>9,sql_trace=>FALSE);

tkprof ISC_ora_5684.trc tkprof.out explain=sys/<password> table=sys.plan_table sort=exeela

exec dbms_system.set_sql_trace_in_session(sid=> 36, serial# =>9,sql_trace=>FALSE);

tkprof ISC_ora_5677.trc tkprof.out explain=sys/<password> table=sys.plan_table sort=exeela

exec dbms_system.set_sql_trace_in_session(sid=> 39, serial# =>43,sql_trace=>FALSE);

tkprof ISC_ora_5688.trc tkprof.out explain=sys/<password> table=sys.plan_table sort=exeela

exec dbms_system.set_sql_trace_in_session(sid=> 37, serial# =>9,sql_trace=>FALSE);

tkprof ISC_ora_5690.trc tkprof.out explain=sys/<password> table=sys.plan_table sort=exeela

exec dbms_system.set_sql_trace_in_session(sid=> 46, serial# =>3,sql_trace=>FALSE);

tkprof ISC_ora_5694.trc tkprof.out explain=sys/<password> table=sys.plan_table sort=exeela

exec dbms_system.set_sql_trace_in_session(sid=> 28, serial# =>15,sql_trace=>FALSE);

tkprof ISC_ora_5692.trc tkprof.out explain=sys/<password> table=sys.plan_table sort=exeela

exec dbms_system.set_sql_trace_in_session(sid=> 40, serial# =>9,sql_trace=>FALSE);

tkprof ISC_ora_5700.trc tkprof.out explain=sys/<password> table=sys.plan_table sort=exeela

exec dbms_system.set_sql_trace_in_session(sid=> 29, serial# =>27,sql_trace=>FALSE);

tkprof ISC_ora_5696.trc tkprof.out explain=sys/<password> table=sys.plan_table sort=exeela

exec dbms_system.set_sql_trace_in_session(sid=> 33, serial# =>7,sql_trace=>FALSE);

tkprof ISC_ora_5698.trc tkprof.out explain=sys/<password> table=sys.plan_table sort=exeela

exec dbms_system.set_sql_trace_in_session(sid=> 17, serial# =>31,sql_trace=>FALSE);

tkprof ISC_ora_5702.trc tkprof.out explain=sys/<password> table=sys.plan_table sort=exeela

exec dbms_system.set_sql_trace_in_session(sid=> 48, serial# =>11,sql_trace=>FALSE);

tkprof ISC_ora_5704.trc tkprof.out explain=sys/<password> table=sys.plan_table sort=exeela

exec dbms_system.set_sql_trace_in_session(sid=> 49, serial# =>5,sql_trace=>FALSE);

tkprof ISC_ora_5706.trc tkprof.out explain=sys/<password> table=sys.plan_table sort=exeela

exec dbms_system.set_sql_trace_in_session(sid=> 47, serial# =>23,sql_trace=>FALSE);

tkprof ISC_ora_5721.trc tkprof.out explain=sys/<password> table=sys.plan_table sort=exeela

exec dbms_system.set_sql_trace_in_session(sid=> 45, serial# =>19,sql_trace=>FALSE);

tkprof ISC_ora_5717.trc tkprof.out explain=sys/<password> table=sys.plan_table sort=exeela

exec dbms_system.set_sql_trace_in_session(sid=> 35, serial# =>23,sql_trace=>FALSE);

tkprof ISC_ora_5725.trc tkprof.out explain=sys/<password> table=sys.plan_table sort=exeela

exec dbms_system.set_sql_trace_in_session(sid=> 30, serial# =>13,sql_trace=>FALSE);

tkprof ISC_ora_5714.trc tkprof.out explain=sys/<password> table=sys.plan_table sort=exeela

PL/SQL procedure successfully completed.

Make sure to select the correct line for the SID you want. The line that starts with “exec” should be used on sqlplus itself, while the tkprof line should be used on the OS level, in the user_dump_dest directory (usually /oracle/<SID>/saptrace/diag/rdbms/<sid>/<SID>/trace). Tkprof is an Oracle tool that creates a more user friendly output for the SQL trace. Make sure you replace the “<password>” with the actual password for the SYS user. You may need to request the customer to that. Here is an excerpt from one I have created on a test system:

TKPROF: Release 11.2.0.3.0 – Development on Thu Jan 31 11:42:17 2013

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

Trace file: ISC_ora_5994.trc

Sort options: exeela

********************************************************************************

count    = number of times OCI procedure was executed

cpu      = cpu time in seconds executing

elapsed  = elapsed time in seconds executing

disk     = number of physical reads of buffers from disk

query    = number of buffers gotten for consistent read

current  = number of buffers gotten in current mode (usually for update)

rows     = number of rows processed by the fetch or execute call

********************************************************************************

Error in CREATE TABLE of EXPLAIN PLAN table: sys.plan_table

ORA-01031: insufficient privileges

EXPLAIN PLAN option disabled.

********************************************************************************

SQL ID: 7ng34ruy5awxq Plan Hash: 3992920156

select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags,i.property,

  i.pctfree$,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i.distkey,i.lblkkey,

  i.dblkkey,i.clufac,i.cols,i.analyzetime,i.samplesize,i.dataobj#,

  nvl(i.degree,1),nvl(i.instances,1),i.rowcnt,mod(i.pctthres$,256),

  i.indmethod#,i.trunccnt,nvl(c.unicols,0),nvl(c.deferrable#+c.valid#,0),

  nvl(i.spare1,i.intcols),i.spare4,i.spare2,i.spare6,decode(i.pctthres$,null,

  null,mod(trunc(i.pctthres$/256),256)),ist.cachedblk,ist.cachehit,

  ist.logicalread

from

ind$ i, ind_stats$ ist, (select enabled, min(cols) unicols,

  min(to_number(bitand(defer,1))) deferrable#,min(to_number(bitand(defer,4)))

  valid# from cdef$ where obj#=:1 and enabled > 1 group by enabled) c where

  i.obj#=c.enabled(+) and i.obj# = ist.obj#(+) and i.bo#=:1 order by i.obj#

call     count       cpu    elapsed       disk      query    current        rows

——- ——  ——– ———- ———- ———- ———-  ———-

Parse        1      0.00       0.00          0          0          0           0

Execute      1      0.00       0.00          0          0          0           0

Fetch        2      0.00       0.02          1          7          0           1

——- ——  ——– ———- ———- ———- ———-  ———-

total        4      0.00       0.03          1          7          0           1

Misses in library cache during parse: 1

Misses in library cache during execute: 1

Optimizer mode: CHOOSE

Parsing user id: SYS   (recursive depth: 1)

Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation

———- ———- ———-  —————————————————

         1          1          1 SORT ORDER BY (cr=7 pr=1 pw=0 time=25849 us cost=3 size=187 card=1)

         1          1          1   HASH JOIN OUTER (cr=7 pr=1 pw=0 time=25800 us cost=2 size=187 card=1)

         1          1          1    NESTED LOOPS OUTER (cr=4 pr=0 pw=0 time=86 us cost=0 size=144 card=1)

         1          1          1     TABLE ACCESS CLUSTER IND$ (cr=3 pr=0 pw=0 time=53 us cost=0 size=92 card=1)

         1          1          1    NESTED LOOPS OUTER (cr=4 pr=0 pw=0 time=86 us cost=0 size=144 card=1)

         1          1          1     TABLE ACCESS CLUSTER IND$ (cr=3 pr=0 pw=0 time=53 us cost=0 size=92 card=1)

         1          1          1      INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=25 us cost=0 size=0 card=1)(object id 3)

         0          0          0     TABLE ACCESS BY INDEX ROWID IND_STATS$ (cr=1 pr=0 pw=0 time=28 us cost=0 size=52 card=1)

         0          0          0      INDEX UNIQUE SCAN I_IND_STATS$_OBJ# (cr=1 pr=0 pw=0 time=27 us cost=0 size=0 card=1)(object id 433)

         1          1          1    VIEW  (cr=3 pr=1 pw=0 time=25380 us cost=2 size=43 card=1)

         1          1          1     SORT GROUP BY (cr=3 pr=1 pw=0 time=25369 us cost=1 size=15 card=1)

         1          1          1      TABLE ACCESS BY INDEX ROWID CDEF$ (cr=3 pr=1 pw=0 time=25260 us cost=0 size=15 card=1)

        18         18         18       INDEX RANGE SCAN I_CDEF2 (cr=2 pr=0 pw=0 time=168 us cost=0 size=0 card=8)(object id 54)

********************************************************************************

Here I listed only one SQL statement, but the report will actually contain this output for all statements executed while the trace was turned on.

 

Best regards,

Thiago

To report this post you need to login first.

8 Comments

You must be Logged on to comment or reply to a post.

  1. Stefan Koehler

    Hi Thiago,

    just in addition to your provided blog post and scripts.

    – You usually assign / block a work process with ABAP report RSTRC000 and then trace only this particular database session (no need to enable a “full application” trace on database level with all of its side effects) by reproducing the issue

    – The trace files are limited by SAP default setting for Oracle databases to 20000 OS blocks (MAX_DUMP_FILE_SIZE), which usually results in “max file size reached” by tracing a business process without adjusting this setting

    DBMS_MONITOR should be used instead of DBMS_SYSTEM (e.g. for using plan_stat or by using “new” trace events for dumping execution plans in different cursor scenarios)

    – EXPLAIN option of TKPROF can produce wrong results due to implicit usage of “EXPLAIN PLAN” and its limitations (e.g. like “it treats all bind variables as VARCHAR2”)

    – TKPROF has some major issues / lack of function like relationship between SQLs is lost after specifying the sort argument, data is provided in an aggregate manner, bind information is not provided or unaccounted time needs to be calculated manually – i recommend TVD$XTAT instead in most cases

    Best Regards

    Stefan

    (0) 
    1. Thiago Cavalheiro Post author

      Hi Stefan,

      Thanks for sharing your thoughts. In my opinion TKPROF is still useful though, even if only to check what are the SQL statements that are affecting the performance. And of course I wouldn’t recommend leaving the SQL trace enabled for much long, this is just while reproducing a specific task.

      I didn’t know about TVD$XTAT, I’ll take a look into it.

      Thanks again.

      Best regards,

      Thiago

      (0) 
    2. Stefan Koehler

      Hi all,

      just in addition to my previous comment – i noticed this behavior a few days ago.

      You don’t need to block a SAP WP by using ABAP report RSTRC000 due to the good code instrumentation by SAP DBSL. You are able to enable a dedicated extended SQL trace for a specific SAP user on Oracle database level by using the client ID (Database Session Identifier). For example for user DDIC:

      SQL> exec DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE(‘DDIC’,TRUE,TRUE,’ALL_EXECUTIONS’);

      Regards

      Stefan

      (0) 
        1. Stefan Koehler

          Hi Fidel,

          that would be awesome. I was surprised about this code instrumentation enhancement as well, because of i had not noticed this before. As far as i can remember this was a 7.20 EXT2 kernel.

          Regards

          Stefan

          (0) 
          1. Fidel Vales

            Hi

            The column CLIENT_IDENTIFER started to be populated on 7.20 (before the EXT2 Kernel) but it is not documented the exact patch.

            Before, the DBSL updated other information of V$SESSION fields MODULE, ACTION and CLIENT_INFO (to find out the ABAP source mainly)

            (0) 
            1. Stefan Koehler

              Hi Fidel,

              thanks for the update and information about the patched kernel release. Unfortunately the previous implemented code instrumentation (MODULE, ACTION and CLIENT_INFO) was not enough to trace a whole business process without locking a SAP WP 🙁 … Luckily SAP took notice of that and implemented it – great stuff 🙂

              Regards

              Stefan

              (0) 

Leave a Reply