There may be occassions when you need to or wish to run a tkprof on only a portion of a trace file (a fragment of the trace file or a partial trace file).
Cases where I've used this approach are similar to these examples :
1. Tracing was executed for an application server process running for 30minutes, probably running the same 40 SQL statements 20times (a total of 800 execution) in those 30minutes. Assuming that I am interested in 1 particular SQL statement that took 240seconds for 1 of the 20executions (maybe the fifth execution), 180seconds for another (possibly the eighteenth execution) and 5seconds each for all other 18executions.
If I were to run a tkprof on the whole trace file, it would show me that the SQL was executed 20 times but would show me Row Source Operations for *only 1* of those 20 executions. That 1 execution might be the case where it fetched 200 rows in 5seconds.
Oracle might very well have used the same execution plan for all 20 executions but, because of the nature of the underlying data, it might be suboptimal for those 2 occurrences which took 240seconds and 180seconds each. Quite possible, right ?
tkprof's listing of Row Source Operations does not show me all 20 execution.
However, the raw trace file would show 20 sets of STAT# lines where I can read the Row Source Operations from. {This is assuming that the cursor is closed after every execution. If the cursor doesn't get closed, STAT# lines are not placed in the trace file}.
Such a case would be where tkprof is "lying" to me -- but it is really only providing me partial data. {Although it still says that the summed execution time for the 20executions was 410seconds (240+180+18*5), the Row Source Operations details are for a 5seconds execution. The minimum time was 5seconds, the maximum was 240seconds. This (min/max execution time) information, too, is not available in tkprof.
2. During the course of the execution of the application server program, a developer drops an index on a key table accessed by the one (of the 30 !) SQL statement that I am interested in (he could have dropped the index when another SQL was being executed).
Say, he dropped the index after the fifth execution. The next 15 executions would have a different Execution Plan from the first 5 executions. Yet, tkprof will NOT tell me that there were at least 2 different Execution Plans. I can discern that from the "Misses in library cache" information but the Row Source Operation section would show me only 1 of the (at least 2 different) Execution Plans. So, once again, tkprof is "lying" in that it is not presenting the complete information.
What would I do in such cases ? I would split up the trace file into, maybe, 20 different pieces and run a tkprof on each piece. (Assuming that the cursor was closed each of the 20 times), I can see all 20 sets of Row Source Operation details now ! For the first case, I can see in one of the 20 trace files that the SQL took 240seconds and Row Source Operations would show me where (which index scan , table fetch, join operation etc) it spent the most time !
This leads to the question : How can I split the trace file ? Don't I have to maintain the "consistency" of the trace file ? Shouldn't the header information be repeated in all 20 pieces ?
NO, I can slice the trace file (horizontally of course, not vertically) at any point and still run tkprof. If, of course, I slice it incorrectly such that the WAIT events and/or Row Source Operations for an SQL execution are not in the same "slice" (piece), tkprof cannot tell me the correct (or would actually present incorrect) Wait times / Row Source operations. However, if I slice the file correctly (forget the trace file header, it is not important to me), I can get seperate tkprofs.
No comments:
Post a Comment