When a process in user mode makes an operating system call (a sys call), it transitions to kernel mode. read and select are two typical system calls. Once in kernel mode, a process is endowed with special privileges that allow it to manipulate low-level hardware components and arbitrary memory locations. In kernel mode, a process is able, for example, to manipulate I/O devices like sockets and disk drives [Bovet and Cesati (2001) 8].

Many types of system call can be expected to wait on a device for many, many CPU cycles. For example, a read call of a disk subsystem today typically consumes time on the order of a few milliseconds. Many CPUs today can execute millions of instructions in the time it takes to execute one physical disk I/O operation. So during a single read call, enough time to perform on the order of a million CPU instructions will elapse. Designers of efficient read system calls of course realize this and design their code in a manner that allows another process to use the CPU while the reading process waits.

Imagine, for example, an Oracle kernel process executing some kind of read system call to obtain a block of Oracle data from a disk. After issuing a request from an expectedly “slow” device, the kernel code in the read system call will transition its calling process into the sleep state, where that process will await an interrupt signaling that the I/O operation is complete. This polite yielding of the CPU allows another ready to run process to consume the CPU capacity that the reading process would have been unable to use anyway.

When the I/O device signals that the asleep process’s I/O operation is ready for further processing, the process is “awoken,” which is to say that it transitions to ready to run state. When the process becomes ready to run, it becomes eligible for scheduling. When the scheduler again chooses the process for execution, the process is returned to kernel running state, where the remaining kernel mode code path of the read call is executed (for example, the data transfer of the content obtained from the I/O channel into memory). The final instruction in the read subroutine returns control to the calling program (our Oracle kernel process), which is to say that the process transitions back into user running state. In this state, the Oracle kernel process continues consuming user-mode CPU until it next receives an interrupt or makes a system call.

The second path through the operating system process state diagram is motivated by an interrupt. An interrupt is a mechanism through which a device such as an I/O peripheral or the system clock can interrupt the CPU asynchronously [Bach (1986) 16]. I’ve already described why an I/O peripheral might interrupt a process. Most systems are configured so that the system clock generates an interrupt every 1/100^th of a second (that is, once per centisecond). Upon receipt of a clock interrupt, each process on the system in user running state saves its context (a frozen image of what the process was doing) and executes the operating system scheduler subroutine. The scheduler determines whether to allow the process to continue running or to preempt the process.

Preemption essentially sends a process directly from kernel running state to ready to run state, clearing the way for some other ready to run process to return to user running state [Bach (1986) 148]. This is how most modern operating systems implement time-sharing. Any process in ready to run state is subject to treatment that is identical to what I have described previously. The process becomes eligible for scheduling, and so on. Your understanding of preemptions motivated by clock interrupts will become particularly important later in this chapter when I describe one of the most important causes of “missing data” in an Oracle trace file.

I have already alluded to the existence of a more complicated process state transition diagram than I’ve shown in Figure 7-1. Indeed, after discussing the four process states and seven of the transitions depicted in Figure 7-1, Bach later in his book reveals a more complete process state transition diagram [Bach (1986) 148]. The more complicated diagram details the actions undertaken during transitions such as preempting, swapping, forking, and even the creation of zombie processes. If you run applications on Unix systems, I strongly encourage you to add Bach’s book to your library.

For the purposes of the remainder of this chapter, however, Figure 7-1 is all you need. I hope you will agree that it is easy to learn the precise definitions of Oracle timing statistics by considering them in terms of the process states shown in Figure 7-1.

The Oracle kernel derives all of its timing statistics from the results of system calls issued upon the host operating system. Example 7-1 shows how a program like the Oracle kernel computes the durations of its own actions.

t0 = gettimeofday;   # mark the time immediately before doing something
do_something;
t1 = gettimeofday;   # mark the time immediately after doing it
t = t1 - t0;         # t is the approximate duration of do_something

The gettimeofday function is an operating system call found on POSIX-compliant systems. You can learn by viewing your operating system’s documentation that gettimeofday provides a C language data structure to its caller that contains the number of seconds and microseconds that have elapsed since the Epoch, which is 00:00:00 Coordinated Universal Time (UTC), January 1, 1970.

