Chronological list of statements from Oracle trace

oracletrace

I'm using a trace in Oracle (11.2) to elucidate the behavior of a client application, and would like to view a list of all of the SQL statements that it submits, in the order in which they were submitted. Toward this end, I enable the trace using:

EXECUTE DBMS_SYSTEM.SET_EV(<sid>, <serial#>, 10046, 12, '')

This produces a trace file with the information I'm seeking, though in a format that is difficult for human consumption. Accordingly, I format the raw trace using:

tkprof raw.trc formatted.out explain=user/password aggregate=no sys=no waits=yes record=formatted.rec

This facilitates readability, but also obscures the real-world sequence of events in both of the output files (formatted.out, formatted.rec).

Specifically, the client appropriately holds open the cursors for popular statements and re-executes them on subsequent invocations. The default (and only?) behavior of tkprof is to:

  • In the main output file, combine the stats for all executions
  • In the record file, only list the statement when initially parsed

(The latter of which assumes I'm lucky enough to catch the parse event in the first place, which usually requires flushing the shared pool before enabling the trace, but I digress.)

For example, if the client submits statements like the following and holds the cursors open:

SELECT column1 FROM table1 WHERE column2 = :value;
INSERT INTO table1 SET column1 = :value1, column2 = :value2;
SELECT column1 FROM table1 WHERE column2 = :value;

The output record file will only show two statements:

SELECT column1 FROM table1 WHERE column2 = :value;
INSERT INTO table1 SET column1 = :value1, column2 = :value2;

There is no evidence, as far as I can tell, that the first statement was executed a second time.

Similarly, the main trace file will only show reports for two statements, though the first one will indicate that the SELECT statement was executed/fetched twice (only a partial excerpt follows):

call     count       cpu    elapsed       disk      query    current        rows    
------- ------  -------- ---------- ---------- ---------- ----------  ----------    
Parse        1      0.00       0.00          0          0          0           0    
Execute      2      0.00       0.00          0          4          6           0    
Fetch        2      0.00       0.00          0          0          0           2    
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      0.00       0.00          0          4          6           2

It's not clear from this formatted output which statements were executed in which order – only that one of them was executed twice at some point.

As far as I can see, I need to read the raw trace file and laboriously follow the trail of cursor numbers (some of which get reused for different statements over time) to understand the actual sequence of events, as they occurred in the real world.

My question is:

  • Is there some tkprof option, or tkprof alternative, that will extract from a raw trace file a list of all SQL statements in the
    order that they were executed, even in cases where the same cursor is
    held open and executed multiple times?

Ideally, this output would include the bind variable values for each execution, or at least the SQL ID or cursor ID, so I could go back and find them in the raw trace.

Thanks in advance.

Best Answer

While TKProf is generally referred to as something that makes a trace file 'human readable' it is primarily a Profiling tool that aggregates the SQL statements to find the most impactful.

The raw trace file can be used. However if you are primarily interested in what the client sends to the server, you should look at logging options in JDBC ( https://www.oracle.com/technetwork/topics/11-2.pdf ) or in the SQL Net layer (see Oracle Client trace not generating )