We love to discuss Oracle trace data with customers. A few months ago, one of our customers in The Netherlands, Andre van Winssen, contacted us to ask whether we could help him see the order in which SQL statements were being fired by an individual Oracle client process on his system. My response was that he could do this easily with Method R Tools. With Andre’s kind permission, I share our conversation with you here. Thank you, Andre, for having us give Method R Tools a stretch for you.

(beginning of email conversation)


Hi Cary,

Hope all is well on your end.

I have a question and hope you can give me a hint.

I have to improve database performance of one particular client program. This client program has on average 4 concurrent sessions open during its lifetime and opens and closes connections to the database all the time. So when I started to collect extended trace information I ended up with a whole bunch of trace files but I could not find an easy way to tell me the order in which sql statements were being fired by that one client. Do you know of a tool that can do that and generate a text file with the sql statement execution ordered by timestamp? The extended trace file seems to have all the information:

...
PARSING IN CURSOR #140550517933024 len=82 dep=1 uid=0 oct=3 lid=0 tim=1377012408378133 hv=3873422482 ad='3e4853988' sqlid='0k8522rmdzg4k'
...

As an alternative I turned on extended database auditing and that way I was able to find out this order of sql firing. But that is a very expensive method.

Met vriendelijke groeten/kind regards,
Andre van Winssen


Andre,Our mrskew program in Method R Tools will do it. I’d be glad to show you.

Cary Millsap
Method R Corporation


Attached one of the redacted trace files. I still have a copy of mrskew but don’t know how to call it to get what I want. Can you show me an example invocation of mrskew?

Met vriendelijke groeten/kind regards,
Andre van Winssen


Andre,

In Method R Tools version 3.0.2.3, within the GUI, I executed the following:

Custom Report

mrskew --group=sprintf("%15.6f %7d %7d %-8s %-.50s", $tim, $exec_id, $line, $name, $sql) --name=dbcall --glabel=TIM, EXEC-LINE, LINE, CALL, SQL-TEXT --sort=1na --top=50 --nohistogram --where1=1 "/Users/carymillsap/Downloads/testtrace.trc"
2013-08-28T12:06:43.000036-0500
Elapsed: 0.933000 s