Imagine the execution of Example 7-1 on a timeline, as shown in Figure 7-2. In the drawing, the value of the gettimeofday clock is t ₀ = 1492 when a function called do_something begins. The value of the gettimeofday clock is t ₁ = 1498 when do_something ends. Thus the measured duration of do_something is t = t ₁ - t ₀ = 6 clock ticks.

Figure 7-2. The function called do_something begins after clock tick 1492 and ends after clock tick 1498, resulting in a measured response time of 6 clock ticks

The Oracle kernel reports on two types of elapsed duration: the e statistic denotes the elapsed duration of a single database call, and the ela statistic denotes the elapsed duration of an instrumented sequence of instructions (often a system call) executed by an Oracle kernel process. The kernel performs these computations by executing code that is structured roughly like the pseudocode shown in Example 7-2. Notice that the kernel uses the method shown in Example 7-1 as the basic building block for constructing the e and ela metrics.

procedure dbcall {
    e0 = gettimeofday;      # mark the wall time
    ...                     # execute the db call (may call wevent)
    e1 = gettimeofday;      # mark the wall time
    e = e1 - e0;            # elapsed duration of dbcall
    print(TRC, ...);        # emit PARSE, EXEC, FETCH, etc. line
}
   
procedure wevent {
    ela0 = gettimeofday;    # mark the wall time
    ...                     # execute the wait event here
    ela1 = gettimeofday;    # mark the wall time
    ela = ela1 - ela0;      # ela is the duration of the wait event
    print(TRC, "WAIT...");  # emit WAIT line
}

The Oracle kernel reports not only the elapsed duration e for each database call and ela for each system call, but also the amount of total CPU capacity c consumed by each database call. In the context of the process state transition diagram shown in Figure 7-1, the c statistic is defined as the approximate amount of time that a process has spent in the following states:

On POSIX-compliant operating systems, the Oracle kernel obtains CPU usage information from a function called getrusage on Linux and many other operating systems, or a similar function called times on HP-UX and a few other systems. Although the specifications of these two system calls vary significantly, I will use the name getrusage to refer generically to either function. Each function provides its caller with a variety of statistics about a process, including data structures representing the following four characteristics:

Each of these amounts is expressed in microseconds, regardless of whether the data are accurate to that degree of precision.

The Oracle kernel performs c, e, and ela computations by executing code that is structured roughly like the pseudocode shown in Example 7-3. Notice that this example builds upon Example 7-2 by including executions of the getrusage system call and the subsequent manipulation of the results. In a method analogous to the gettimeofday calculations, the Oracle kernel marks the amount of user-mode CPU time consumed by the process at the beginning of the database call, and then again at the end. The difference between the two marks (c0 and c1) is the approximate amount of CPU capacity that was consumed by the database call. Shortly I’ll fill you in on exactly how approximate the amount is.

procedure dbcall {
    e0 = gettimeofday;          # mark the wall time
    c0 = getrusage;             # obtain resource usage statistics
    ...                         # execute the db call (may call wevent)
    c1 = getrusage;             # obtain resource usage statistics
    e1 = gettimeofday;          # mark the wall time
    e = e1 - e0;                # elapsed duration of dbcall
    c = (c1.utime + c1.stime)
      - (c0.utime + c0.stime);  # total CPU time consumed by dbcall
    print(TRC, ...);            # emit PARSE, EXEC, FETCH, etc. line
}
   
procedure wevent {
    ela0 = gettimeofday;        # mark the wall time
    ...                         # execute the wait event here
    ela1 = gettimeofday;        # mark the wall time
    ela = ela1 - ela0;          # ela is the duration of the wait event
    print(TRC, "WAIT...");      # emit WAIT line
}

When I was a kid, one of the everyday benefits of growing up in the Space Age was the advent of the digital alarm clock. Digital clocks are fantastically easy to read, even for little boys who don’t yet know how to “tell the time.” It’s hard to go wrong when you can see those big red numbers showing “7:29”. With an analog clock, a kid sometimes has a hard time knowing whether it’s five o’clock and seven o’clock, but the digital difference between 5 and 7 is unmistakable.

