trace_by_hash.awk
A number of years ago, I wrote a SQL Trace File formatter when I needed to process a large amount of trace files for a complex project we were working on. The formatter is not intended to replace the really good tools that are out there, but I like reading the detail which appears in a raw trace file (but with some additional help). I also wanted to structure the trace file so it could be processed by other scripts separately. This is by no means written to a commercial standard, but I thought people may find it useful and also provide interesting insite on how to process trace files. I worked with James Morle in a previous company to build a benchmark based on Oracle trace files using some software he had written in his book (Scaling Oracle 8i, the paper Brewing Benchmarks and the later software simora ). The benchmark software contained an awk script to process traces files and extract the entry point database calls and convert them to a tcl scripting language to then drive the benchmark. I took (with permission) the conversion script and modified it so it generated a Oracle trace file but with extra information.
Reading a large Oracle Trace file can be difficult (particularly if the application is well written to avoid unnecessary parsing of sql). Usage of a “prepared statement cache” and later versions of JDBC drivers mean that a trace file may show the sql text during the first parse at the top of the file, but never show any sql text ever again.
Example raw trace file
note: 10g version of trace file without bind tracing EXEC #9:c=295955,e=289036,p=0,cr=7760,cu=18338,mis=0,r=1,dep=2,og=1,tim=1180634170580983 EXEC #29:c=0,e=125,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=2,tim=1180634170581711 FETCH #29:c=0,e=44,p=0,cr=1,cu=0,mis=0,r=0,dep=2,og=2,tim=1180634170581781 XCTEND rlbk=0, rd_only=1 EXEC #31:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=0,tim=1180634170581989 EXEC #53:c=0,e=136,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=1,tim=1180634170589160 FETCH #53:c=33995,e=33271,p=0,cr=7029,cu=0,mis=0,r=700,dep=3,og=1,tim=1180634170622566 EXEC #44:c=0,e=389,p=0,cr=0,cu=4,mis=0,r=1,dep=3,og=1,tim=1180634170623588 XCTEND rlbk=0, rd_only=0 EXEC #45:c=0,e=111,p=0,cr=0,cu=1,mis=0,r=0,dep=3,og=0,tim=1180634170623747 EXEC #54:c=0,e=71,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=1,tim=1180634170623859 FETCH #54:c=1000,e=279,p=0,cr=50,cu=0,mis=0,r=0,dep=3,og=1,tim=1180634170624189 EXEC #55:c=0,e=28,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=1,tim=1180634170624287 FETCH #55:c=0,e=12,p=0,cr=1,cu=0,mis=0,r=0,dep=3,og=1,tim=1180634170624330 EXEC #57:c=0,e=65,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=1,tim=1180634170700148 ===================== PARSING IN CURSOR #63 len=129 dep=4 uid=0 oct=6 lid=0 tim=1180634170702781 hv=2635489469 ad='22daed20' update seq$ set increment$=:2,minvalue=:3,maxvalue=:4,cycle#=:5,order$=:6,cache=:7,highwater=:8,audit$=:9,flags=:10 where obj#=:1 END OF STMT PARSE #63:c=0,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=4,og=4,tim=1180634170702778 EXEC #63:c=0,e=293,p=0,cr=1,cu=2,mis=0,r=1,dep=4,og=4,tim=1180634170703175 STAT #63 id=1 cnt=1 pid=0 pos=1 obj=0 op='UPDATE SEQ$ (cr=1 pr=0 pw=0 time=239 us)' STAT #63 id=2 cnt=1 pid=1 pos=1 obj=102 op='INDEX UNIQUE SCAN I_SEQ1 (cr=1 pr=0 pw=0 time=23 us)' FETCH #57:c=4999,e=4311,p=0,cr=6,cu=3,mis=0,r=1358,dep=3,og=1,tim=1180634170704540 WAIT #58: nam='log file switch completion' ela= 228006 p1=0 p2=0 p3=0 obj#=-1 tim=1180634170950223 WAIT #58: nam='log file switch completion' ela= 244847 p1=0 p2=0 p3=0 obj#=-1 tim=1180634171195162 WAIT #58: nam='buffer busy waits' ela= 1689 file#=35 block#=20489 class#=155 obj#=0 tim=1180634171210594 EXEC #58:c=90985,e=566666,p=0,cr=149,cu=15399,mis=0,r=1358,dep=3,og=1,tim=1180634171272924 EXEC #44:c=1000,e=266,p=0,cr=0,cu=4,mis=0,r=1,dep=3,og=1,tim=1180634171273760 XCTEND rlbk=0, rd_only=0 EXEC #45:c=0,e=316,p=0,cr=0,cu=1,mis=0,r=0,dep=3,og=0,tim=1180634171274111 EXEC #59:c=1000,e=1087,p=0,cr=26,cu=26,mis=0,r=24,dep=3,og=1,tim=1180634171275272 EXEC #60:c=40994,e=40592,p=0,cr=40,cu=3207,mis=0,r=1056,dep=3,og=1,tim=1180634171319080 EXEC #61:c=0,e=69,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=1,tim=1180634171321161 FETCH #61:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=1,dep=3,og=1,tim=1180634171321254 EXEC #62:c=7999,e=7531,p=0,cr=529,cu=0,mis=0,r=0,dep=3,og=1,tim=1180634171328838 EXEC #46:c=1000,e=309,p=0,cr=1,cu=1,mis=0,r=1,dep=3,og=1,tim=1180634171349850 EXEC #47:c=2999,e=3049,p=0,cr=31,cu=237,mis=0,r=63,dep=3,og=1,tim=1180634171353333 EXEC #48:c=0,e=274,p=0,cr=0,cu=3,mis=0,r=1,dep=3,og=4,tim=1180634171354545 XCTEND rlbk=0, rd_only=0 WAIT #56: nam='latch: enqueue hash chains' ela= 230 address=35343054720 number=19 tries=1 obj#=-1 tim=1180634171360412 WAIT #56: nam='latch: enqueue hash chains' ela= 37255 address=35343054720 number=19 tries=2 obj#=-1 tim=1180634171397762 EXEC #56:c=5999,e=43121,p=0,cr=0,cu=1,mis=0,r=0,dep=3,og=0,tim=1180634171398190 EXEC #9:c=308953,e=816696,p=0,cr=7865,cu=18908,mis=0,r=1,dep=2,og=1,tim=1180634171398856 EXEC #50:c=0,e=288,p=0,cr=1,cu=2,mis=0,r=1,dep=2,og=1,tim=1180634171399378 XCTEND rlbk=0, rd_only=0 EXEC #52:c=1000,e=87,p=0,cr=0,cu=1,mis=0,r=0,dep=2,og=0,tim=1180634171399503
When you look at a large trace file (like above), you have to try to remember which cursor number relates to which sql text. It’s possible for the same cursor number to be reused for different sql statements. It can be difficult to compare several trace files generated by different sessions because the cursor numbers can vary (One session may call extra internal recursive sql and use the cursor number which was used by something else in another sessions trace file.
My trace file formatter attempts to deal with these issues with the following features. Note: Some or all the features can be switched on by a set of configuration parameters in the top of the script.
Summary of Features
I will give a brief summary of the features before exploring them in more detail. Some of the features work better than others. trace_by_hash.awk has the following options:
- conversion of the cursor numbers into the sql hash_value. eg “EXEC #59:” becomes “EXEC #3096109005:”. Because all references to the cursor number is now the fixed sql_hash_value, it is now possible to write scripts against a trace file to profile specific sql statements and also to profile many trace files with the same processing.
- Repeat the sql parse text on every execution (EXEC) call. eg, now possible to jump in at any part of the trace file and see the sql_text for the nearest execution (EXEC). The way this is done is to repeat the exact “PARSING IN CURSOR” information on every call. The reason for repeating the full “PARSING IN CURSOR” text is that it is now possible to cut out short parts of the trace file and have it run against utilities such as tkprof (Oracle’s trace profiler). This allows profiling of short parts of a large trace output.
- Indent trace output to reflect the recursive sql depth. eg, when reading the trace of a call to a stored plsql, which in turn executes sql, which in turn executes recursive SYS sql, the trace file will be indented making it easier to read.
- Add timestamp to trace file. The script will add an approximate human readable time to the trace file output. There are a couple of ways to do this but I am only going to talk about the default method. The scripts see’s what time the trace file was started in the header, and assumes the “tim=” value on the first sql statement is that same time and then works out all time from that baseline. This method works reasonably well, but is possible for trace file to be started and then a delay before next sql statement. May be possible to improve this in the future. The other option involved getting the application to execute a special SQL statement which includes the system time so the formatter can find it and set the base time and system time at consistent point.
- Add delta time to every line. The script can also add a delta time between sql/wait statements. This can be important to spot delays which are not in sql but either the client or time spent in pure plsql. I do have a version of the script which attempts to break down this time further into time spent in plsql and sql but I only had limited success so not included it.
- Allow processing of bind variables. If the trace was made to include bind variables, the script will generate a single line for each execution which includes the sql_hash_value and all the bind data. This makes it possible to profile all the values for a specific query.
- profile sql dependency (note: very badly implemented but kind of works). This allows a file to be generated which shows for example which plsql procedure was called and which sql statements it calls. These can be then used in profiling sql for a specific procedure call. **Note: The code is left in for this but the output needs a lot of mucking about by hand** probably not worth trying!.
Using the above, we were able to generate additional scripts which could then profile specific parts of the application (both time in sql statements and procedures but also the time between sql statements (including inside large plsql procedures) and also give a summary of rows processed (r=) for key sql statements.
Examples
Following example shows how we can profile specific sql statements. In this example I will format the trace file so all cursor numbers are converted to the sql_hash_value, then I can look for a specific sql statement by hash number (I can then run this on many trace files regardless of cursor numbers used)
$ ./trace_by_hash.awk abc1_ora_15772.trc | grep "EXEC #1711438125" | more EXEC #1711438125:c=277957,e=278731,p=0,cr=7900,cu=18934,mis=0,r=1,dep=2,og=1,tim=1180634162359512 EXEC #1711438125:c=293955,e=289873,p=0,cr=7945,cu=20453,mis=0,r=1,dep=2,og=1,tim=1180634162650576 EXEC #1711438125:c=283957,e=301283,p=0,cr=7808,cu=19294,mis=0,r=1,dep=2,og=1,tim=1180634162954735 EXEC #1711438125:c=307953,e=325653,p=0,cr=8077,cu=20290,mis=0,r=1,dep=2,og=1,tim=1180634163281707 EXEC #1711438125:c=298955,e=293236,p=0,cr=7981,cu=20165,mis=0,r=1,dep=2,og=1,tim=1180634163576579 EXEC #1711438125:c=291956,e=285030,p=0,cr=7893,cu=19470,mis=0,r=1,dep=2,og=1,tim=1180634163862972 EXEC #1711438125:c=287957,e=289269,p=0,cr=7842,cu=18255,mis=0,r=1,dep=2,og=1,tim=1180634164153867 EXEC #1711438125:c=301953,e=306938,p=0,cr=7851,cu=19901,mis=0,r=1,dep=2,og=1,tim=1180634164462182
I can now write a simple awk filter to find examples of the elapsed time (e=) taking a long time. In this example, sql_hash_value 1711438125 is a plsql stored procedure so I will find any examples longer than half a second (500ms)
$ ./trace_by_hash.awk abc1_ora_15772.trc | grep "EXEC #1711438125" | gawk -F, '{e=$2;x=sub("e=","",e);if (e + 0 > 500000) {print $0;}}'
EXEC #1711438125:c=308953,e=816696,p=0,cr=7865,cu=18908,mis=0,r=1,dep=2,og=1,tim=1180634171398856
EXEC #1711438125:c=347948,e=507123,p=0,cr=8391,cu=19861,mis=0,r=1,dep=2,og=1,tim=1180634172341323
EXEC #1711438125:c=338948,e=523424,p=0,cr=7963,cu=19401,mis=0,r=1,dep=2,og=1,tim=1180634185387239
EXEC #1711438125:c=323951,e=597571,p=0,cr=8003,cu=18819,mis=0,r=1,dep=2,og=1,tim=1180634217021013
EXEC #1711438125:c=334949,e=563515,p=0,cr=8016,cu=19676,mis=0,r=1,dep=2,og=1,tim=1180634218655660
EXEC #1711438125:c=302954,e=543647,p=0,cr=7883,cu=19719,mis=0,r=1,dep=2,og=1,tim=1180634280115132
EXEC #1711438125:c=290955,e=519560,p=1,cr=7982,cu=18639,mis=0,r=1,dep=2,og=1,tim=1180634346928803
I can now take a specific tim= value and search for this in the fully formatted trace file. If we look up the plsql call for the 816ms example above (first slow example) we can jump into the trace file and see how that 816ms elapsed time is accounted for. I have switched on all the formatting options here.
Things to remember:
- This example sql is faked so don’t worry if the sql application does not make sense.
- None of the sql text would appear in the middle of a real raw trace file making it difficult to read and understand.
- Cursor numbers are converted to sql_hash_values making possible to profile by hash_value
- a time and delta of tim= values added (note: I only change the delta time when a new tim= value is changed, so you will see the same value repeated until a new tim= is found)
- EXEC line only appears when a sql statement completes, so you need to find the EXEC you are interested in and read nested sql statements above that. This is helped by the indentation of the SQL depth.
- I have added a few comments in the following output (**COMMENT**)
- One final point, this is the formatted trace for the exact raw trace section shown at the top of this blog article.
./trace_by_hash.awk abc1_ora_15772.trc > abc1_ora_15772.txt **comment: I have cut the output around the slow 816ms procedure call **comment: ignore this first procedure call, this is the EXEC of the PREVIOUS plsql procedure 2008-04-23 16:49:50 689 PARSING IN CURSOR #1711438125 len=223 dep=2 uid=68 oct=47 lid=68 tim=1180634162359516 hv=1711438125 ad='233a05e8' 2008-04-23 16:49:50 689 BEGIN pkg_do_stuff.pr_process( :id, :reload_true_false, :dump_data, :call_immediately, :error_id ); END; 2008-04-23 16:49:50 689 END OF STMT 2008-04-23 16:49:50 689 EXEC #1711438125:c=295955,e=289036,p=0,cr=7760,cu=18338,mis=0,r=1,dep=2,og=1,tim=1180634170580983 2008-04-23 16:49:50 728 ===================== 2008-04-23 16:49:50 728 PARSING IN CURSOR #525534860 len=570 dep=2 uid=0 oct=3 lid=0 tim=1180634162360228 hv=525534860 ad='2344b810' 2008-04-23 16:49:50 728 select /*+ FIRST_ROWS(1) */ tab.rowid, tab.msgid, tab.corrid, tab.priority, tab.delay, tab.expiration, tab.retry_count, tab.exception_qschema, tab.exception_queue, tab.chain_no, tab.local_order_no, tab.enq_time, tab.time_manager_info, tab.state, tab.enq_tid, tab.step_no, tab.sender_name, tab.sender_address, tab.sender_protocol, tab.dequeue_msgid, tab.user_prop, tab.user_data from "CODE"."QTAB_INFO" tab where q_name = :1 and (state = :2 ) order by q_name, state, enq_time, step_no, chain_no, local_order_no for update skip locked 2008-04-23 16:49:50 728 END OF STMT 2008-04-23 16:49:50 728 EXEC #525534860:c=0,e=125,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=2,tim=1180634170581711 2008-04-23 16:49:50 70 FETCH #525534860:c=0,e=44,p=0,cr=1,cu=0,mis=0,r=0,dep=2,og=2,tim=1180634170581781 2008-04-23 16:49:50 70 XCTEND rlbk=0, rd_only=1 2008-04-23 16:49:50 208 ===================== 2008-04-23 16:49:50 208 PARSING IN CURSOR #255718823 len=6 dep=2 uid=68 oct=44 lid=68 tim=1180634162360510 hv=255718823 ad='0' 2008-04-23 16:49:50 208 COMMIT 2008-04-23 16:49:50 208 END OF STMT 2008-04-23 16:49:50 208 EXEC #255718823:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=0,tim=1180634170581989 **comment: this is in fact the first sql statement in side the slow procedure, it is indented (dep=3) **comment: The actual slow EXEC will be at dep=2 at the end of the output 2008-04-23 16:49:50 7171 ===================== 2008-04-23 16:49:50 7171 PARSING IN CURSOR #1676635612 len=1083 dep=3 uid=68 oct=3 lid=68 tim=1180634162366901 hv=1676635612 ad='22b0c098' 2008-04-23 16:49:50 7171 SELECT DATA1,DATA2,DATA3 FROM T_INPUT TBU 2008-04-23 16:49:50 7171 END OF STMT 2008-04-23 16:49:50 7171 EXEC #1676635612:c=0,e=136,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=1,tim=1180634170589160 2008-04-23 16:49:50 33406 FETCH #1676635612:c=33995,e=33271,p=0,cr=7029,cu=0,mis=0,r=700,dep=3,og=1,tim=1180634170622566 2008-04-23 16:49:50 1022 ===================== 2008-04-23 16:49:50 1022 PARSING IN CURSOR #776466503 len=196 dep=3 uid=68 oct=2 lid=68 tim=1180634162396345 hv=776466503 ad='24cc4f58' 2008-04-23 16:49:50 1022 INSERT INTO T_LOG ( ID , TYPE , MESSAGE , DAEMON_ID ) VALUES ( LOG_ID.NEXTVAL , :B7 , :B6 , :B5 , :B4 , ) 2008-04-23 16:49:50 1022 END OF STMT 2008-04-23 16:49:50 1022 EXEC #776466503:c=0,e=389,p=0,cr=0,cu=4,mis=0,r=1,dep=3,og=1,tim=1180634170623588 2008-04-23 16:49:50 1022 XCTEND rlbk=0, rd_only=0 2008-04-23 16:49:50 159 ===================== 2008-04-23 16:49:50 159 PARSING IN CURSOR #255718823 len=6 dep=3 uid=68 oct=44 lid=68 tim=1180634162396510 hv=255718823 ad='0' 2008-04-23 16:49:50 159 COMMIT 2008-04-23 16:49:50 159 END OF STMT 2008-04-23 16:49:50 159 EXEC #255718823:c=0,e=111,p=0,cr=0,cu=1,mis=0,r=0,dep=3,og=0,tim=1180634170623747 2008-04-23 16:49:50 112 ===================== 2008-04-23 16:49:50 112 PARSING IN CURSOR #4115507142 len=1012 dep=3 uid=68 oct=3 lid=68 tim=1180634162396622 hv=4115507142 ad='24a69150' 2008-04-23 16:49:50 112 SELECT DATA1 FROM T_QUEUE 2008-04-23 16:49:50 112 END OF STMT 2008-04-23 16:49:50 112 EXEC #4115507142:c=0,e=71,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=1,tim=1180634170623859 2008-04-23 16:49:50 330 FETCH #4115507142:c=1000,e=279,p=0,cr=50,cu=0,mis=0,r=0,dep=3,og=1,tim=1180634170624189 2008-04-23 16:49:50 98 ===================== 2008-04-23 16:49:50 98 PARSING IN CURSOR #2654270261 len=796 dep=3 uid=68 oct=3 lid=68 tim=1180634162396990 hv=2654270261 ad='22b0b5a0' 2008-04-23 16:49:50 98 SELECT DATA1,DATA2 FROM T_QUEUE2 2008-04-23 16:49:50 98 END OF STMT 2008-04-23 16:49:50 98 EXEC #2654270261:c=0,e=28,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=1,tim=1180634170624287 2008-04-23 16:49:50 43 FETCH #2654270261:c=0,e=12,p=0,cr=1,cu=0,mis=0,r=0,dep=3,og=1,tim=1180634170624330 2008-04-23 16:49:50 75818 ===================== 2008-04-23 16:49:50 75818 PARSING IN CURSOR #3186096073 len=75 dep=3 uid=68 oct=3 lid=68 tim=1180634162467210 hv=3186096073 ad='22acd4f0' 2008-04-23 16:49:50 75818 SELECT APP_ID.NEXTVAL FROM T_APP_NUMS WHERE ROWNUM <= :B1 2008-04-23 16:49:50 75818 END OF STMT 2008-04-23 16:49:50 75818 EXEC #3186096073:c=0,e=65,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=1,tim=1180634170700148 2008-04-23 16:49:50 75818 ===================== **comment: recursive oracle sys sql to update a system sequence table 2008-04-23 16:49:50 75818 PARSING IN CURSOR #2635489469 len=129 dep=4 uid=0 oct=6 lid=0 tim=1180634170702781 hv=2635489469 ad='22daed20' 2008-04-23 16:49:50 75818 update seq$ set increment$=:2,minvalue=:3,maxvalue=:4,cycle#=:5,order$=:6,cache=:7,highwater=:8,audit$=:9,flags=:10 where obj#=:1 2008-04-23 16:49:50 75818 END OF STMT 2008-04-23 16:49:50 2630 PARSE #2635489469:c=0,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=4,og=4,tim=1180634170702778 2008-04-23 16:49:50 397 ===================== 2008-04-23 16:49:50 397 PARSING IN CURSOR #2635489469 len=129 dep=4 uid=0 oct=6 lid=0 tim=1180634170702781 hv=2635489469 ad='22daed20' 2008-04-23 16:49:50 397 update seq$ set increment$=:2,minvalue=:3,maxvalue=:4,cycle#=:5,order$=:6,cache=:7,highwater=:8,audit$=:9,flags=:10 where obj#=:1 2008-04-23 16:49:50 397 END OF STMT 2008-04-23 16:49:50 397 EXEC #2635489469:c=0,e=293,p=0,cr=1,cu=2,mis=0,r=1,dep=4,og=4,tim=1180634170703175 2008-04-23 16:49:50 397 STAT #2635489469 id=1 cnt=1 pid=0 pos=1 obj=0 op='UPDATE SEQ$ (cr=1 pr=0 pw=0 time=239 us)' 2008-04-23 16:49:50 397 STAT #2635489469 id=2 cnt=1 pid=1 pos=1 obj=102 op='INDEX UNIQUE SCAN I_SEQ1 (cr=1 pr=0 pw=0 time=23 us)' 2008-04-23 16:49:50 1365 FETCH #3186096073:c=4999,e=4311,p=0,cr=6,cu=3,mis=0,r=1358,dep=3,og=1,tim=1180634170704540 **comment: notice we loose 400ms in two waits on the database **comment: any difference between the delta times and the elapsed sql time (e=) is normally time in the plsql or client 2008-04-23 16:49:51 245683 WAIT #2577162295: nam='log file switch completion' ela= 228006 p1=0 p2=0 p3=0 obj#=-1 tim=1180634170950223 2008-04-23 16:49:51 244939 WAIT #2577162295: nam='log file switch completion' ela= 244847 p1=0 p2=0 p3=0 obj#=-1 tim=1180634171195162 2008-04-23 16:49:51 15432 WAIT #2577162295: nam='buffer busy waits' ela= 1689 file#=35 block#=20489 class#=155 obj#=0 tim=1180634171210594 2008-04-23 16:49:51 62330 ===================== 2008-04-23 16:49:51 62330 PARSING IN CURSOR #2577162295 len=208 dep=3 uid=68 oct=2 lid=68 tim=1180634162279786 hv=2577162295 ad='24a2ad68' 2008-04-23 16:49:51 62330 INSERT INTO T_APP_OUTPUT VALUES (:B1 ,:B2 ,:B3 ,:B4 ,:B5 ,:B6 ,:B7 ,:B8 ,:B9 ,:B10 ,:B11 ,:B12 ,:B13 ,:B14 ,:B15 ,:B16 ,:B17 ,:B18 ,:B19 ,:B20 ,:B21 ,:B22 ,:B23 ,:B24 ,:B25 ,:B26 ,:B27 ,:B28 ,:B29 ,:B30 ) 2008-04-23 16:49:51 62330 END OF STMT **comment: notice this next EXEC is 500ms but includes the time lost in the nested recursive waits above **comment: Wait events are also reported in trace after they complete, hence a short time in delta between **comment: the WAITs tim= value and the completion of the EXEC sql statement. 2008-04-23 16:49:51 62330 EXEC #2577162295:c=90985,e=566666,p=0,cr=149,cu=15399,mis=0,r=1358,dep=3,og=1,tim=1180634171272924 2008-04-23 16:49:51 836 ===================== 2008-04-23 16:49:51 836 PARSING IN CURSOR #776466503 len=196 dep=3 uid=68 oct=2 lid=68 tim=1180634162396345 hv=776466503 ad='24cc4f58' 2008-04-23 16:49:51 836 INSERT INTO T_LOG ( ID , TYPE , MESSAGE , DAEMON_ID ) VALUES ( LOG_ID.NEXTVAL , :B7 , :B6 , :B5 , :B4 , ) 2008-04-23 16:49:51 836 END OF STMT 2008-04-23 16:49:51 836 EXEC #776466503:c=1000,e=266,p=0,cr=0,cu=4,mis=0,r=1,dep=3,og=1,tim=1180634171273760 2008-04-23 16:49:51 836 XCTEND rlbk=0, rd_only=0 2008-04-23 16:49:51 351 ===================== 2008-04-23 16:49:51 351 PARSING IN CURSOR #255718823 len=6 dep=3 uid=68 oct=44 lid=68 tim=1180634162396510 hv=255718823 ad='0' 2008-04-23 16:49:51 351 COMMIT 2008-04-23 16:49:51 351 END OF STMT 2008-04-23 16:49:51 351 EXEC #255718823:c=0,e=316,p=0,cr=0,cu=1,mis=0,r=0,dep=3,og=0,tim=1180634171274111 2008-04-23 16:49:51 1161 ===================== 2008-04-23 16:49:51 1161 PARSING IN CURSOR #3096109005 len=385 dep=3 uid=68 oct=6 lid=68 tim=1180634162281365 hv=3096109005 ad='24a2b1e8' 2008-04-23 16:49:51 1161 UPDATE T_CONTROL SET TOTAL=:B1 WHERE ID = :B2 AND OTHER_ID = :B3 2008-04-23 16:49:51 1161 END OF STMT 2008-04-23 16:49:51 1161 EXEC #3096109005:c=1000,e=1087,p=0,cr=26,cu=26,mis=0,r=24,dep=3,og=1,tim=1180634171275272 2008-04-23 16:49:51 43808 ===================== 2008-04-23 16:49:51 43808 PARSING IN CURSOR #2694978569 len=275 dep=3 uid=68 oct=6 lid=68 tim=1180634162321122 hv=2694978569 ad='24a2bbe8' 2008-04-23 16:49:51 43808 UPDATE T_INPUT TBUF SET TBUF.STATUS = :B4 , TBUF.SIZE = :B3 WHERE TBUF.ROWID = :B5 2008-04-23 16:49:51 43808 END OF STMT 2008-04-23 16:49:51 43808 EXEC #2694978569:c=40994,e=40592,p=0,cr=40,cu=3207,mis=0,r=1056,dep=3,og=1,tim=1180634171319080 2008-04-23 16:49:51 2081 ===================== 2008-04-23 16:49:51 2081 PARSING IN CURSOR #624481974 len=48 dep=3 uid=68 oct=3 lid=68 tim=1180634162322917 hv=624481974 ad='23326260' 2008-04-23 16:49:51 2081 SELECT SEQ_NO.NEXTVAL FROM DUAL 2008-04-23 16:49:51 2081 END OF STMT 2008-04-23 16:49:51 2081 EXEC #624481974:c=0,e=69,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=1,tim=1180634171321161 2008-04-23 16:49:51 93 FETCH #624481974:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=1,dep=3,og=1,tim=1180634171321254 2008-04-23 16:49:51 7584 ===================== 2008-04-23 16:49:51 7584 PARSING IN CURSOR #562877356 len=135 dep=3 uid=68 oct=6 lid=68 tim=1180634162329662 hv=562877356 ad='24a2a8e8' 2008-04-23 16:49:51 7584 UPDATE T_MONEY SET ESTIMATED = 'Y' , LOCK = :B3 WHERE ID = :B2 AND ESTIMATED = 'N' 2008-04-23 16:49:51 7584 END OF STMT 2008-04-23 16:49:51 7584 EXEC #562877356:c=7999,e=7531,p=0,cr=529,cu=0,mis=0,r=0,dep=3,og=1,tim=1180634171328838 2008-04-23 16:49:51 21012 ===================== 2008-04-23 16:49:51 21012 PARSING IN CURSOR #945999453 len=122 dep=3 uid=68 oct=6 lid=68 tim=1180634162349722 hv=945999453 ad='2299fff0' 2008-04-23 16:49:51 21012 UPDATE T_SEQ SET ID = ID + 1 WHERE NAME = :B1 RETURNING ID INTO :O0 2008-04-23 16:49:51 21012 END OF STMT 2008-04-23 16:49:51 21012 EXEC #945999453:c=1000,e=309,p=0,cr=1,cu=1,mis=0,r=1,dep=3,og=1,tim=1180634171349850 2008-04-23 16:49:51 3483 ===================== 2008-04-23 16:49:51 3483 PARSING IN CURSOR #3080672287 len=63 dep=3 uid=68 oct=2 lid=68 tim=1180634162353483 hv=3080672287 ad='23326620' 2008-04-23 16:49:51 3483 INSERT INTO T_OUTPUT VALUES ( :B4 , :B1 , :B2 , :B3 ) 2008-04-23 16:49:51 3483 END OF STMT 2008-04-23 16:49:51 3483 EXEC #3080672287:c=2999,e=3049,p=0,cr=31,cu=237,mis=0,r=63,dep=3,og=1,tim=1180634171353333 2008-04-23 16:49:51 1212 ===================== 2008-04-23 16:49:51 1212 PARSING IN CURSOR #840807921 len=496 dep=3 uid=0 oct=2 lid=0 tim=1180634162354581 hv=840807921 ad='248a25e8' 2008-04-23 16:49:51 1212 insert into "CODE"."DATA_QTAB" (q_name, msgid, corrid, priority, state, delay, expiration, time_manager_info, local_order_no, chain_no, enq_time, step_no, enq_uid, enq_tid, retry_count, exception_qschema, exception_queue, recipient_key, dequeue_msgid, user_data, sender_name, sender_address, sender_protocol, user_prop, cscn, dscn) values (:1, :2, :3, :4, :5, :6, :7, :8, :9, :10, :11, :12, :13, :14, 0, :15, :16, :17, :18, :19, :20, :21, :22, :23, :24, :25) 2008-04-23 16:49:51 1212 END OF STMT 2008-04-23 16:49:51 1212 EXEC #840807921:c=0,e=274,p=0,cr=0,cu=3,mis=0,r=1,dep=3,og=4,tim=1180634171354545 2008-04-23 16:49:51 1212 XCTEND rlbk=0, rd_only=0 2008-04-23 16:49:51 5867 WAIT #255718823: enqueue hash chains' ela= 230 address=35343054720 number=19 tries=1 obj#=-1 tim=1180634171360412 2008-04-23 16:49:51 37350 WAIT #255718823: enqueue hash chains' ela= 37255 address=35343054720 number=19 tries=2 obj#=-1 tim=1180634171397762 2008-04-23 16:49:51 428 ===================== 2008-04-23 16:49:51 428 PARSING IN CURSOR #255718823 len=6 dep=3 uid=68 oct=44 lid=68 tim=1180634162358893 hv=255718823 ad='0' 2008-04-23 16:49:51 428 COMMIT 2008-04-23 16:49:51 428 END OF STMT 2008-04-23 16:49:51 428 EXEC #255718823:c=5999,e=43121,p=0,cr=0,cu=1,mis=0,r=0,dep=3,og=0,tim=1180634171398190 **comment: notice the depth returns to depth=2: the next EXEC is the slow 816ms statements which the sql above relates too 2008-04-23 16:49:51 666 ===================== 2008-04-23 16:49:51 666 PARSING IN CURSOR #1711438125 len=223 dep=2 uid=68 oct=47 lid=68 tim=1180634162359516 hv=1711438125 ad='233a05e8' 2008-04-23 16:49:51 666 BEGIN pkg_do_stuff.pr_process( :id, :reload_true_false, :dump_data, :call_immediately, :error_id ); END; 2008-04-23 16:49:51 666 END OF STMT 2008-04-23 16:49:51 666 EXEC #1711438125:c=308953,e=816696,p=0,cr=7865,cu=18908,mis=0,r=1,dep=2,og=1,tim=1180634171398856 **comment: we continue with the next statement also at depth 2 (dep=2) 2008-04-23 16:49:51 522 ===================== 2008-04-23 16:49:51 522 PARSING IN CURSOR #375712160 len=108 dep=2 uid=68 oct=6 lid=68 tim=1180634162651576 hv=375712160 ad='2355ada0' 2008-04-23 16:49:51 522 UPDATE ALIVE_COUNT DAC SET DAC.COUNT = NVL( DAC.COUNT, 0 ) + 1 WHERE DAC.ID = :B1 2008-04-23 16:49:51 522 END OF STMT 2008-04-23 16:49:51 522 EXEC #375712160:c=0,e=288,p=0,cr=1,cu=2,mis=0,r=1,dep=2,og=1,tim=1180634171399378 2008-04-23 16:49:51 522 XCTEND rlbk=0, rd_only=0 2008-04-23 16:49:51 125 ===================== 2008-04-23 16:49:51 125 PARSING IN CURSOR #255718823 len=6 dep=2 uid=68 oct=44 lid=68 tim=1180634162651797 hv=255718823 ad='0' 2008-04-23 16:49:51 125 COMMIT 2008-04-23 16:49:51 125 END OF STMT 2008-04-23 16:49:51 125 EXEC #255718823:c=1000,e=87,p=0,cr=0,cu=1,mis=0,r=0,dep=2,og=0,tim=1180634171399503 **comment: trace file then continues with the rest of the trace file.
Processing bind variables
The final example is of processing Bind variables (none of the previous examples had bind tracing on
processing bind variables can be difficult because they are not tagged to a cursor in a way which makes it easy to process via grep
PARSING IN CURSOR #1 len=132 dep=1 uid=0 oct=3 lid=0 tim=1273586951204031 hv=4260389146 ad='27ab99f28' sqlid='cvn54b7yz0s8u' select /*+ index(idl_ub1$ i_idl_ub11) +*/ piece#,length,piece from idl_ub1$ where obj#=:1 and part=:2 and version=:3 order by piece# END OF STMT PARSE #1:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3246118364,tim=1273586951204030 BINDS #1: Bind#0 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0 kxsbbbfp=2b0113708e70 bln=22 avl=04 flg=05 value=44125 Bind#1 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0 kxsbbbfp=2b0113708e40 bln=24 avl=02 flg=05 value=2 Bind#2 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0 kxsbbbfp=2b0113708e10 bln=24 avl=06 flg=05 value=184549376 EXEC #1:c=0,e=113,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3246118364,tim=1273586951204205 FETCH #1:c=0,e=19,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,plh=3246118364,tim=1273586951204252 FETCH #1:c=0,e=8,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,plh=3246118364,tim=1273586951204282
Included in the output is a summary line added for each bind which is referenced by the sql_hash_value. In this example, I have run sql tracing on the execution of a statspack report (spreport). I have then profiled the bind variables for one statement. You can see BINDDUMP# tag, a short part of the sql_text, the hash_value, Number of Bind variables (4) and then each value of the bind eg, (1, 4140534469, 1, “db block changes”)
$ ./trace_by_hash.awk 11201_spreport.trc | grep "BINDDUMP.*3685970426" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "db block changes" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "db block changes" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "user calls" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "user calls" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "user rollbacks" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "user rollbacks" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "user commits" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "user commits" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "redo size" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "redo size" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "physical reads" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "physical reads" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "physical reads direct" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "physical reads direct" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "physical reads direct (lob)" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "physical reads direct (lob)" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "physical reads cache" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "physical reads cache" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "physical writes" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "physical writes" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "parse count (hard)" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "parse count (hard)" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "parse count (total)" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "parse count (total)" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "session logical reads" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "session logical reads" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "recursive calls" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "recursive calls" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "redo log space requests" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "redo log space requests" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "redo entries" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "redo entries" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "logons cumulative" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "logons cumulative" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "parse time cpu" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "parse time cpu" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "parse time elapsed" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "parse time elapsed" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "CPU used by this session" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "CPU used by this session" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "execute count" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "execute count" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "logons current" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "logons current" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 1, 4140534469, 1, "opened cursors current" BINDDUMP# , SELECT VALUE FROM STATS$SYSSTAT WHERE S, 3685970426, num_binds ,4, bind_data, 2, 4140534469, 1, "opened cursors current"
Link to “readme” file which also includes link to the script: trace_by_hash_readme
I hope people find the script useful for profiling SQL trace files and also a good source for information on how trace files work. Please remember that this script is not supported and I can’t guarantee does not have any bugs, but I have used it extensively (mostly against 10gR2 trace files).
Advertisement
Hello Nigel
Interesting. I look forward to testing it.
I like the blog, but surely your normal speaking voice reaches a large enough audience?
Cheers
Ray
Comment by Ray Feighery — 18/06/2010 @ 5:11 am
Hi Ray,
THANKS FOR THE COMMENT!! (There I go again.. shouting)
Good to hear from you!
Let me know how you get on with the formatter.
Regards
Nigel.
Comment by Nigel Noble — 21/06/2010 @ 5:23 pm