Peeking into Oracle using Linux tracing tools – five tools in five minutes

Five tools in five minutes?

What’s that supposed to mean, you will be asking! Well, one week ago at Trivadis Tech Event, I had the honor of being invited to participate in the Oracle Lightning Talks session organised by my colleague Ludovico Caldara, where every topic has to be presented in five minutes (which of course makes for quite an interesting “listening experience” for the audience …).
To sort of “maximize the mismatch”, I chose to present on Linux tracing tools – not one (normally you’d need hours to explain just one) – but five, one for every minute 😉

So here’s my personal list of appetizers, you’ll find some links at the end to really get you started:

strace

So, strace, you will be thinking, that sounds a bit boring, doesn’t it? Well, perhaps, but it’s a good tool to start an investigation. Oracle has its “wait event lingo”, – but what’s going on underneath?
Here for example, we’re stracing the CKPT process, who says he’s doing a control file parallel write. With strace we can see the asynchronous IO request it issued (io_submit), the two file descriptors it was issued to, and how the process waits for completion in a blocking IO call (io_getevents):

$ strace -tt -f -e write=all -v -s 100 -p $(pgrep ora_ckpt)

So strace can be useful, but beware, it will slow down the process being traced – check out Brendan Gregg’s post “Strace Wow Much Syscall” (nice title isn’t it ;-)) listed in the appendix. Speaking of whom …

https://github.com/brendangregg/perf-tools

… Brendan Gregg has a very nice collection of scripts on github, following the unix/linux philosophy, “one tool one purpose”.
Here, for example, I’m using iolatency to get a meaningful representation of IO latencies to a voting disk on one of my VMs:

$ lsblk/dev/vdb
$ ./iolatency –d 251,16

Or check out execsnoop, which shows newly created processes on the system – just watch how clusterware is constantly monitoring itself and others …

$ ./execsnoop

Useful little scripts, you could write them yourself!
Just have a look at what’s to be discovered in …

The /proc filesystem

Its content doesn’t always come as nicely formatted as the /proc/meminfo us DBAs are used to using ;-), but it may be possible to look in the kernel source to figure out what it means… For example, you might look in fs/proc/stat.c to figure out this:

$ cat /proc/stat

And perhaps even more helpful, we have lots of per-process information under /proc/<pid>/.
For example, process memory mappings, like this one here of the Oracle log writer:

$ cat /proc/$(pgrep ora_lgwr)/maps

Ok. Two left, time for the big shots… Enter –

perf

Perf has many uses, but one of the most frequent probably is sampling on-cpu functions. Say I want to determine how much overhead it is setting statistics_level to all.
I‘m executing a simple two-table join, first with statistics_level set to all, and then, with statistics_level set to typical, and for both, I sample what runs on cpu using perf. The result: not much of a difference!

$ perf record -p  -o all_hj.data sleep 30
$ perf record -p  -o typ_hj.data sleep 30
$ perf diff typ_hj.data all_hj.data

Well. Oracle was doing a hash join. Now I do the same, forcing a nested loop join, what happens?

$ perf record -p  -o all_nl.data sleep 30
$ perf record -p  -o typ_nl.data sleep 30
$ perf diff typ_nl.data all_nl.data

Oracle spends 26% of the time in a vdso call, getting the current time from the operating system!

That‘s just one example of what you can do with perf, there’s numerous others – and possibly an even more amazing tool is …

systemtap

Using systemtap, I can profile user-space (here: Oracle) functions.
This all builds upon the awesome investigations of two guys, Luca Canali and Frits Hoogland, whose work you will find linked in the appendix.
So say I’d like compare two versions of a Java program, one hard parsing all the time (using plain java.sql.Statement) and another that uses bind variables (by means of java.sql.PreparedStatement). What are they doing „under the hood“, and how long do these operations take?

This is one thing I could do: get a latency histogram of the Oracle function kksParseCursor. First, the case of doing a hard parse every time: Most parses take between 128 and 512 ms.

Then we have the code using bind variables – most parses take less than 8 ms here…

Again, this is just a starting point … possibilities are endless. So to get you started, have a look at the appendix, and: enjoy!

Appendix: What to Read

System Tap into Oracle for Fun and Profit
Life of an Oracle I/O: Tracing Logical and Physical I/O with SystemTap
Linux strace doesn’t lie after all.
How long does a logical IO take?
strace Wow Much Syscall
perf Examples