But there’s a problem with digital clocks. When you glance at a digital clock that shows “7:29”, how close is it to 7:30? The problem with digital clocks is that you can’t know. With a digital clock, you can’t tell whether it’s 7:29:00 or 7:29:59 or anything in-between. With an analog clock, even one without a second-hand, you can guess about fractions of minutes by looking at how close the minute hand is to the next minute.

All times measured on digital computers derive ultimately from interval timers, which behave like the good old digital clocks at our bedsides. An interval timer is a device that ticks at fixed time intervals. Times collected from interval timers can exhibit interesting idiosyncrasies. Before you can make reliable decisions based upon Oracle timing data, you need to understand the limitations of interval timers.

An interval timer’s resolution is the elapsed duration between adjacent clock ticks. Timer resolution is the inverse of timer frequency. So a timer that ticks at 1 GHz (approximately 10⁹ ticks per second) has a resolution of approximately 1/10⁹ seconds per tick, or about 1 nanosecond (ns) per tick. The larger a timer’s resolution, the less detail it can reveal about the duration of a measured event. But for some timers (especially ones involving software), making the resolution too small can increase system overhead so much that you alter the performance behavior of the event you’re trying to measure.

As a timing statistic passes upward from hardware through various layers of application software, each application layer can either degrade its resolution or leave its resolution unaltered. For example:

Thus, each e and ela statistic emitted by an Oracle8i kernel actually represents a system characteristic whose actual value cannot be known exactly, but which resides within a known range of values. Such a range of values is shown in Table 7-1. For example, the Oracle8i statistic e=2 can refer to any actual elapsed duration e _a in the range:

Quantization error is the quantity E defined as the difference between an event’s actual duration e _a and its measured duration e _m . That is:

Let’s revisit the execution of Example 7-1 superimposed upon a timeline, as shown in Figure 7-5. In this drawing, each tick mark represents one clock tick on an interval timer like the one provided by gettimeofday. The value of the timer was t ₀ = 1492 when do_something began. The value of the timer was t ₁ = 1498 when do_something ended. Thus the measured duration of do_something was e _m = t ₁ - t ₀ = 6. However, if you physically measure the length of the duration e _a in the drawing, you’ll find that the actual duration of do_something is e _a = 5.875 ticks. You can confirm the actual duration by literally measuring the height of e _a in the drawing, but it is not possible for an application to “know” the value of e _a by using only the interval timer whose ticks are shown in Figure 7-5. The quantization error is E = e _m - e _a = 0.125 ticks, or about 2.1 percent of the 5.875-tick actual duration.

Figure 7-5. An interval timer is accurate for measuring durations of events that span many clock ticks

Now, consider the case when the duration of do_something is much closer to the timer resolution, as shown in Figure 7-6. In the left-hand case, the duration of do_something spans one clock tick, so it has a measured duration of e _m = 1. However, the event’s actual duration is only e _a = 0.25. (You can confirm this by measuring the actual duration in the drawing.) The quantization error in this case is E = 0.75, which is a whopping 300% of the 0.25-tick actual duration. In the right-hand case, the execution of do_something spans no clock ticks, so it has a measured duration of e _m = 0; however, its actual duration is e _a = 0.9375. The quantization error here is E = -0.9375, which is -100% of the 0.9375-tick actual duration.

Figure 7-6. An interval timer is not accurate for measuring durations of events that span zero or only a few clock ticks

To describe quantization error in plain language:

More formally, the difference between any two digital clock measurements is an elapsed duration with quantization error whose exact value cannot be known, but which ranges anywhere from almost -1 clock tick to almost +1 clock tick. If we use the notation r _x to denote the resolution of some timer called x, then we have:

The quantization error E inherent in any digital measurement is a uniformly distributed random variable (see Chapter 11) with range -r _x < E < r _x , where r _x denotes the resolution of the interval timer.

