Nigel Noble's Oracle Blog

17/06/2010

My 10046 SQL Trace Formatter

Filed under: Monitoring, trace — Nigel Noble @ 10:52 pm

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).

About these ads

2 Comments »

  1. 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


RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

The Silver is the New Black Theme. Blog at WordPress.com.

Follow

Get every new post delivered to your Inbox.

Join 26 other followers

%d bloggers like this: