Zahid Karim
Recent Posts
1.Draw plus and cross sign into PDF via PLSQL using PL_FPDF
2.Draw Triangle directly into PDF via PLSQL using PL_FPDF
3.Write fast and efficient PLSQL - DBMS_PROFILER
4.Fix physically corrupt data blocks using PLSQL - DBMS_REPAIR
5.Encrypt or Decrypt sensitive data using PLSQL - DBMS_CRYPTO
Find me on
How to kill all processes with one command in Linux Add ASM Instance into Enterprise Manager

How to extract user sql statements from Oracle Trace Files

Posted by Zahid on May 4, 2010.

While working as a Performance Tuning Specialist most of times it happens that you are given an application performing slow and that application is a total black box for you (usually third party vendors). The first thing to know about that application is what is it doing behind the smoke. Oracle tracing can come quite handy as one of the ways to know what exactly the application is doing.

When you switch on tracing oracle starts capturing every thing that is being done in the application session into the trace files. And all that information is not always any important to you. For example you will find lot of queries on SYS objects, queries done for general session management, queries for enforcing constraints etc etc. Here in this article I will demonstrate a way to filter the actual queries coming from the application from Oracle's self management queries.

$ sqlplus / as sysdba
grant select on v_$session to scott;
grant select on v_$process to scott;

/* grant necessary privileges to user SCOTT for this tutorial */

show parameter user_dump_dest

NAME                 TYPE        VALUE
-------------------- ----------- ------------------------------
user_dump_dest       string      /d01/apps/admin/oraxpo/udump

/* The user_dump_dest is the location where all user trace files go. */

Keep the sysdba session intact, open a new console and login as scott and think it as your application has just started.

$ sqlplus scott/tiger

Connected to:
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production
With the Partitioning, OLAP and Data Mining options

SQL> 

Once you have successfully created a session with user SCOTT come back to the sysdba console and enable tracing for that session.

SQL> select sid, serial# from v$session where username = 'SCOTT';

       SID    SERIAL#
---------- ----------
       147          6

begin
  dbms_system.set_sql_trace_in_session (147 , 6 , TRUE);
end;
/

PL/SQL procedure successfully completed.

dbms_system.set_sql_trace_in_session enables tracing in another session

whose SID and SERIAL# you provide.
After enabling trace come back to SCOTT's console and start your workload just like your application would.

SQL> insert into emp (empno,deptno) values (1001,10);

1 row created.

SQL> insert into emp (empno,deptno) values (1002,10);

1 row created.

SQL> update emp set sal=sal+1000 where empno=7839;

1 row updated.

SQL> commit;

Commit complete.

SQL> delete from emp where empno = 1002;

1 row deleted.

SQL> delete from dept where deptno=40

1 row deleted.

SQL> select p.spid
  2  from v$process p , v$session s
  3  where p.addr = s.paddr
  4  and s.audsid = userenv('sessionid');

SPID
------------
4836

/* 
  The spid is important as when oracle generates the trace file,
  it names the file as [SID]_ora_[SPID].trc. So in our case the trace
  file for this session shoud be oraxpo_ora_4836.trc where oraxpo is 
  my oracle sid.
*/

When your work load is complete come to the sysdba console and disable the tracing.

begin
  dbms_system.set_sql_trace_in_session (147 , 6 , FALSE);
end;
/

PL/SQL procedure successfully completed.

Now lets look for the file oraxpo_ora_4836.trc in /d01/apps/admin/oraxpo/udump.

$ cd /d01/apps/admin/oraxpo/udump

$ ls -lart *4836*
-rw-r----- 1 oracle oinstall 1190460 May  3 19:06 oraxpo_ora_4836.trc

See below, we have 3126 lines in the trace file against a few queries.

$ wc -l oraxpo_ora_4836.trc
3126 oraxpo_ora_4836.trc

The follwoing command will filter out the queries that you need.

$ awk '/PARSING IN CURSOR/,/END OF STMT/' oraxpo_ora_4836.trc |
  egrep -v '^PARSING|^END OF STMT|\#|\$ '
alter session set sql_trace=true
insert into emp (empno,deptno) values (1001,10)
insert into emp (empno,deptno) values (1002,10)
update emp set sal=sal+1000 where empno=7839
commit
delete from emp where empno = 1002
delete from dept where deptno=40
 select /*+ all_rows */ count(1) from "SCOTT"."EMP" where "DEPTNO" = :1
select p.spid
from v$process p , v$session s
where p.addr = s.paddr
and s.audsid = userenv('sessionid')
$ 

As you can see these are only those queries which we executed from SCOTT except the red marked.
Now here is no magic, this is just an implication of regular expressions on the trace file using Linux AWK command.
Lets see how its done.

The statements in the trace files are put by Oracle like this:

PARSING IN CURSOR #3 len=103 dep=0 uid=54 oct=3 lid=54 tim=1243063785371672 hv=1991672904 ad='56541de0'
select p.spid
from v$process p , v$session s
where p.addr = s.paddr
and s.audsid = userenv('sessionid')
END OF STMT

Now the first part of the awk command which is "awk '/PARSING IN CURSOR/,/END OF STMT/' oraxpo_ora_4836.trc" prints all the lines in the trace file oraxpo_ora_4836.trc where starting line contains "PARSING IN CURSOR" and ending line contains "END OF STMT". Once all these are extracted then we put an egrep on this output as egrep -v '^PARSING|^END OF STMT|\#|\$|\/ ' , which means we don't want any line having "PARSING" and "END OF STMT" in it and lines which contains any word ending at "$" and "#" which is usually the case with the Oracle Internal Object Names. So any query issued on these objects are not displayed.

As you may have an idea now that we are just working on a guess which is almost all of the times correct with a very few exceptions. The red marked statement above was not issued by the user SCOTT, but it was issued by Oracle to check any child record in the Table EMP when SCOTT tried to delete a record from DEPT table which is a parent table of RMP is a foreign key relationship. This particular query was not filtered out because there is no word in this line which ends at "$" or "#" and "PARSING" and "END OF STMT" are not part of this line either.

Now you may not be sure if this query is coming from the application or not. In that case you should probably leave it as is. But if the application has some defined coding standards and you know that the application is not using any Oracle Hints anywhere or you have any other way to tell that this is not an application query, you can further extend your regular expression to filter this out.

$ awk '/PARSING IN CURSOR/,/END OF STMT/' oraxpo_ora_4836.trc |
  egrep -v '^PARSING|^END OF STMT|\#|\$|\/ '
alter session set sql_trace=true
insert into emp (empno,deptno) values (1001,10)
insert into emp (empno,deptno) values (1002,10)
update emp set sal=sal+1000 where empno=7839
commit
delete from emp where empno = 1002
delete from dept where deptno=40
select p.spid
from v$process p , v$session s
where p.addr = s.paddr
and s.audsid = userenv('sessionid')

Here I added "|\/" to my regular expression and it removed any query where a forward slash (/) is being used at the end of a word. So the long story short is that you should always start with a minimum restricted regular expression and then extend it if required.

Once you have all the queries executed by the application, target the suspicious ones and look for there statistics like from the trace file.

$ sqlplus / as sysdba
-- Clean up after the tutorial.
revoke select on v_$session from scott;
revoke select on v_$process from scott;