Advertisements

Bind variables vs. literals, a quiz and a surprise

The quiz

Recently, something I had intended to be a simple demo promoting the use of bind variables among Java developers turned out to be more interesting than expected.
It all started as a quiz. So I was going to ask, how long would the following run:

  • a fixed query, repeated 100,000 times, always with the same literal
  • the same query, again repeated 100,000 times, but this time using a bind variable, the same value every time
  • the same query, repeated 100,000 times, using 100,000 different literals
  • the same query, repeated 100,000 times, using 100,000 different values for the bind variable

Just so you know what I did exactly, this is how the Java code looked (displaying the relevant parts here only):

One same literal, 100,000 times

String query = "select text1, text2 from mytab where rn=";
int id = 1;
long startTime = System.currentTimeMillis();
Statement stmt = conn.createStatement();
for (int i = 0; i <= 100000; i++) {
  ResultSet rset = stmt.executeQuery (query + id);
  String s;
  while (rset.next ()) {
    s = rset.getString (1) + " " + rset.getString (2);
  }
  rset.close();
}
stmt.close();
System.out.println(System.currentTimeMillis() - startTime);
conn.close();

One same bind value, 100,000 times

String query = "select text1, text2 from mytab where rn=?";
int id = 1;
long startTime = System.currentTimeMillis();
PreparedStatement stmt = conn.prepareStatement(query);
for (int i=0; i<= 100000; i++) {
  stmt.setInt(1, id);
  ResultSet rset = stmt.executeQuery();
  String s;
  while (rset.next ()) {
    s = rset.getString (1) + " " + rset.getString (2);
  }
  rset.close();
}
stmt.close();
System.out.println(System.currentTimeMillis() - startTime);
conn.close();

100,000 different literals

String query = "select text1, text2 from mytab where rn=";
int id = 1;
long startTime = System.currentTimeMillis();
Statement stmt = conn.createStatement();
for (int i = 0; i<= 100000; i++) {
  ResultSet rset = stmt.executeQuery (query + id);
  String s;
  while (rset.next ()) {
    s = rset.getString (1) + " " + rset.getString (2);
  }
  rset.close();
  id = id + 1;
}
stmt.close();
System.out.println(System.currentTimeMillis() - startTime);
conn.close();

100,000 different bind values

String query = "select text1, text2 from mytab where rn=?";
int id = 1;
long startTime = System.currentTimeMillis();
PreparedStatement stmt = conn.prepareStatement(query);
for (int i = 0; i<= 100000; i++) {
  stmt.setInt(1, id);
  ResultSet rset = stmt.executeQuery();
  String s;
  while (rset.next ()) {
    s = rset.getString (1) + " " + rset.getString (2);
  }
  rset.close();
  id = id + 1;
}
stmt.close();
conn.close();

So, of course what I intended to show was the devastating effect of using different literals all the time. Which I succeeded in. But let’s look at the results, first, the execution times measured on the client side:

Client-side execution times (ms)
One same literal 36.1
One same bind value 24.7
100,000 literals 147.4
100,000 bind values 25.3

The surprise

Nice. The 100,000 different literals case does have a horrible execution time. But let’s look at the one-same-value cases, same literal vs. same bind value. Why is the bind variable case so much faster?
(And by the way, although I’m listing the results of one trial only, they were totally reproducible, the pattern was the same how ever I varied the circumstances – e.g., with/without tracing …)

In the one-same-literal case, we perform one hard parse and two soft parses, – from there on it’s “softer soft parses” only.
This can nicely be seen in the trace file. In the third CLOSE line, we have type=1, and PARSE elapsed times are <30 microseconds from there on:

PARSING IN CURSOR ...
PARSE #140263995577416:c=2999,e=20813,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2832086359,tim=1420822842233661
EXEC #140263995577416:c=0,e=69,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2832086359,tim=1420822842238446
WAIT #140263995577416: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420822842238488
FETCH #140263995577416:c=0,e=110,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2832086359,tim=1420822842238639
..
WAIT #140263995577416: nam='SQL*Net message from client' ela= 101732 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420822842340650
CLOSE #140263995577416:c=0,e=15,dep=0,type=0,tim=1420822842340788
=====================
PARSING IN CURSOR ... 
PARSE #140263995577416:c=0,e=199,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2832086359,tim=1420822842341057
EXEC #140263995577416:c=0,e=46,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2832086359,tim=1420822842341161
WAIT #140263995577416: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420822842341197
FETCH #140263995577416:c=0,e=44,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2832086359,tim=1420822842341312
...
WAIT #140263995577416: nam='SQL*Net message from client' ela= 1708 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420822842343128
CLOSE #140263995577416:c=0,e=8,dep=0,type=0,tim=1420822842343193
=====================
PARSING IN CURSOR ...
PARSE #140263995577416:c=0,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2832086359,tim=1420822842343301
EXEC #140263995577416:c=0,e=30,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2832086359,tim=1420822842343386
WAIT #140263995577416: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420822842343414
FETCH #140263995577416:c=0,e=29,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2832086359,tim=1420822842343467
...
WAIT #140263995577416: nam='SQL*Net message from client' ela= 1618 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420822842345279
CLOSE #140263995577416:c=0,e=14,dep=0,type=1,tim=1420822842345357
PARSE #140263995577416:c=0,e=27,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2832086359,tim=1420822842345420
EXEC #140263995577416:c=0,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2832086359,tim=1420822842345473
WAIT #140263995577416: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420822842345502
FETCH #140263995577416:c=0,e=27,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2832086359,tim=1420822842345568
WAIT #140263995577416: nam='SQL*Net message from client' ela= 1618 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420822842347230
CLOSE #140263995577416:c=0,e=11,dep=0,type=3,tim=1420822842347318

From a visual inspection of the trace file for the one-same-bind-value case, you might think both cases should take about the same time in the end:

PARSING IN CURSOR ...
PARSE #140450201769032:c=0,e=873,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1420823096225812
EXEC #140450201769032:c=2000,e=2337,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2832086359,tim=1420823096228602
WAIT #140450201769032: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420823096228684
FETCH #140450201769032:c=0,e=112,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2832086359,tim=1420823096228869
...
WAIT #140450201769032: nam='SQL*Net message from client' ela= 83168 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420823096312251
EXEC #140450201769032:c=0,e=71,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2832086359,tim=1420823096312442
WAIT #140450201769032: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420823096312507
FETCH #140450201769032:c=0,e=60,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2832086359,tim=1420823096312527
WAIT #140450201769032: nam='SQL*Net message from client' ela= 1081 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420823096313684
EXEC #140450201769032:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2832086359,tim=1420823096313794
WAIT #140450201769032: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420823096313832
FETCH #140450201769032:c=0,e=35,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2832086359,tim=1420823096313848

How does this go together then – on the one hand, the work done by the database does not seem to be tremendously different, on the other, the bind values case is noticeably faster on the client!

Well, let’s look at a statistical summary of the database calls for both cases.
First, the one-same-literal case:

1 same literal, 100,000 times
call type count sum elapsed avg elapsed stddev elapsed median elapsed
PARSE 100001 1850716 19 20 16
EXEC 100001 1207545 12 12 11
FETCH 100001 1384287 14 17 12
CLOSE 100000 335618 3 4 3
overall db 400003 4778166
1 same bind value, 100,000 times
call type count sum elapsed avg elapsed stddev elapsed median elapsed
PARSE 1 202 202 0 202
EXEC 100001 1388479 14 25 12
FETCH 100001 3080674 31 30 28
CLOSE 0
overall db 200003 4469355

So it’s true, seen from the database side, the elapsed times for both cases do not differ much at all!
So really the database is doing about the same amount of work in both cases.

Wait a sec …

What about when we add the wait time, especially, SQL*NET message from client (overall db calls are the db call summary numbers from above)?

1 same literal, 100,000 times
type count sum elapsed avg elapsed stddev elapsed median elapsed
SQL*NET msg from client 100001 15308493 153 949 106
overall db calls 400003 4778166
overall total 500004 20086659
1 same bind value, 100,000 times
type count sum elapsed avg elapsed stddev elapsed median elapsed
SQL*NET msg from client 100001 11425310 114 416 74
overall db calls 200003 4469355
overall total 300004 15894665

So we see it is really the time subsumed under SQL*NET message from client that makes the difference.
Why? A SQL*NET trace shows that the amount of data transferred over the network is about twice as much for the literals case than for the binds case (156 vs. 70 bytes per execution). Of course, that’s way below TCP packet size in both cases, but the data has to pass various layers where the size of the read/write operations might make a difference. Probably, the biggest factor here might be the processing on the Java client side, the client having to marshal either a simple number or a not-too-short string. (Of course, that’s just a guess which would need to be supported by more sophisticated measurements on the client side.)