Whenever you see an elapsed duration printed by the Oracle kernel (or any other software), you must think in terms of the measurement resolution. For example, if you see the statistic e=4 in an Oracle8i trace file, you need to understand that this statistic does not mean that the actual elapsed duration of something was 4 cs. Rather, it means that if the underlying timer resolution is 1 cs or better, then the actual elapsed duration of something was between 3 cs and 5 cs. That is as much detail as you can know.

For small numbers of statistic values, this imprecision can lead to ironic results. For example, you can’t actually even make accurate comparisons of event durations for events whose measured durations are approximately equal. Figure 7-7 shows a few ironic cases. Imagine that the timer shown here is ticking in 1-centisecond intervals. This is behavior that is equivalent to the Oracle8i practice of truncating digits of timing precision past the 0.01-second position. Observe in this figure that event A consumed more actual elapsed duration than event B, but B has a longer measured duration; C took longer than D, but D has a longer measured duration. In general, any event with a measured duration of n + 1 may have an actual duration that is longer than, equal to, or even shorter than another event having a measured duration of n. You cannot know which relationship is true.

Figure 7-7. Any duration measured with an interval timer is accurate only to within one unit of timer resolution. Notice that events measured as n clock ticks in duration can actually be longer than events measured as n + 1 ticks in duration

An interval timer can give accuracy only to ±1 clock tick, but in practical application, this restriction does not diminish the usefulness of interval timers. Positive and negative quantization errors tend to cancel each other over large samples. For example, the sum of the quantization errors in Figure 7-6 is:

Even though the individual errors were proportionally large, the sum of the errors is a much smaller 16% of the sum of the two actual event durations. In a several hundred SQL trace files collected at http://www.hotsos.com from hundreds of different Oracle sites, we have found that positive and negative quantization errors throughout a trace file with hundreds of lines tend to cancel each other out. Errors commonly converge to magnitudes smaller than ±10% of the total response time measured in a trace file.

You may have noticed by now that your gettimeofday system call has much better resolution than getrusage. Although the pseudocode in Example 7-3 makes it look like gettimeofday and getrusage do almost the same thing, the two functions work in profoundly different ways. As a result, the two functions produce results with profoundly different accuracies.

How getrusage works

There are two ways in which an operating system can account for how much time a process spends consuming user-mode or kernel-mode CPU capacity:

Polling (sampling)

The operating system could be instrumented with extra code so that, at fixed intervals, each running process could update its own rusage table. At each interval, each running process could update its own CPU usage statistic with the estimate that it has consumed the entire interval’s worth of CPU capacity in whatever state the processes is presently executing in.

Event-based instrumentation

The operating system could be instrumented with extra code so that every time a process transitions to either user running or kernel running state, it could issue a high-resolution timer call. Every time a process transitions out of that state, it could issue another timer call and publish the microseconds’ worth of difference between the two calls to the process’ rusage accounting structure.

Most operating systems use polling, at least by default. For example, Linux updates several attributes for each process, including the CPU capacity consumed thus far by the process, upon every clock interrupt [Bovet and Cesati (2001) 144-145]. Some operating systems do provide event-based instrumentation. Sun Solaris, for example, provides this feature under the name microstate accounting [Cockroft (1998)].

With microstate accounting, quantization error is limited to one unit of timer resolution per state switch. With a high-resolution timer (like gettimeofday), the total quantization error on CPU statistics obtained from microstate accounting can be quite small. However, the additional accuracy comes at the cost of incrementally more measurement intrusion effect. With polling, however, quantization error can be significantly worse, as you’ll see in a moment.

Regardless of how the resource usage information is obtained, an operating system makes this information available to any process that wants it via a system call like getrusage. POSIX specifies that getrusage must use microseconds as its unit of measure, but—for systems that obtain rusage information by polling—the true resolution of the returned data depends upon the clock interrupt frequency.

The clock interrupt frequency for most systems is 100 interrupts per second, or one interrupt every centisecond (operating systems texts often speak in terms of milliseconds; 1 cs = 10 ms = 0.010 s). The clock interrupt frequency is a configurable parameter on many systems, but most system managers leave it set to 100 interrupts per second. Asking a system to service interrupts more frequently than 100 times per second would give better time measurement resolution, but at the cost of degraded performance. Servicing interrupts even only ten times more frequently would intensify the kernel-mode CPU overhead consumed by the operating scheduler by a factor of ten. It’s generally not a good tradeoff.

