|« 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 sessionwhose 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'
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;