TIM, EXEC-LINE, LINE, CALL, SQL-TEXT                                                         
---------------------------------------------------------------------------------------------
1377013557.763203       0      31 PARSE    select privilege# from sysauth$ where (grantee#=:1
1377013557.763931      38      38 EXEC     select privilege# from sysauth$ where (grantee#=:1
1377013557.764429      38      39 FETCH    select privilege# from sysauth$ where (grantee#=:1
1377013557.764703       0      44 PARSE    select /*+ connect_by_filtering */ privilege#,leve
1377013557.766246      51      51 EXEC     select /*+ connect_by_filtering */ privilege#,leve
1377013557.766960      51      52 FETCH    select /*+ connect_by_filtering */ privilege#,leve
1377013557.767907      51      58 CLOSE    select /*+ connect_by_filtering */ privilege#,leve
1377013557.768075      38      59 FETCH    select privilege# from sysauth$ where (grantee#=:1
1377013557.768296      38      62 CLOSE    select privilege# from sysauth$ where (grantee#=:1
1377013557.769181       0      67 PARSE    insert into sys.aud$( sessionid,entryid,statement,
1377013557.779009     228     228 EXEC     insert into sys.aud$( sessionid,entryid,statement,
1377013557.780270       0     234 PARSE    ALTER SESSION SET NLS_LANGUAGE= 'AMERICAN' NLS_TER
1377013557.781390     235     235 EXEC     ALTER SESSION SET NLS_LANGUAGE= 'AMERICAN' NLS_TER
1377013557.781491     235     236 CLOSE    ALTER SESSION SET NLS_LANGUAGE= 'AMERICAN' NLS_TER
1377013557.781977       0     241 PARSE    select value$ from props$ where name = 'GLOBAL_DB_
1377013557.782410     242     242 EXEC     select value$ from props$ where name = 'GLOBAL_DB_
1377013557.783087     242     243 FETCH    select value$ from props$ where name = 'GLOBAL_DB_
1377013557.783281     242     244 FETCH    select value$ from props$ where name = 'GLOBAL_DB_
1377013557.783493     242     246 CLOSE    select value$ from props$ where name = 'GLOBAL_DB_
1377013557.784181       0     251 PARSE    select SYS_CONTEXT('USERENV', 'SERVER_HOST'), SYS_
1377013557.784791     252     252 EXEC     select SYS_CONTEXT('USERENV', 'SERVER_HOST'), SYS_
1377013557.785175     252     253 FETCH    select SYS_CONTEXT('USERENV', 'SERVER_HOST'), SYS_
1377013557.785591     252     259 CLOSE    select SYS_CONTEXT('USERENV', 'SERVER_HOST'), SYS_
1377013557.786146       0     264 PARSE    select decode(failover_method, NULL, 0 , 'BASIC', 
1377013557.787310     271     271 EXEC     select decode(failover_method, NULL, 0 , 'BASIC', 
1377013557.787614     271     272 FETCH    select decode(failover_method, NULL, 0 , 'BASIC', 
1377013557.787922     271     274 CLOSE    select decode(failover_method, NULL, 0 , 'BASIC', 
1377013557.791570       0     311 PARSE    DECLARE tmpVar varchar2(128); /*******************
1377013557.799613       0     316 PARSE    SELECT VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHER
1377013557.799914     317     317 EXEC     SELECT VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHER
1377013557.800144     317     319 FETCH    SELECT VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHER
1377013557.801067     317     321 FETCH    SELECT VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHER
1377013557.802090     317     325 CLOSE    SELECT VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHER
1377013557.802358       0     330 PARSE    SELECT VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHER
1377013557.802612     331     331 EXEC     SELECT VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHER
1377013557.802827     331     333 FETCH    SELECT VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHER
1377013557.803780     331     335 FETCH    SELECT VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHER
1377013557.805547     331     339 CLOSE    SELECT VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHER
1377013557.806122       0     344 PARSE    SELECT KEY_TYPE FROM RTD_ENV_REGISTRATION WHERE ((
1377013557.809068     346     346 EXEC     SELECT KEY_TYPE FROM RTD_ENV_REGISTRATION WHERE ((
1377013557.811119     346     348 FETCH    SELECT KEY_TYPE FROM RTD_ENV_REGISTRATION WHERE ((
1377013557.812021     346     350 FETCH    SELECT KEY_TYPE FROM RTD_ENV_REGISTRATION WHERE ((
1377013557.818341     346     356 CLOSE    SELECT KEY_TYPE FROM RTD_ENV_REGISTRATION WHERE ((
1377013557.818505       0     361 PARSE    COMMIT                                            
1377013557.818796       0     362 XCTEND   #-512:/Users/carymillsap/Downloads/testtrace.trc  
1377013557.819133     363     363 EXEC     COMMIT                                            
1377013557.820567     363     366 CLOSE    COMMIT                                            
1377013557.820719       0     371 PARSE    ROLLBACK                                          
1377013557.820957       0     372 XCTEND   #-512:/Users/carymillsap/Downloads/testtrace.trc  
1377013557.821045     373     373 EXEC     ROLLBACK                                          
6 others                                                                                     
---------------------------------------------------------------------------------------------
TOTAL (56)

I’m imagining that this is pretty close to what you want. It’s a time-ordered list of each dbcall in a table containing:

  1. What time the call ended ($tim). You could print what time the call began by using the expression ($tim – $e).
  2. The line number of the call’s corresponding EXEC call ($exec_id). This helps you see, for example, how a flock of FETCH calls are coupled with a single EXEC.
  3. The line number of the call itself ($line).
  4. The first few characters of the SQL text ($sql, truncated by the sprintf call format that I used).

If you want to query across more than just one file, then you’ll want to load them into the top panel of the GUI and select them all when you run your mrskew command.

I used the option --where1=1, which opens up the query to all recursive SQL statements, too. To filter those, just don’t use the --where1=1 thing that I did. If you do that, you’ll get this:

Custom Report
mrskew --group=sprintf("%15.6f %7d %7d %-8s %-.50s", $tim, $exec_id, $line, $name, $sql) --name=dbcall --glabel=TIM, EXEC-LINE, LINE, CALL, SQL-TEXT --sort=1na --top=50 --nohistogram "/Users/carymillsap/Downloads/testtrace.trc" 
2013-08-28T12:19:01.000684-0500
Elapsed: 1.293000 s
    
TIM, EXEC-LINE, LINE, CALL, SQL-TEXT                                                         
---------------------------------------------------------------------------------------------
1377013557.799613       0     316 PARSE    SELECT VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHER
1377013557.799914     317     317 EXEC     SELECT VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHER
1377013557.800144     317     319 FETCH    SELECT VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHER
1377013557.801067     317     321 FETCH    SELECT VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHER
1377013557.802090     317     325 CLOSE    SELECT VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHER
1377013557.802358       0     330 PARSE    SELECT VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHER
1377013557.802612     331     331 EXEC     SELECT VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHER
1377013557.802827     331     333 FETCH    SELECT VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHER
1377013557.803780     331     335 FETCH    SELECT VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHER
1377013557.805547     331     339 CLOSE    SELECT VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHER
1377013557.806122       0     344 PARSE    SELECT KEY_TYPE FROM RTD_ENV_REGISTRATION WHERE ((
1377013557.809068     346     346 EXEC     SELECT KEY_TYPE FROM RTD_ENV_REGISTRATION WHERE ((
1377013557.811119     346     348 FETCH    SELECT KEY_TYPE FROM RTD_ENV_REGISTRATION WHERE ((
1377013557.812021     346     350 FETCH    SELECT KEY_TYPE FROM RTD_ENV_REGISTRATION WHERE ((
1377013557.818341     346     356 CLOSE    SELECT KEY_TYPE FROM RTD_ENV_REGISTRATION WHERE ((
1377013557.818505       0     361 PARSE    COMMIT                                            
1377013557.818796       0     362 XCTEND   #-512:/Users/carymillsap/Downloads/testtrace.trc  
1377013557.819133     363     363 EXEC     COMMIT                                            
1377013557.820567     363     366 CLOSE    COMMIT                                            
1377013557.820719       0     371 PARSE    ROLLBACK                                          
1377013557.820957       0     372 XCTEND   #-512:/Users/carymillsap/Downloads/testtrace.trc  
1377013557.821045     373     373 EXEC     ROLLBACK                                          
1377013557.822396     373     376 CLOSE    ROLLBACK                                          
1377013557.822501       0     377 XCTEND   #-512:/Users/carymillsap/Downloads/testtrace.trc  
1377013557.823814       0     380 XCTEND   #-512:/Users/carymillsap/Downloads/testtrace.trc  
---------------------------------------------------------------------------------------------
TOTAL (25)

The way you phrased your question, “the order in which SQL statements are fired,” probably requires some clarification. It’s more precise to talk about db calls (not SQL statements) being fired. Of course each PARSE, EXEC, or FETCH db call is associated with a particular SQL statement (contrast XCTEND db calls, which are not associated with a given SQL statement [well, except for COMMIT or ROLLBACK]), but it’s common to see a call or two for statement A execute, then a call or two for statement B, and then more calls for A again. So which statement “fired last?” You could argue either A or B. By looking at just your PARSING IN CURSOR lines, you would see the first time Oracle encountered each statement in the execution sequence, but by looking at individual db calls, you’re going to get a much richer understanding of what’s really going on.

If you want to see just the sequence of dbcalls for a single user experience, but the dbcalls for that user experience are spread all over a group of trace files, you’re going to need to get creative with the --where option. For example, if each experience has a unique CLIENT_ID (which I highly recommend that you do if you’re writing an application), you can filter by ($client_id eq "some constant") to see the sequence of action for just that one experience. Perhaps you can use $sid and $serial, or $module and $action to your advantage here. You should also take a look at the @bind expression variable introduced in mrskew 3.0, which would allow you to group calls by statement placeholder values. Look at the “Response time by execution id and placeholder value set for a given SQL id” report in the GUI for a starter on how that works.

This is a good question. Do you mind if I post your question and my answer here on our method-r.com blog?

Cary Millsap
Method R Corporation


Sure Cary, go ahead.

Met vriendelijke groeten/kind regards,
Andre van Winssen


Please let me know if the answer helped you before I go spreading it around all over the world, though. :-)

Cary Millsap
Method R Corporation


Thanks, it is exactly what I was looking for.

Met vriendelijke groeten/kind regards,
Andre van Winssen


(end of email conversation)

And there you go: problem solved.

mrskew is one of my favorite Method R software tools because it can do so many things. The real miracle of mrskew is that we can use it to produce results we had never thought of when we designed and wrote the tool. As a result, it’s a lot of fun to use, because we almost always learn something fascinating when we sit down with it.

mrskew is a component of the Method R Tools software suite. Method R Tools contains other utilities, too, that allow you to manage and manipulate Oracle trace data in ways you might not have thought possible. Method R Tools also includes a graphical user interface that allows you to run over a dozen predefined mrskew reports on your data with just a few clicks, and it helps you modify those reports to your heart’s content.

Watch this blog for more posts about new Method R Tools version 3.1 features that we will be releasing soon.