Section 5.5. Walking the Clock
 |
5.5 Walking the Clock
As you try to extract response time information from raw trace data, you'll need to be able to interpret the time sequence of events using a process we call "walking the clock." Walking the clock requires a few pieces of knowledge about how the Oracle kernel manages time data:
-
The value of a line's tim field is the approximate time at which the action represented by that line completed .
-
A database call's e field value contains the total elapsed time consumed by that action. This value includes both the CPU time consumed by the action (the value of the c field) and the time consumed by events executed during the course of the action (the sum of the appropriate ela field values).
-
Recursive SQL causes double-counting . That is, the value of a database call's e field when dep= n + 1 is already included in the subsequent e value for which dep= n .
-
Don't expect perfection from clock walks. Off-by-one errors are common in Oracle8 i trace files. Errors of seemingly much greater magnitude are common in Oracle9 i trace files; however, with the microsecond timing resolution of Oracle9 i , the errors are smaller than they look.
5.5.1 Oracle Release 8 and Prior
Here is an example of some trace data that will demonstrate how to walk the clock through trace files emitted by Oracle8 i and prior kernels :
EXEC #13:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=3,tim=198360834 FETCH #13:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=2,og=3,tim=198360834 EXEC #12:c=2,e=4,p=0,cr=27,cu=0,mis=0,r=0,dep=1,og=4,tim=198360837 FETCH #12:c=2,e=10,p=10,cr=19,cu=4,mis=0,r=1,dep=1,og=4,tim=198360847
Table 5-7 shows the associated clock-walk.
Table 5-7. Walking the tim clock for Oracle8i database calls
| Line ( k ) | e | Predicted tim k = tim k -1 + e k | Actual tim k | Error |
|---|---|---|---|---|
| 1 |
| 198360834 | ||
| 2 |
| 198360834 + 0 = 198360834 | 198360834 |
|
| 3 | 4 | 198360834 + 4 = 198360838 | 198360837 | 1 |
| 4 | 10 | 198360837 + 10 = 198360847 | 198360847 |
|
Occasionally, there'll be an off-by-one error such as the one that distinguishes the predicted tim value in line 3 from the actual tim value found there. Don't let a ±1-cs error disturb you. Oracle8 i kernels round their time values to the nearest centisecond, so what appeared to be the addition of ...834 + 4 might actually have been the addition of ...833.7048 + 3.5827, which after rounding would have produced the observed value of ...837.
The following Oracle8 i trace file excerpt contains database calls and wait events:
PARSE #494:c=4,e=5,p=11,cr=88,cu=0,mis=1,r=0,dep=2,og=0,tim=3864619462 WAIT #494: nam='latch free' ela= 2 p1=-2147434220 p2=95 p3=0 WAIT #494: nam='latch free' ela= 2 p1=-2147434220 p2=95 p3=1 EXEC #494:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=3864619466 FETCH #494:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=1,dep=2,og=4,tim=3864619466
Table 5-8 shows the clock-walk of these lines. In the walk for this excerpt, notice that I've assigned k labels only to database call lines (not the WAIT lines). It's okay to track the anticipated progress of the tim clock during wait events, but remember that the e value in a database call already includes the time recorded in ela values for wait events motivated by the database call. Therefore, the basis for predicting a tim k value for a database call is always the tim k -1 from the prior database call line.
Table 5-8. Walking the tim clock for Oracle8i database calls and wait events
| Line ( k ) | e | Predicted tim k = tim k -1 + e k | Actual tim k | Error |
|---|---|---|---|---|
| 1 | 5 | 3864619462 | ||
| 2 | 3864619462 + 2 = 3864619464 | |||
| 2 | 3864619464 + 2 = 3864619466 | |||
| 2 | 4 | 3864619462 + 4 = 3864619466 | 3864619466 |
|
| 3 |
| 3864619466 + 0 = 3864619466 | 3864619466 |
|
Now for a tricky excerpt to make sure that you're paying attention. Can you explain why the actual tim value of 198360796 in the EXEC #8 line is so different from the value you might have expected, 198360795 + 19 = 198360814?
EXEC #9:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=3,tim=198360795 FETCH #9:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=2,og=3,tim=198360795 EXEC #9:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=3,tim=198360795 FETCH #9:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=2,og=3, tim=198360795 EXEC #8:c=4, e=19 ,p=16,cr=162,cu=0,mis=0,r=0,dep=1,og=4, tim=198360796 FETCH #8:c=0,e=5,p=4,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=198360801 FETCH #8:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,tim=198360801 FETCH #7:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=198360801 EXEC #8:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=198360801
The answer is that the EXEC #8 database call is the dep=1 recursive parent of each of the dep=2 actions shown here on cursor #9 . Therefore, the e=19 field contains all of the cursor #9 e values shown here plus some other time-consuming activities that are not shown here. The EXEC #8 action probably began very near tim 198360796 - 19 = 198369777. Between tim values ...777 and ...796, lots of dep=2 actions took place, each consuming time while the tim clock advanced. But remember, these dep=2 actions all took place during the single EXEC #8 action.
5.5.2 Oracle Release 9
The microsecond output resolution of time statistics in Oracle9 i is a helpful enhancement. The first thing you'll notice about SQL trace data when you upgrade to Oracle9 i is that the microsecond resolution feature provides real data for cases in which Oracle8 i would have emitted lots of zero values.
|
The new resolution has allowed us to see a little more clearly into the Oracle kernel's behavior. This section describes a few cases in which we've been able to learn more as a result of the Oracle kernel's improved output resolution.
Walking the clock in Oracle9 i trace files requires a little more patience. The first difference you'll notice is that the numbers are all so much larger that it's quite a bit more difficult to do the walk in your head. For example:
EXEC #1:c=0,e=1863,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1017039275956134 FETCH #1:c=0,e=2566,p=0,cr=23,cu=0,mis=0,r=1,dep=1,og=4,tim=1017039275958821 FETCH #1:c=0,e=50,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1017039275959013 FETCH #1:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1017039275959155 FETCH #1:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1017039275959293 FETCH #1:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1017039275959433
The next thing that you might notice is that the numbers don't add up. Observe the large numbers that show up in the "Error" column of Table 5-9.
Table 5-9. Walking the tim clock for Oracle9i database calls. Notice the apparently large error values, but remember that the errors here are actually quite small because they're expressed in microseconds
| Line ( k ) | e | Predicted tim k = tim k -1 + e k | Actual tim k | Error |
|---|---|---|---|---|
| 1 | 1863 | ...956134 | ||
| 2 | 2566 | ...956134 + 2566 = ...958700 | ...958821 | - 121 |
| 3 | 50 | ...958821 + 50 = ...958871 | ...959013 | - 142 |
| 4 | 34 | ...959013 + 34 = ...959047 | ...959155 | - 108 |
| 5 | 34 | ...959155 + 34 = ...959189 | ...959293 | - 104 |
| 6 | 35 | ...959293 + 35 = ...959328 | ...959433 | - 105 |
The sensation produced by these large error values is quite horrific until you realize that the errors are expressed in microseconds. Small time gap errors like this have always been present in Oracle diagnostic data. They were usually invisible when measured with centisecond resolution. When we view microsecond timing data, the impact of another type of response time measurement error becomes apparent: the calls to gettimeofday and getrusage consume elapsed time that the calls themselves do not measure (see the Chapter 7 discussion of the measurement intrusion effect ).
In Oracle9 i trace files, you might notice the " disturbing " fact that not all trace lines are listed in ascending time order. Specifically, the tim value for a PARSING IN CURSOR section always occurs in the future relative to the tim value of the database call immediately following the PARSING IN CURSOR section. For example:
PARSING IN CURSOR #1 len=32 dep=0 uid=5 oct=42 lid=5 tim=1033050389 206593 hv=1197935484 ad='50f93654' alter session set sql_trace=true END OF STMT EXEC #1:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1033050389 204497
You can confirm why this occurs by tracing the wait events of an Oracle kernel process with strace or a similar tool. The Oracle kernel finishes processing the EXEC call before it begins computing the information for the PARSING IN CURSOR section. But then the kernel prints the PARSING IN CURSOR section before it prints the EXEC line. Hence, the times appear out of order.
You'll find that the Oracle8 i kernel does things in this order as well. You just didn't notice, because the centisecond statistics emitted by Oracle8 i in most cases concealed the true time sequence information from you. With the microsecond statistics emitted by Oracle9 i , the order becomes apparent.
5.5.3 Clock Walk Formulas
After having seen a few clock-walk examples, you have probably caught onto the formula. As long as you remember not to double-count in the presence of different levels of recursive database calls, then the values of the tim and e fields bear the following relationship:
- tim k +1
tim k + e k +1
That is, the following line's tim field value is approximately this line's tim field value plus the following line's e field value. Equivalently, you can write:
- tim k tim k +1 - e k +1
That is, the current line's tim field value approximately equals the following line's tim field value minus the following line's e field value.
Of course, a WAIT line has no tim field, so if you want to estimate what a WAIT line's tim value would be, you have to estimate it by walking the clock forward from the most recently available tim value, using the relationship:
- tim k +1 tim k + ela k +1
These formulas will come in handy when you learn how to correct for data collection error in Chapter 7.
| |
| Top |
EAN: 2147483647
Pages: 102