If your operating system is POSIX-compliant, the following Perl program will reveal its operating system scheduler resolution [Chiesa (1996)]:

$ cat clkres.pl
#!/usr/bin/perl
use strict;
use warnings;
use POSIX qw(sysconf _SC_CLK_TCK);
my $freq = sysconf(_SC_CLK_TCK);
my $f = log($freq) / log(10);
printf "getrusage resolution %.${f}f seconds
", 1/$freq;
$ perl clkres.pl
getrusage resolution: 0.01 seconds

With a 1-cs clock resolution, getrusage may return microsecond data, but those microsecond values will never contain valid detail smaller than 1/100^th (0.01) of a second.

The reason I’ve explained all this is that the quantization error of the Oracle c statistic is fundamentally different from the quantization error of an e or ela statistic. Recall when I wrote:

Any duration measured with an interval timer is accurate only to within one unit of timer resolution.

The problem with Oracle’s c statistic is that the statistic returned by getrusage is not really a duration. That is, a CPU consumption “duration” returned by getrusage is not a statistic obtained by taking the difference of a pair of interval timer measurements. Rather:

• On systems with microstate accounting activated, CPU consumption is computed as potentially very many short durations added together.

• On systems that poll for rusage information, CPU consumption is an estimate of duration obtained by a process of polling.

Hence, in either circumstance, the quantization error inherent in an Oracle c statistic can be much worse than just one clock tick. The problem exists even on systems that use microstate accounting. It’s worse on systems that don’t.

Figure 7-8 depicts an example of a standard polling-based situation in which the errors in user-mode CPU time attribution add up to cause an over-attribution of time to a database call’s response time. The sequence diagram in this figure depicts both the user-mode CPU time and the system call time consumed by a database call. The CPU axis shows clock interrupts scheduled one cs apart. Because the drawing is so small, I could not show the 10,000 clock ticks on the non-CPU time consumer axis that occur between every pair of ticks on the CPU axis.

Figure 7-8. The way getrusage polls for CPU consumption can cause over-attributions of response time to an individual database call

In response to the actions depicted in Figure 7-8, I would expect an Oracle9i kernel to emit the trace data shown in Example 7-5. I computed the expected e and ela statistics by measuring the durations of the time segments on the sys call axis. Because of the fine resolution of the gettimeofday clock with which e and ela durations are measured, the quantization error in my e and ela measurements is negligible.

Example 7-5. The Oracle9i timing statistics that would be generated by the events depicted in Figure 7-8

WAIT #1: ...ela= 6250
WAIT #1: ...ela= 6875
WAIT #1: ...ela= 32500
WAIT #1: ...ela= 6250
FETCH #1:c=60000,e=72500,...

The actual amount of CPU capacity consumed by the database call was 2.5 cs, which I computed by measuring durations physically in the picture. However, getrusage obtains its CPU consumption statistic from a process’s resource usage structure, which is updated by polling at every clock interrupt. At every interrupt, the operating system’s process scheduler tallies one full centisecond (10,000 μs) of CPU consumption to whatever process is running at the time. Thus, getrusage will report that the database call in Figure 7-8 consumed six full centiseconds’ worth of CPU time. You can verify the result by looking at Figure 7-8 and simply counting the number of clock ticks that are spanned by CPU consumption.

It all makes sense in terms of the picture, but look at the unaccounted-for time that results:

Negative unaccounted-for time means that there is a negative amount of “missing time” in the trace data. In other words, there is an over-attribution of 39,375 μs to the database call. It’s an alarmingly large-looking number, but remember, it’s only about 4 cs. The actual amount of user-mode CPU that was consumed during the call was only 25,000 μs (which, again, I figured out by cheating—by measuring the physical lengths of durations depicted in Figure 7-8).