So what’s the conclusion? We can be even more confident about advising (Java) developers to use bind variables, because response times will go down even in cases where one (me, at least) wouldn’t have expected to see a noticeable difference 🙂

SQL trace files, think time, and outliers

Idle wait events and think time

When creating a resource profile for a session or a group of sessions, one usually has to decide how to handle the so-called idle wait events, first and foremost, SQL*Net message from client.

One possibility would be to simply remove (physically or logically) those lines from the trace, thereby avoiding the question of whether some wait should be classified as client (= application) response time, or as think time.
Another would be be to define a threshold and exclude only those lines with wait times above the threshold. In that case, of course, I have to know what makes for a sensible threshold. I could base that threshold on network latencies but then, I might miss information about how the application behaves – what, from the database server’s point of view, is the response time of the application?

So here I want to try another approach, which is applying common outlier detection methods and find out how far that gets me ;-). My test material, this time, will be “real life”, non-artificial trace files, my tools will be the mining infrastructure based on external tables described in the latest three blog posts (starting with Mining SQL Trace Files Using External Tables Part 1: Getting the Timeline and, for ease of use, uploaded on github, and the outlier detection methods used will be four common ones described in http://d-scholarship.pitt.edu/7948/1/Seo.pdf.

Outlier detection methods

The four methods chosen were selected for being both commonly used as well as easily applicable. None of them are based on hypothesis testing as this would require knowledge of the underlying distribution.

Standard deviation method

One commonly used method is classifying as outliers those measurements whose distance from the mean is more than 2 or 3 standard deviations. We may already suspect that a method based on the normality assumption might not be the most effective here, but we’ll have a look anyway, be it only for establishing a baseline for the other methods.

Boxplot

As per Tukey’s boxplot method, values are seen as outliers when either below the first quartile minus 1.5* (3*, respectively) the interquartile range or above the third quartile plus 1.5 * (3*, respectively) the interquartile range (i.e., x < Q1 – 1.5[3]*IQR or x > Q3 + 1.5[3]*IQR).

MADe

Using the MADe method, values are classified as outliers when there distance from the median is more than 2 times (3 times, respectively) the median of absolute differences from the median, scaled by 1.483 (this scaled median of absolute differences is the so-called MADe).
I.e., x < median – 2[3] MADe or x > median – 2[3] MADe.

Median method

Using the median method, values are classified as outliers when they are below/above the median by more than n*IQR, when n is adjustable and chosen as 2.3 in the above mentioned paper.

Outlier detection methods applied

Inspecting the data

First, for all four trace files, let me indicate some summary statistics for the SQL*Net message from client event and present the data graphically.
All trace files have about 50.000 lines for this wait event, with minimum values of ~ 0.35-0.55 milliseconds, a median value of ~ 0.55-0.75 ms, an average of ~1.5-1.8 ms and a maximum ranging from 2.2 to 12 seconds approximately.

SQL> select min(elapsed) min, median(elapsed) median, trunc(avg(elapsed)) avg, trunc(stddev(elapsed)) stddev, max(elapsed) max, count(elapsed) cnt from wait where event='SQL*Net message from client';

-- file 1
       MIN     MEDIAN	     AVG     STDDEV	   MAX	      CNT
---------- ---------- ---------- ---------- ---------- ----------
       368	  541	    1606      33961    3005346	    53124

-- file 2
       MIN     MEDIAN	     AVG     STDDEV	   MAX	      CNT
---------- ---------- ---------- ---------- ---------- ----------
       523	  683	    1843      33805    2269024	    51485

-- file 3
       MIN     MEDIAN	     AVG     STDDEV	   MAX	      CNT
---------- ---------- ---------- ---------- ---------- ----------
       339	  530	    1530      68874   11794066	    47152

-- file 4
       MIN     MEDIAN	     AVG     STDDEV	   MAX	      CNT
---------- ---------- ---------- ---------- ---------- ----------
       547	  770	    1482      27795    3306050	    52608

The following diagrams should help visualize how the data is distributed. I’ve chosen a bucket size of 250 microseconds/0.25 milliseconds, which after some experimentation seemed to work best.
(This means that the numbers on the x axis have to be multiplied by 0.25 to give the elapsed time in microseconds).

SQLNET message from client wait elapsed time distribution

SQLNET message from client wait elapsed time distribution

SQLNET message from client wait elapsed time distribution

SQLNET message from client wait elapsed time distributionFor all methods, I’m interested in the upper threshold only. Now let’s see what the different methods yield.

Standard deviation method
with sd_data as
  (select avg(elapsed) avg, stddev(elapsed) stddev from wait where event='SQL*Net message from client'),
  bounds as 
    (select avg + 2*stddev upper_2sd, avg + 3*stddev upper_3sd from sd_data),
    candidates_2sd as
      (select elapsed from wait w join bounds b on (w.event='SQL*Net message from client' and w.elapsed >  b.upper_2sd)),
      candidates_3sd as
        (select elapsed from wait w join bounds b on (w.event='SQL*Net message from client' and w.elapsed >  b.upper_3sd))
        select '   2sd' "method", count(elapsed) "num_outliers", round(min(elapsed)/1000, 1) "smallest_outlier_ms", round(max(elapsed)/1000, 1) "max_value_ms" from candidates_2sd
        union all 
        select '   3sd', count(elapsed), round(min(elapsed)/1000, 1), round(max(elapsed)/1000, 1) from candidates_3sd;


-- file 1
method num_outliers smallest_outlier_ms  max_value_ms
------ ------------ ------------------- -------------
   2sd		 64		   75.2        3005.3
   3sd		 62		  106.6        3005.3

-- file 2
method num_outliers smallest_outlier_ms max_value_ms
------ ------------ ------------------- ------------
   2sd		 88		   70.5 	2269
   3sd		 84		  116.3 	2269

-- file 3
method num_outliers smallest_outlier_ms max_value_ms
------ ------------ ------------------- ------------
   2sd		 31		  145.9      11794.1
   3sd		 26		  221.7      11794.1

-- file 4
method num_outliers smallest_outlier_ms max_value_ms
------ ------------ ------------------- ------------
   2sd		 64		   62.4       3306.1
   3sd		 55		     93       3306.1

Not surprisingly (given the non-normality of the data), the standard deviation method does not yield useful results. We’ll certainly want to classify as think time values well below 100 ms.

Boxplot
with iqr_data as 
  (select percentile_cont(0.25) within group (order by elapsed) q1, percentile_cont(0.75) within group (order by elapsed) q3, abs(percentile_cont(0.25) within group (order by elapsed) - percentile_cont(0.75) within group (order by elapsed)) iqr from wait where event='SQL*Net message from client'),
  bounds as 
    (select q3 + 1.5 * iqr lower_bound, q3 + 3 * iqr upper_bound from iqr_data),
      candidates_inner as
          (select elapsed from wait w join bounds b on (w.event='SQL*Net message from client' and w.elapsed >  b.lower_bound)),
          candidates_outer as
            (select elapsed from wait w join bounds b on (w.event='SQL*Net message from client' and w.elapsed >  b.upper_bound))
            select 'outside inner bound' "criterion", count(elapsed) "num_outliers", round(min(elapsed)/1000, 1) "smallest_outlier_ms", round(max(elapsed)/1000, 1) "max_value_ms" from candidates_inner
            union all
            select 'outside outer bound', count(elapsed), round(min(elapsed)/1000, 1), round(max(elapsed)/1000, 1) from candidates_outer
        ;
   

-- file 1
criterion	    num_outliers smallest_outlier_ms max_value_ms
------------------- ------------ ------------------- ------------
outside inner bound	    5370		  .9	   3005.3
outside outer bound	    3983		 1.1	   3005.3

-- file 2
criterion	    num_outliers smallest_outlier_ms max_value_ms
------------------- ------------ ------------------- ------------
outside inner bound	    3869		   1	     2269
outside outer bound	    2264		 1.2	     2269

-- file 3
criterion	    num_outliers smallest_outlier_ms max_value_ms
------------------- ------------ ------------------- ------------
outside inner bound	    2026		  .8	  11794.1
outside outer bound	     809		  .9	  11794.1

-- file 4
criterion	    num_outliers smallest_outlier_ms max_value_ms
------------------- ------------ ------------------- ------------
outside inner bound	    3836		 1.1	   3306.1
outside outer bound	    1418		 1.3	   3306.1

This looks better! If we choose the outer bound, waits have to exceed 1 ms to be classified as think time. However, looking at the diagrams, I’m not sure if this is not too low. Let’s compare with median-based methods.

MADe
with median as
  (select median(elapsed) median from wait where event='SQL*Net message from client'),
  abs_differences as
    (select abs(elapsed - median) absdiff from wait, median),
    mad_e as 
      (select median(absdiff) mad_e from abs_differences),
        bounds as 
          (select median + 2*mad_e upper_2mad_e, median + 3*mad_e upper_3mad_e from median, mad_e),
          candidates_2mad_e as
            (select elapsed from wait w join bounds b on (w.event='SQL*Net message from client' and w.elapsed >  b.upper_2mad_e)),
            candidates_3mad_e as
              (select elapsed from wait w join bounds b on (w.event='SQL*Net message from client' and w.elapsed >  b.upper_3mad_e))
                select '2mad_e' "method", count(elapsed) "num_outliers", round(min(elapsed)/1000, 1) "smallest_outlier_ms", round(max(elapsed)/1000, 1) "max_value_ms" from candidates_2mad_e
                union all 
                select '3mad_e', count(elapsed), round(min(elapsed)/1000, 1), round(max(elapsed)/1000, 1) from candidates_3mad_e;


-- file 1
method	num_outliers smallest_outlier_ms max_value_ms
------- ------------ ------------------- ------------
2mad_e   	2740		     1.6       3005.3
3mad_e  	1523		     2.2       3005.3

-- file 2
method num_outliers smallest_outlier_ms max_value_ms
------ ------------ ------------------- ------------
2mad_e		287		      2 	2269
3mad_e		208		    2.7 	2269

-- file 3
method num_outliers smallest_outlier_ms max_value_ms
------ ------------ ------------------- ------------
2mad_e		236		    1.6      11794.1
3mad_e		142		    2.1      11794.1

-- file 4
method num_outliers smallest_outlier_ms max_value_ms
------ ------------ ------------------- ------------
2mad_e		487		    2.3       3306.1
3mad_e		380		    3.1       3306.1

Now this – again choosing the outer bound, so we end up at a threshold of ~ 2-2.5 ms, looks much better to me. Perhaps it is still a little low, from visual inspection?

Median method
with iqr_data as 
  (select median(elapsed) median, percentile_cont(0.25) within group (order by elapsed) q1, percentile_cont(0.75) within group (order by elapsed) q3, abs(percentile_cont(0.25) within group (order by elapsed) - percentile_cont(0.75) within group (order by elapsed)) iqr from wait where event='SQL*Net message from client'),
  bounds as 
    (select median + 2.3 * iqr bound from iqr_data),
      candidates as
          (select elapsed from wait w join bounds b on (w.event='SQL*Net message from client' and w.elapsed >  b.bound))
            select 'outside bound' "criterion", count(elapsed) "num_outliers", round(min(elapsed)/1000, 1) "smallest_outlier_ms", round(max(elapsed)/1000, 1) "max_value_ms" from candidates;


-- file 1   
criterion     num_outliers smallest_outlier_ms max_value_ms
------------- ------------ ------------------- ------------
outside bound	      5065		    .9	     3005.3

-- file 2
criterion     num_outliers smallest_outlier_ms max_value_ms
------------- ------------ ------------------- ------------
outside bound	      3575		     1	       2269

-- file 3
criterion     num_outliers smallest_outlier_ms max_value_ms
------------- ------------ ------------------- ------------
outside bound	      1729		    .8	    11794.1

-- file 4
criterion     num_outliers smallest_outlier_ms max_value_ms
------------- ------------ ------------------- ------------
outside bound	      3316		   1.1	     3306.1

The median method, at least for the trace files given, seems to yield results very similar to boxplot. Same as with boxplot, it might be too strict though.

Conclusion

Of course, four trace files, taken from the same application and under similar conditions, do not make for a representative sample. However, the idea here was to demonstrate the approach, i.e., looking at think time from an outlier detection perspective. For the given sample, the MADe method seems to yield a plausible classification. However, what classification makes sense is, in the end, a question of (at least) two things – the application we’re looking at (a real application? or end users, sitting at their terminals?) and what we want to do with the data (diagnose the database only or the client, too).

I guess it’s the latter case when this approach will be the most useful.

.