Trace Event Timeline, Part 2
In Part 2 of this post I’m going to describe how the trace event timeline is created. I think it’s important to discuss which events are being captured and how the intervals are derived since it affects the output of the graph and of course, the validity of the technique. There will also be a Part 3 which will discuss the event timeline graph and how it may be used.
There are several issues that crop up when thinking about how to slice a trace file into intervals and what is valid to use as event totals. When I initially came up with the idea of an event timeline I posed the question to Jeff Holt at Method-R.com in their forum as to what he thought about the idea. He raised these same issues, and suffice it to say that trying to do this at the “statement” level would be very hard. Reconciling the recursive SQL and trying to account for the time across multiple intervals was beyond the scope of what I was trying to achieve. That’s the beauty of the Interval Resource Profiler. It only summarizes the entire trace file or interval, and it does not attempt the much more detailed analysis of statement level attribution. This makes it fairly easy from a scripting perspective to use non-uniform intervals based on statement timings for wait events and recursive depth zero parse, execute and fetch statements.
Now for some background on the current state of extended SQL trace files. As of 11.1.0.6 a SQL trace file looks something like this (this is just a small part of one trace file):
EXEC #6:c=0,e=83,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1219708745416872 WAIT #6: nam='SQL*Net message to client' ela= 1 driver #bytes=1 p3=0 obj#=-1 tim=1219708745416904 FETCH #6:c=0,e=84,p=0,cr=8,cu=0,mis=0,r=1,dep=0,og=1,tim=1219708745417024 STAT #6 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS (cr=8 pr=0 pw=0 time=0 us cost=5 size=89 card=1)' STAT #6 cnt=1 pid=1 pos=1 obj=71003 op='TABLE ACCESS BY INDEX ROWID ODM_PUBLICOBJECT (cr=4 pr=0 pw=0 time=0 us cost=3 size=73 card=1)' STAT #6 cnt=1 pid=2 pos=1 obj=71009 op='INDEX UNIQUE SCAN SYS_C009848 (cr=3 pr=0 pw=0 time=0 us cost=2 size=0 card=1)' STAT #6 cnt=1 pid=1 pos=2 obj=70836 op='TABLE ACCESS BY INDEX ROWID ODM_DOCUMENT (cr=4 pr=0 pw=0 time=0 us cost=2 size=16 card=1)' STAT #6 cnt=1 pid=4 pos=1 obj=70839 op='INDEX UNIQUE SCAN SYS_C009781 (cr=3 pr=0 pw=0 time=0 us cost=1 size=0 card=1)' WAIT #6: nam='SQL*Net message from client' ela= 1202 driver #bytes=1 p3=0 obj#=-1 tim=1219708745418336 FETCH #6:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1219708745418358 WAIT #6: nam='SQL*Net message to client' ela= 1 driver #bytes=1 p3=0 obj#=-1 tim=1219708745418375 WAIT #6: nam='SQL*Net message from client' ela= 87423 driver #bytes=1 p3=0 obj#=-1 tim=1219708745505813 EXEC #3:c=0,e=84,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1219708745505944 WAIT #3: nam='SQL*Net message to client' ela= 1 driver #bytes=1 p3=0 obj#=-1 tim=1219708745506104 FETCH #3:c=0,e=174,p=0,cr=11,cu=0,mis=0,r=3,dep=0,og=1,tim=1219708745506134 WAIT #3: nam='SQL*Net message from client' ela= 2607 driver #bytes=1 p3=0 obj#=-1 tim=1219708745508784
Oracle continues to add events and fields but the basic trace file format remains essentially the same (see Metalink note 39817.1). The first thing to notice is that the WAIT, PARSE, EXEC and FETCH statements all have “tim=” values. These values provide the basis for a running timeline for the interval being traced (see Optimizing Oracle Performance for the best description of a trace file). Unfortunately the “tim=” values for the WAIT statements do not yet appear to make sense in the overall timing (this is apparently due to Oracle bug 8342329), and aren’t available in older releases. However this can be dealt with by keeping a running timeline and using the “ela=” or elapsed time values to supplement the timeline between PARSE, EXEC and FETCH statements. This is, in fact, the approach taken with the Interval Resource Profiler.
Now, what about slicing a trace file into intervals? Given that we’re only interested in the entire trace file interval and that we have a running timeline, we can create non-uniform intervals as long as we don’t “double count” recursive CPU time (again see Optimizing Oracle Performance for a description of double counting recursive statements). That leaves us with creating our interval “splits” between WAIT events or recursive depth zero PARSE, EXEC and FETCH statements. The side effect of this is that the event totals for each interval may or may not be the same, hence the non-uniform part. This ultimately affects the graph representation as well, and I’ll cover that in part 3. Adding this code to the Interval Resource Profiler was actually pretty easy since the timeline tracking and event summarization was already there.
The basic timeline tracking consists of checking to see if the start time has been set for statements with a “tim=” value that are not WAIT events. If the start time has not been set then the timeline is set to the current time minus any previously recorded WAIT event time. If it has been set then if the current time is less than the start time the start time is reset to the current time. Otherwise the end time is set (the normal situation) and a check is made to see if we’ve passed over an event time boundary, and if so then a new boundary time is set.
Timeline
#
# Track interval time start and end
#
if ($time_start == 0) {
$time_start = ($8 - $time_offset);
$time_offset = 0;
$time_end = $8;
$time_skew = $time_end;
}
elsif ($8 < $time_start) {
$time_start = $8;
}
else {
$time_end = $8;
#
# Adjust the skew interval
#
if (($time_end-$time_skew) > $time_skew_intvl) {
$time_skew = $time_end;
}
}
#
If a PARSE, EXEC or FETCH statement and the recursive depth is zero (i.e. dep = 0) then the CPU time “c=” is added to the appropriate event total for this interval (i.e. PARSE, EXEC or FETCH).
PARSE|EXEC|FETCH
#
# Track the interval events for P|E|F dep=0
#
if ($10 == 0) {
my $cmd = "'" . $1 . "'";
if (defined $intvl_skew->{$time_skew}->{$cmd}) {
$intvl_skew->{$time_skew}->{$cmd} += $3;
}
else {
$intvl_skew->{$time_skew}->{$cmd} = $3;
}
}
#
If this is a WAIT statement then the timeline consists of either adding the time to the “time_offset”, if the start time hasn’t been set, or adding it to the end time (in case no more tim= values are seen). The end time is then checked to see if we’ve passed over an event time boundary and if so then we set a new one.
WAITs
#
if ($time_start == 0) {
$time_offset = $ela;
}
$time_end += $ela;
#
# Adjust the skew interval
#
if (($time_end-$time_skew) > $time_skew_intvl) {
$time_skew = $time_end;
}
#
The elapsed time (i.e. “ela=”) is then added to the event time for this interval.
#
# Track the interval events
#
if (defined $intvl_skew->{$time_skew}->{$nam}) {
$intvl_skew->{$time_skew}->{$nam} += $ela;
}
else {
$intvl_skew->{$time_skew}->{$nam} = $ela;
}
#
The only hard part left is determining what the base interval time should be for the event timeline. The Interval Resource Profiler is a two pass parser, so currently the event timeline interval is calculated in pass one by taking the entire trace file interval time and dividing it by the desired number of event intervals, currently 20. Then in pass 2 the previously described logic is applied to calculate the event timeline using the interval as $time_skew_intvl.
Once the event timeline has been calculated, it’s just a matter of graphing the results. This can be done in Perl using the GD Graphics Library package, this was how the graph in part 1 was created, or the results can be output to a CSV file and input into an Excel spreadsheet. In either case a pivot on the data must be performed in order to get the event time as a column for each interval row in order to create the graph. This will be part of the discussion of Part 3.
Entries