Quantization error E = e _m - e _a is the difference between an event’s actual duration e _a and its measured duration e _m . You cannot know an event’s actual duration; therefore, you cannot detect quantization error by inspecting an individual statistic. However, you can prove the existence of quantization error by examining groups of related statistics. You’ve already seen an example in which quantization error was detectable. In Example 7-5, we could detect the existence of quantization error by noticing that:

It is easy to detect the existence of quantization error by inspecting a database call and the wait events executed by that action on a low-load system, where other influences that might disrupt the e ≈ c + Σ ela relationship are minimized.

The following Oracle8i trace file excerpt shows the effect of quantization error:

WAIT #103: nam='db file sequential read' ela= 0 p1=1 p2=3051 p3=1
WAIT #103: nam='db file sequential read' ela= 0 p1=1 p2=6517 p3=1
WAIT #103: nam='db file sequential read' ela= 0 p1=1 p2=5347 p3=1
FETCH #103:c=0,e=1,p=3,cr=15,cu=0,mis=0,r=1,dep=2,og=4,tim=116694745

This fetch call motivated exactly three wait events. We know that the c, e, and ela times shown here should be related by the approximation:

On a low-load system, the amount by which the two sides of this approximation are unequal is an indication of the total quantization error present in the five measurements (one c value, one e value, and three ela values):

Given that individual gettimeofday calls account for only a few microseconds of measurement intrusion error on most systems, quantization error is the prominent factor contributing to the 1-centisecond (cs) “gap” in the trace data.

The following Oracle8i trace file excerpt shows the simplest possible over-counting of elapsed time, resulting in a negative amount of unaccounted-for time:

WAIT #96: nam='db file sequential read' ela= 0 p1=1 p2=1691 p3=1
FETCH #96:c=1,e=0,p=1,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=116694789

Here, we have E = -1 cs:

In this case of a “negative gap” like the one shown here, we cannot appeal to the effects of measurement intrusion for explanation; the measurement intrusion effect can create only positive unaccounted-for time. It might have been possible that a CPU consumption double-count had taken place; however, this isn’t the case here, because the value ela= 0 means that no CPU time was counted in the wait event at all. In this case, quantization error has had a dominating influence, resulting in the over-attribution of time within the fetch.

Although Oracle9i uses improved output resolution in its timing statistics, Oracle9i is by no means immune to the effects of quantization error, as shown in the following trace file excerpt with E > 0:

WAIT #5: nam='db file sequential read' ela= 11597 p1=1 p2=42463 p3=1
FETCH #5:c=0,e=12237,p=1,cr=3,cu=0,mis=0,r=1,dep=2,og=4,tim=1023745094799915

In this example, we have E = 640 μs:

Some of this error is certainly quantization error (it’s impossible that the total CPU consumption of this fetch was actually zero). A few microseconds are the result of measurement intrusion error.

Finally, here is an example of an E < 0 quantization error in Oracle9i trace data:

WAIT #34: nam='db file sequential read' ela= 16493 p1=1 p2=33254 p3=1
WAIT #34: nam='db file sequential read' ela= 11889 p1=2 p2=89061 p3=1
FETCH #34:c=10000,e=29598,p=2,cr=5,cu=0,mis=0,r=1,dep=3,og=4,tim=1017039276445157

In this case, we have E = -8784 μs:

It is possible that some CPU consumption double-counting has occurred in this case. It is also likely that the effect of quantization error is a dominant contributor to the attribution of time to the fetch call. The 8,784-μs over-attribution is evidence that the actual total CPU consumption of the database call was probably only about (10,000 - 8,784) μs = 1,216 μs.

The amount of quantization error present in Oracle’s timing statistics cannot be measured directly. However, the statistical properties of quantization error can be analyzed in extended SQL trace data. First, there’s a limit to how much quantization error there can be in a given set of trace data. It is easy to imagine the maximum quantization error that a set of elapsed durations like Oracle’s e and ela statistics might contribute. The worst total quantization error for a sequence of e and ela statistics occurs when all the individual quantization errors are at their maximum magnitude and the signs of the quantization errors all line up.

Figure 7-9 exhibits the type of behavior that I’m describing. This drawing depicts eight very-short-duration system calls that happen to all cross an interval timer’s clock ticks. The actual duration of each event is practically zero, but the measured duration of each event is one clock tick. The total actual duration of the system calls shown is practically zero, but the total measured duration is 8 clock ticks. For this set of n = 8 system calls, the total quantization error is essentially nr _x , where r _x is, as described previously, the resolution of the interval timer upon which the x characteristic is measured.

Figure 7-9. A worst-case type scenario for the accumulation of quantization error for a sequence of measured durations

It shouldn’t take you long to notice that the situation in Figure 7-9 is horribly contrived to suit my purpose of illustrating a point. For things to work out this way in reality is extremely unlikely. The probability that n quantization errors will all have the same sign is only 0.5 ⁿ . The probability of having n = 8 consecutive negative quantization errors is only 0.00390625 (that’s only about four chances in a thousand). There’s less than one chance in 10⁸⁰ that n = 266 statistics will all have quantization errors with the same sign.

For long lists of elapsed duration statistics, it is virtually impossible for all the quantization errors to “point in the same direction.” Yet, my contrivance in Figure 7-9 goes even further. It assumes that the magnitude of each quantization error is maximized. The odds of this happening are even more staggeringly slim than for the signs to line up. For example, the probability that the magnitude of each of n given quantization error values exceeds 0.9 is only (1 - 0.9) ⁿ . The odds of having each of n = 266 quantization error magnitudes exceed 0.9 are one in 10²⁶⁶.

For n quantization errors to all have the same sign and all have magnitudes greater than m, the probability is the astronomically unlikely product of both probabilities I’ve described:

Quantization errors for elapsed durations (like Oracle e and ela statistics) are random numbers in the range:

where r _x is the resolution of the interval timer from which the x statistic (where x is either e or ela) is obtained.

Because negative and positive quantization errors occur with equal probability, the average quantization error for a given set of statistics tends toward zero, even for large trace files. Using the central limit theorem developed by Pierre Simon de Laplace in 1810, you can even predict the probability that quantization errors for Oracle e and ela statistics will exceed a specified threshold for a trace file containing a given number of statistics.

I’ve begun work to compute the probability that a trace file’s total quantization error (including the error contributed by c statistics) will exceed a given threshold; however, I have not yet completed that research. The problem in front of me is to calculate the distribution of the quantization error produced by c, which, as I’ve said already, is complicated by the nature of how c is tallied by polling. I intend to document my research in this area in a future project.

Happily, there are several pieces of good news about quantization error that make not yet knowing how to quantify it quite bearable:

Sometimes, the effect of quantization error can cause loss of faith in the validity of Oracle’s trace data. Perhaps nothing can be more damaging to your morale in the face of a tough problem than to gather the suspicion that the data you’re counting on might be lying to you. A firm understanding of the effects of quantization error is possibly your most important tool in keeping your faith.

Let’s assume that we had instrumented our code in a manner similar to how the Oracle kernel does it, as I’ve shown in Example 7-6.

e0 = gettimeofday;
c0 = getrusage;
P;                        # remember, P makes no system calls
c1 = getrusage;
e1 = gettimeofday;
e = e1 - e0;
c = (c1.stime + c1.utime) - (c0.stime + c0.utime);
printf "e=%.0fs, c=%.0fs
", e, c;

Then we should expect approximately the timing output shown in Table 7-2 for each given concurrency level on a single-CPU system. You should expect our program P to consume the same amount of total CPU capacity, regardless of how busy the system is. But of course, since the CPU capacity of the system is being shared more and more thinly across users as we increase the concurrency level, you should expect for the program to execute for longer and longer elapsed times before being able to obtain the ten seconds of CPU time that it needs.

The table shows what we expected to see, but notice that we now have created a “problem with missing time” in some of our measurements. Remember our performance model: the elapsed time of a program is supposed to approximately equal the time spent consuming CPU capacity plus the time spent executing instrumented “wait events,” as in:

However, even in the two-user case, this works out to:

We can use the substitution ela = 0 because we know our program executes no instrumented “wait events” whatsoever. All our program does is consume some CPU capacity and then print the result. (And even the printf statement can be eliminated as a suspect because the call to it occurs outside of the domain of the timer calls.) As you can plainly see, c + Σ ela = 10 is a really lousy approximation of e = 20. Where did the “missing time” go? In our Table 7-2 cases, the problem just keeps getting worse as user concurrency increases. Where have we gone wrong in our instrumentation of P?

The answer is easy to understand after looking again at Figure 7-1. Recall that even when a process is executing happily along in user running state, a system clock interrupt occurs on most systems every 1/100^th of a second. This regularly scheduled interrupt transitions each running process into the kernel running state to service the interrupt. Once in kernel running state, the process saves its current context and then executes the scheduler subroutine (see Section 7.1.2 earlier in this chapter). If there is a process in the ready to run state, then the system’s scheduling policy may dictate that the running process must be preempted, and the ready to run process be scheduled and given an opportunity to consume CPU capacity itself.

When this happens, note what happens to our originally running process. When it is interrupted, it is transitioned immediately to kernel running state. Note in particular that the process does not get the chance to execute any application code to see what time it is when this happens. When the process is preempted, it is transitioned to ready to run state, where it waits until it is scheduled. When it is finally scheduled (perhaps only a mere 10 milliseconds later), it spends enough time in kernel running state to reinstate its context, and then it returns to user running state, right where it left off.

How did the preemption activity affect the timing data for the process? The CPU time spent in kernel running state while the scheduler was preparing for the process’s preemption counts as CPU time consumed by the process. But time spent in ready to run state did not count as CPU time consumed by the process. However, when the process had completed its work on P, the difference e=e1-e0 of course included all time spent in all states of the process state transition diagram. The net effect is that all the time spent in ready to run state continues to tally on the e clock, but it’s not accounted for as CPU capacity consumption, or for anything else that the application is aware of for that matter. It’s as if the process had been conked on the head and then awoken, with no way to account for what happened to the time spent out of consciousness.

This is what happens to each process as more concurrent processes were added to the mix shown in Table 7-2. Of course, the more processes there were waiting in ready to run state, the more each process had to wait for its turn at the CPU. The longer the wait, the longer the program’s elapsed time. For three and four users, the unaccounted-for time increases proportionally. It’s simply a problem of a constant-sized pie (CPU capacity) being divvied up among more and more pie-eaters (users running P). There’s really nothing in need of “repair” about the instrumentation upon P. What you need is to understand how to estimate how much of the unaccounted-for time is likely to be due to time spent not executing.

The existence and exact size of this gap is of immense value to the Oracle performance analyst. The size of this gap permits you to use extended SQL trace data to identify when performance problems are caused by excessive swapping or time spent in the CPU run queue.

When Oracle Corporation leaves a sequence of kernel instructions un-instrumented, the missing time becomes apparent in one of two ways:

In practice you may never encounter a situation in which un-instrumented system calls will consume an important proportion of a program’s elapsed time. We encounter the phenomenon at a rate of fewer than five per thousand trace files at http://www.hotsos.com. One case of un-instrumented database activity is documented as bug number 2425312 at Oracle MetaLink. You may encounter this bug if you trace Oracle Forms applications with embedded (client-side) PL/SQL. You will perhaps encounter other cases in which un-instrumented time materially affects your analysis, but those cases will be rare.

You will encounter at least one un-instrumented system call every time you use SQL trace, although its performance impact is usually small. It is the write call that the Oracle kernel uses to write SQL trace output to the trace file. Using strace allows you to see quite plainly how the Oracle kernel writes each line of data to a trace file. Of the several hundred extended SQL trace files collected at http://www.hotsos.com by the time of this writing, fewer than 1% exhibit accumulation of unaccounted-for time that might be explained by slow trace file writing. However, you should follow these recommendations to reduce the risk that the very act of tracing an application program will materially degrade the performance of an application:

Don’t let the overhead of writing to trace files deter you from using extended SQL trace data as a performance diagnostic tool. Keep the overhead in perspective. The potential overhead is not noticeable in most cases. Even if the performance overhead were nearly unbearable, the overhead of tracing a program once is a worthwhile investment if the diagnosis results in either of the following outcomes: