Oracle Wait Events and Skew

First things First…
Most savvy Oracle performance folks know about the 10046 extended trace file. If not, just Google “10046 trace” and you’ll learn all you need to know from a variety of sources.  Oracle’s tkprof utility provides a means to read the trace file and provide meaningful output, and recently (10g+) it’s had some nicer summary information on a per-cursor and per-session basis at the end of it.
What a tkprof report won’t give you though is any information about skew. In other words, it summarizes CPU and wait information per cursor and per session, but it doesn’t provide information about what sorts of time period buckets the associated events fell into.
Is this important?  My opinion is yes, and after reading Alex Gorbachev’s paper he presented at RMOUG 2012, I decided to write some programs.  In addition to providing meaningful data, it allowed me a chance to polish off my Perl skills (reader beware – I’m not the best Perl programmer, so please don’t cringe.  It’s late …).
What to Expect in this Post
Code and output.  After looking at output from some of the below scripts, you should be able to determine how to apply the information to whatever problem you’re trying to solve.
10046 Trace File Analysis
First, we’ll write a little program to rip through a 10046 trace file and print some summary results:
[[email protected] 10046]$ ./10046a.pl visx1_ora_25865.trc
Elapsed time < (CPU+WAIT), instrumentation overlap …
Duration   Pct     # Calls    Avg (ms)  Oracle kernel event
———  ——  ———  ——  —————————————-
   51.48s  433.5%        25  2059.05  SQL*Net message from client
    5.27s   44.4%      6751   0.78  CPU service (FETCH)
    4.24s   35.7%     18308   0.23  cell smart table scan
    0.69s    5.8%      1390   0.50  cell single block physical read
    0.68s    5.8%       138   4.96  CPU service (PARSE)
    0.40s    3.4%      2273   0.18  CPU service (EXEC)
    0.10s    0.8%        98   1.02  cell multiblock physical read
    0.10s    0.8%       813   0.12  row cache lock
    0.03s    0.3%       374   0.08  gc cr grant 2-way
    0.03s    0.3%        39   0.78  reliable message
    0.01s    0.1%        92   0.16  KSV master wait
    0.01s    0.1%        56   0.21  gc cr multi block request
    0.01s    0.1%        78   0.14  enq: KO – fast object checkpoint
    0.01s    0.1%         9   0.97  cell list of blocks physical read
    0.00s    0.0%        32   0.08  gc current grant 2-way
    0.00s    0.0%        15   0.12  library cache lock
    0.00s    0.0%        16   0.11  library cache pin
    0.00s    0.0%        46   0.04  ASM file metadata operation
    0.00s    0.0%        14   0.12  gc cr disk read
    0.00s    0.0%         2   0.09  gc cr grant congested
    0.00s    0.0%        32   0.00  Disk file operations I/O
    0.00s    0.0%        39   0.00  SQL*Net message to client
    0.00s    0.0%         1   0.00  asynch descriptor resize
  -51.19s  -431.1%         0  -0.00  instrumentation overlap
———  ——  ———  ——  —————————————-
   11.87s  100.0%     30641        N/A  Totals
       LIO: 1065421.00
      Rows: 13104.00
   LIO/Row: 81.31
   LIO CPU:  5.66s
 Parse CPU:  0.68s
Here’s what the code looks like for 10046a.pl:
#!/u01/app/oracle/product/11.2.0.3/dbhome_1/perl/bin/perl
###########################################
# Name: 10046a.pl
# Usage: 10046a.pl <trace file name>
###########################################
use 5.010;
my %elapsed;                    # Elapsed time
my %counts;                     # Call counts
my $cwl      = 0;               # Current wait line
my $tw       = 0;               # Total waits
my $act_wait = 0;               # Active elapsed
my $idl_wait = 0;               # Idle Waits
my $r        = 0;               # Response time
my $action = “(?:EXEC|UNMAP|SORT UNMAP)”;
my $parse  = “(?:PARSE)”;
my $fetch  = “(?:FETCH)”;
my $chkdep = “(?:EXEC|FETCH|UNMAP|SORT UNMAP|PARSE)”;
my $sum_counts = 0;
my $rows = 0;
my $lio = 0;
my $total_wait_time=0;
die “Usage: $0 <trace file>” if $#ARGV!=0;
my $file=$ARGV[0];
if (-e $file) {
  open(X,”head -2 $file|tail -1|”);
  while (<X>) {
    ($a,$b,$c,$d,$version,$x,$y)=split(‘ ‘, $_);
    if ($version=~/^9/) {
        $resolution=1000000;
    } elsif ($version=~/^8/) {
        $resolution=100;
    } elsif ($version=~/^10/) {
        $resolution=1000000;
    } elsif ($version=~/^11/) {
        $resolution=1000000;
    } elsif ($version=~/^Edition/) {
        if ($y=~/^10/) {
          $resolution=1000000;
        } else { $resolution=1000000; }
    } else {
        die “Not ported to version $version\n”;}
          }
}
close(X);
open(F,”$file”);
while (<F>) {
  if (/^WAIT #(\d+): nam='([^’]*)’ ela=\s*(\d+)/i) {
    ## Processing WAIT lines
    $cwl++;
    $elapsed{$2} += $3/$resolution;
    $total_wait_time += $3/$resolution;
    $counts{$2}++;
    $sum_ela += $3/$resolution;
    push @GLBWAIT, $2.”:”.$3.”\n”;
    $tw++;
  } elsif (/^$action #(\d+):c=(\d+),e=(\d+),p=(\d+),cr=(\d+),cu=(\d+),mis=(\d+),r=(\d+),dep=(\d+)/i) {
    ## Processing EXEC, , UNMAP, and SORT UNMAP lines
    $cwl=0;
    $elapsed{“CPU service (EXEC)”} += $2/$resolution;
    $cpubreakdown{“LIO CPU”} += $2/$resolution;
    $counts{“CPU service (EXEC)”}++;
    $r += $3/$resolution;
    $rows += $8;
    $lio += $5 ;
    $lio += $6 ;
  } elsif (/^$fetch #(\d+):c=(\d+),e=(\d+),p=(\d+),cr=(\d+),cu=(\d+),mis=(\d+),r=(\d+),dep=(\d+)/i) {
    ## Processing FETCH lines
    $cwl=0;
    $elapsed{“CPU service (FETCH)”} += $2/$resolution;
    $cpubreakdown{“LIO CPU”} += $2/$resolution;
    $counts{“CPU service (FETCH)”}++;
    $r += $3/$resolution;
    $rows += $8;
    $lio += $5 ;
    $lio += $6 ;
  } elsif (/^$parse #(\d+):c=(\d+),e=(\d+)/i) {
    ## Processing PARSE lines.
    ## It is important to do this seperately to “walk back” idle
    ## waits.
    for  ($i=0;$i<$cwl;$i++) {
       ($idlnam,$idlela)=split(‘:’,$GLBWAIT[$tw-$i]);
       if ($idlnam=~/Net message/) {
         $elapsed{$idlnam} -= $idlela/$resolution;
         $counts{$idlnam}–;
         $sum_ela -= $idlela/$resolution;
       }
    }
    $cwl=0;
    $elapsed{“CPU service (PARSE)”} += $2/$resolution;
    $cpubreakdown{“Parse CPU”} += $2/$resolution;
    $counts{“CPU service (PARSE)”}++;
    $r += $3/$resolution;
  }
}
## Grabbing any strays at the end
if ($cwl > 0) {
    for  ($i=0;$i<$cwl;$i++) {
       ($idlnam,$idlela)=split(‘:’,$GLBWAIT[$tw-$i]);
       if ($elapsed{idlnam}=~/Net message/) {
         $elapsed{$idlnam} -= $idlela/$resolution;
         $counts{$idlnam}–;
         $sum_ela -= $idlela/$resolution;
       }
    }
}
close (F);
## Set total_cpu
$total_cpu=$elapsed{“CPU service (PARSE)”} + $elapsed{“CPU service (EXEC)”} + $elapsed{“CPU service (FETCH)”};
if ($r < ($total_cpu + $sum_ela)) {
 print “\n\nElapsed time < (CPU+WAIT), instrumentation overlap …\n\n”;
 if ($r < 1) {   ## If trace file *only* has WAIT lines
    $r=$total_wait_time;
    $rows=1;
 } else {
   $elapsed{“instrumentation overlap”} = $r-(($total_cpu + $sum_ela));
   $counts{“instrumentation overlap”}=10000000;
 }
}
$unact = $r – ($total_cpu + $sum_ela);
if ($unact > 0) {
 $elapsed{“instrumentation gap”} = $unact;
 $counts{“instrumentation gap”}=10000000;   #  this helps the division
}
## Report output
printf “%-9s  %-6s  %-9s  %-6s  %-40s\n”, “Duration”, “Pct”, “# Calls”, “Avg (ms)”, “Oracle kernel event”;
printf “%-9s  %-6s  %-9s  %-6s  %-40s\n”, “-“x9, “-“x6, “-“x9, “-“x6,”-“x40;
## Sorting
foreach $key (sort {$elapsed{$b} <=> $elapsed{$a}} keys %elapsed) {
  $curr_ela = $elapsed{$key};
  $curr_pct_ela = ($elapsed{$key}/$r)*100;
  $curr_cnt=$counts{$key};
  if ($key =~ /instrum/) {
     printf “%8.2fs  %5.1f%%  %8.0f  %5.2f  %-40s\n”, $curr_ela, $curr_pct_ela, 0, $curr_ela/$curr_cnt, $key;
     $curr_cnt=0;
  } else {
     if (($curr_ela) > 0 && ($curr_cnt) > 0) {
      printf “%8.2fs  %5.1f%%  %8.0f  %5.2f  %-40s\n”, $curr_ela, $curr_pct_ela, $curr_cnt, (1000*$curr_ela)/$curr_cnt, $key;
     }
  }
  $sum_counts=$sum_counts+$curr_cnt;
}
printf “%8s-  %5s-  %8s-  %5s-  %-40s\n”, “-“x8, “-“x5, “-“x8, “-“x5,”-“x40;
printf “%8.2fs  %5.1f%%  %8.0f  %9s  %-40s\n”, $r, 100, $sum_counts, “N/A”, “Totals”;
my $liopr=$lio/$rows;
printf “\n%11s %5.2f\n”, “LIO:”, $lio;
printf “%11s %5.2f\n”, “Rows:”, $rows;
printf “%11s %5.2f\n”, “LIO/Row:”, $liopr;
my $liocpu=$cpubreakdown{“LIO CPU”};
my $parsecpu=$cpubreakdown{“Parse CPU”};
printf “%11s %5.2fs\n”, “LIO CPU:”, $liocpu;
printf “%11s %5.2fs\n”, “Parse CPU:”, $parsecpu;
So far so good?  Let’s add some skew information:
10046 Trace File Analysis with Skew Info
The first section of the program below is the same as the previous program – I figured I’d just add the skew info to the same general output.  The skew data looks like this:
Wait Skew Data
============================================================
Wait Statistics: gc cr grant congested
Range                                     Time (ms)   %       Count     %      Mean (ms)
—————————————-  ———-  ——  ——–  —— ———-
0.000 to 0.001 ms                            0.00ms   0.0%        0   0.0%     0.00
0.001 to 0.010 ms                            0.18ms 100.0%        2 100.0%     0.09
0.010 to 0.100 ms                            0.00ms   0.0%        0   0.0%     0.00
0.100 to 1.000 ms                            0.00ms   0.0%        0   0.0%     0.00
1.000 to 10.00 ms                            0.00ms   0.0%        0   0.0%     0.00
10.00 to 100.0 ms                            0.00ms   0.0%        0   0.0%     0.00
1 sec to 10   sec                            0.00ms   0.0%        0   0.0%     0.00
> 10      seconds                            0.00ms   0.0%        0   0.0%     0.00
—————————————-  ———-  ——  ——–  —— ———-
Wait Statistics: gc cr disk read
Range                                     Time (ms)   %       Count     %      Mean (ms)
—————————————-  ———-  ——  ——–  —— ———-
0.000 to 0.001 ms                            0.00ms   0.0%        0   0.0%     0.00
0.001 to 0.010 ms                            1.05ms  63.1%       13  92.9%     0.08
0.010 to 0.100 ms                            0.61ms  36.9%        1   7.1%     0.61
0.100 to 1.000 ms                            0.00ms   0.0%        0   0.0%     0.00
1.000 to 10.00 ms                            0.00ms   0.0%        0   0.0%     0.00
10.00 to 100.0 ms                            0.00ms   0.0%        0   0.0%     0.00
1 sec to 10   sec                            0.00ms   0.0%        0   0.0%     0.00
> 10      seconds                            0.00ms   0.0%        0   0.0%     0.00
—————————————-  ———-  ——  ——–  —— ———-
Wait Statistics: gc current grant 2-way
Range                                     Time (ms)   %       Count     %      Mean (ms)
—————————————-  ———-  ——  ——–  —— ———-
0.000 to 0.001 ms                            0.00ms   0.0%        0   0.0%     0.00
0.001 to 0.010 ms                            2.33ms  95.5%       31  96.9%     0.08
0.010 to 0.100 ms                            0.11ms   4.5%        1   3.1%     0.11
0.100 to 1.000 ms                            0.00ms   0.0%        0   0.0%     0.00
1.000 to 10.00 ms                            0.00ms   0.0%        0   0.0%     0.00
10.00 to 100.0 ms                            0.00ms   0.0%        0   0.0%     0.00
1 sec to 10   sec                            0.00ms   0.0%        0   0.0%     0.00
> 10      seconds                            0.00ms   0.0%        0   0.0%     0.00
—————————————-  ———-  ——  ——–  —— ———-
Wait Statistics: cell list of blocks physical read
Range                                     Time (ms)   %       Count     %      Mean (ms)
—————————————-  ———-  ——  ——–  —— ———-
0.000 to 0.001 ms                            0.00ms   0.0%        0   0.0%     0.00
0.001 to 0.010 ms                            0.00ms   0.0%        0   0.0%     0.00
0.010 to 0.100 ms                            4.21ms  48.5%        6  66.7%     0.70
0.100 to 1.000 ms                            4.48ms  51.5%        3  33.3%     1.49
1.000 to 10.00 ms                            0.00ms   0.0%        0   0.0%     0.00
10.00 to 100.0 ms                            0.00ms   0.0%        0   0.0%     0.00
1 sec to 10   sec                            0.00ms   0.0%        0   0.0%     0.00
> 10      seconds                            0.00ms   0.0%        0   0.0%     0.00
—————————————-  ———-  ——  ——–  —— ———-
Wait Statistics: gc cr multi block request
Range                                     Time (ms)   %       Count     %      Mean (ms)
—————————————-  ———-  ——  ——–  —— ———-
0.000 to 0.001 ms                            0.00ms   0.0%        0   0.0%     0.00
0.001 to 0.010 ms                            0.00ms   0.0%        0   0.0%     0.00
0.010 to 0.100 ms                           11.86ms 100.0%       56 100.0%     0.21
0.100 to 1.000 ms                            0.00ms   0.0%        0   0.0%     0.00
1.000 to 10.00 ms                            0.00ms   0.0%        0   0.0%     0.00
10.00 to 100.0 ms                            0.00ms   0.0%        0   0.0%     0.00
1 sec to 10   sec                            0.00ms   0.0%        0   0.0%     0.00
> 10      seconds                            0.00ms   0.0%        0   0.0%     0.00
—————————————-  ———-  ——  ——–  —— ———-
Wait Statistics: cell multiblock physical read
Range                                     Time (ms)   %       Count     %      Mean (ms)
—————————————-  ———-  ——  ——–  —— ———-
0.000 to 0.001 ms                            0.00ms   0.0%        0   0.0%     0.00
0.001 to 0.010 ms                            0.00ms   0.0%        0   0.0%     0.00
0.010 to 0.100 ms                           50.92ms  50.7%       70  71.4%     0.73
0.100 to 1.000 ms                           49.44ms  49.3%       28  28.6%     1.77
1.000 to 10.00 ms                            0.00ms   0.0%        0   0.0%     0.00
10.00 to 100.0 ms                            0.00ms   0.0%        0   0.0%     0.00
1 sec to 10   sec                            0.00ms   0.0%        0   0.0%     0.00
> 10      seconds                            0.00ms   0.0%        0   0.0%     0.00
—————————————-  ———-  ——  ——–  —— ———-
Wait Statistics: library cache pin
Range                                     Time (ms)   %       Count     %      Mean (ms)
—————————————-  ———-  ——  ——–  —— ———-
0.000 to 0.001 ms                            0.00ms   0.0%        0   0.0%     0.00
0.001 to 0.010 ms                            0.46ms  26.7%        5  31.2%     0.09
0.010 to 0.100 ms                            1.27ms  73.3%       11  68.8%     0.12
0.100 to 1.000 ms                            0.00ms   0.0%        0   0.0%     0.00
1.000 to 10.00 ms                            0.00ms   0.0%        0   0.0%     0.00
10.00 to 100.0 ms                            0.00ms   0.0%        0   0.0%     0.00
1 sec to 10   sec                            0.00ms   0.0%        0   0.0%     0.00
> 10      seconds                            0.00ms   0.0%        0   0.0%     0.00
—————————————-  ———-  ——  ——–  —— ———-
Wait Statistics: cell single block physical read
Range                                     Time (ms)   %       Count     %      Mean (ms)
—————————————-  ———-  ——  ——–  —— ———-
0.000 to 0.001 ms                            0.00ms   0.0%        0   0.0%     0.00
0.001 to 0.010 ms                            0.00ms   0.0%        0   0.0%     0.00
0.010 to 0.100 ms                          685.93ms  99.5%     1387  99.8%     0.49
0.100 to 1.000 ms                            3.79ms   0.5%        3   0.2%     1.26
1.000 to 10.00 ms                            0.00ms   0.0%        0   0.0%     0.00
10.00 to 100.0 ms                            0.00ms   0.0%        0   0.0%     0.00
1 sec to 10   sec                            0.00ms   0.0%        0   0.0%     0.00
> 10      seconds                            0.00ms   0.0%        0   0.0%     0.00
—————————————-  ———-  ——  ——–  —— ———-
Wait Statistics: SQL*Net message from client
Range                                     Time (ms)   %       Count     %      Mean (ms)
—————————————-  ———-  ——  ——–  —— ———-
0.000 to 0.001 ms                            0.00ms   0.0%        0   0.0%     0.00
0.001 to 0.010 ms                            0.09ms   0.0%        1   2.6%     0.09
0.010 to 0.100 ms                            7.29ms   0.0%       37  94.9%     0.20
0.100 to 1.000 ms                            0.00ms   0.0%        0   0.0%     0.00
1.000 to 10.00 ms                            0.00ms   0.0%        0   0.0%     0.00
10.00 to 100.0 ms                            0.00ms   0.0%        0   0.0%     0.00
1 sec to 10   sec                            0.00ms   0.0%        0   0.0%     0.00
> 10      seconds                        51471.92ms 100.0%        1   2.6% 51471.92
—————————————-  ———-  ——  ——–  —— ———-
Wait Statistics: cell smart table scan
Range                                     Time (ms)   %       Count     %      Mean (ms)
—————————————-  ———-  ——  ——–  —— ———-
0.000 to 0.001 ms                           27.39ms   0.6%     5005  27.3%     0.01
0.001 to 0.010 ms                          285.71ms   6.7%     7256  39.6%     0.04
0.010 to 0.100 ms                         1420.95ms  33.5%     5060  27.6%     0.28
0.100 to 1.000 ms                         2086.30ms  49.2%      958   5.2%     2.18
1.000 to 10.00 ms                          418.12ms   9.9%       25   0.1%    16.72
10.00 to 100.0 ms                            0.00ms   0.0%        0   0.0%     0.00
1 sec to 10   sec                            0.00ms   0.0%        0   0.0%     0.00
> 10      seconds                            0.00ms   0.0%        4   0.0%     0.00
—————————————-  ———-  ——  ——–  —— ———-
And the code for 10046s.pl is below:
#!/u01/app/oracle/product/11.2.0.3/dbhome_1/perl/bin/perl
###########################################
# Name: 10046s.pl
# Usage: 10046s.pl <trace file name>
###########################################
use 5.010;
my %elapsed;                    # Elapsed time
my %counts;                     # Call counts
# skew buckets
my %elapbkt;
my %countsbkt;
my $bkt1=”bkt1″;
my $bkt2=”bkt2″;
my $bkt3=”bkt3″;
my $bkt4=”bkt4″;
my $bkt5=”bkt5″;
my $bkt6=”bkt6″;
my $bkt7=”bkt7″;
my $bkt8=”bkt8″;
# end skew buckets
my $cwl      = 0;               # Current wait line
my $tw       = 0;               # Total waits
my $act_wait = 0;               # Active elapsed
my $idl_wait = 0;               # Idle Waits
my $r        = 0;               # Response time
my $action = “(?:EXEC|UNMAP|SORT UNMAP)”;
my $parse  = “(?:PARSE)”;
my $fetch  = “(?:FETCH)”;
my $chkdep = “(?:EXEC|FETCH|UNMAP|SORT UNMAP|PARSE)”;
my $sum_counts = 0;
my $rows = 0;
my $lio = 0;
my $total_wait_time=0;
die “Usage: $0 <trace file>” if $#ARGV!=0;
my $file=$ARGV[0];
if (-e $file) {
  open(X,”head -2 $file|tail -1|”);
  while (<X>) {
    ($a,$b,$c,$d,$version,$x,$y)=split(‘ ‘, $_);
    if ($version=~/^9/) {
        $resolution=1000000;
    } elsif ($version=~/^8/) {
        $resolution=100;
    } elsif ($version=~/^10/) {
        $resolution=1000000;
    } elsif ($version=~/^11/) {
        $resolution=1000000;
    } elsif ($version=~/^Edition/) {
        if ($y=~/^10/) {
          $resolution=1000000;
        } else { $resolution=1000000; }
    } else {
        die “Not ported to version $version\n”;}
  }
}
close(X)
open(F,”$file”);
while (<F>) {
  if (/^WAIT/) {
  if (/^WAIT #(\d+): nam='([^’]*)’ ela=\s*(\d+)/i) {
    ## Processing WAIT lines
    $cwl++;
    $elapsed{$2} += $3/$resolution;
    $total_wait_time += $3/$resolution;
    $counts{$2}++;
    $sum_ela += $3/$resolution;
    push @GLBWAIT, $2.”:”.$3.”\n”;
    $tw++;
    ## Skew table …
    given ($3) {
       when ([1..10]) {         ## .001 ms
               $elapbkt{$2}{$bkt1} += 1000*($3/$resolution);        $countsbkt{$2}{$bkt1}++;
       }
       when ([11..100]) {       ## .01 ms
        $elapbkt{$2}{$bkt2} += 1000*($3/$resolution);        $countsbkt{$2}{$bkt2}++;
       }
       when ([101..1000]) {     ## .1 ms
        $elapbkt{$2}{$bkt3} += 1000*($3/$resolution);
        $countsbkt{$2}{$bkt3}++;
       }
       when ([1001..10000]) {   ## 1 ms
        $elapbkt{$2}{$bkt4} += 1000*($3/$resolution);
        $countsbkt{$2}{$bkt4}++;
       }
       when ([10001..100000]) {         ## 10 ms
        $elapbkt{$2}{$bkt5} += 1000*($3/$resolution);
        $countsbkt{$2}{$bkt5}++;
       }
       when ([100001..1000000]) {       ## 100 ms
        $elapbkt{$2}{$bkt6} += 1000*($3/$resolution);
        $countsbkt{$2}{$bkt6}++;
       }
       when ([1000001..10000000]) {     ## 1 s
        $elapbkt{$2}{$bkt7} += 1000*($3/$resolution);
        $countsbkt{$2}{$bkt7}++;
       }
       default {                        ## 10s +
        $elapbkt{$2}{$bkt8} += 1000*($3/$resolution);
        $countsbkt{$2}{$bkt8}++;
       }
    }
    ## End Skew analysis
   }
  } elsif (/^$action #(\d+):c=(\d+),e=(\d+),p=(\d+),cr=(\d+),cu=(\d+),mis=(\d+),r=(\d+),dep=(\d+)/i) {
    ## Processing EXEC, , UNMAP, and SORT UNMAP lines
    $cwl=0;
    $elapsed{“CPU service (EXEC)”} += $2/$resolution;
    $cpubreakdown{“LIO CPU”} += $2/$resolution;
    $counts{“CPU service (EXEC)”}++;
    $r += $3/$resolution;
    $rows += $8;
    $lio += $5 ;
    $lio += $6 ;
  } elsif (/^$fetch #(\d+):c=(\d+),e=(\d+),p=(\d+),cr=(\d+),cu=(\d+),mis=(\d+),r=(\d+),dep=(\d+)/i) {
    ## Processing FETCH lines
    $cwl=0;
    $elapsed{“CPU service (FETCH)”} += $2/$resolution;
    $cpubreakdown{“LIO CPU”} += $2/$resolution;
    $counts{“CPU service (FETCH)”}++;
    $r += $3/$resolution;
    $rows += $8;
    $lio += $5 ;
    $lio += $6 ;
  } elsif (/^$parse #(\d+):c=(\d+),e=(\d+)/i) {
    ## Processing PARSE lines.
    ## It is important to do this seperately to “walk back” idle
    ## waits.
    for  ($i=0;$i<$cwl;$i++) {
       ($idlnam,$idlela)=split(‘:’,$GLBWAIT[$tw-$i]);
       if ($idlnam=~/Net message/) {
         $elapsed{$idlnam} -= $idlela/$resolution;
         $counts{$idlnam}–;
         $sum_ela -= $idlela/$resolution;
       }
    }
    $cwl=0;
    $elapsed{“CPU service (PARSE)”} += $2/$resolution;
    $cpubreakdown{“Parse CPU”} += $2/$resolution;
    $counts{“CPU service (PARSE)”}++;
    $r += $3/$resolution;
  }
}
## Grabbing any strays at the end
if ($cwl > 0) {
    for  ($i=0;$i<$cwl;$i++) {
       ($idlnam,$idlela)=split(‘:’,$GLBWAIT[$tw-$i]);
       if ($elapsed{idlnam}=~/Net message/) {
         $elapsed{$idlnam} -= $idlela/$resolution;
         $counts{$idlnam}–;
         $sum_ela -= $idlela/$resolution;
       }
    }
}
close (F);
## getting unaccounted time (see formula below)
## e = sum(cpu) + sum(wait) + sum(unacct)
## sum(unacct) = e – sum(cpu) – sum(wait)
## Set total_cpu
$total_cpu=$elapsed{“CPU service (PARSE)”} + $elapsed{“CPU service (EXEC)”} + $elapsed{“CPU service (FETCH)”};
if ($r < ($total_cpu + $sum_ela)) {
 print “\n\nElapsed time < (CPU+WAIT), instrumentation overlap …\n\n”;
 if ($r < 1) {   ## If trace file *only* has WAIT lines
    $r=$total_wait_time;
    $rows=1;
 } else {
   $elapsed{“instrumentation overlap”} = $r-(($total_cpu + $sum_ela));
   $counts{“instrumentation overlap”}=10000000;
 }
}
$unact = $r – ($total_cpu + $sum_ela);
if ($unact > 0) {
 $elapsed{“instrumentation gap”} = $unact;
 $counts{“instrumentation gap”}=10000000;   #  this helps the division
}
## Report output
print “\nSUMMARY INFO\n”;
print “============================================================\n”;
printf “%-9s  %-6s  %-9s  %-6s  %-40s\n”, “Duration”, “Pct”, “# Calls”, “Avg (ms)”, “Oracle kernel event”;
printf “%-9s  %-6s  %-9s  %-6s  %-40s\n”, “-“x9, “-“x6, “-“x9, “-“x6,”-“x40;
## Sorting
foreach $key (sort {$elapsed{$b} <=> $elapsed{$a}} keys %elapsed) {
  $curr_ela = $elapsed{$key};
  $curr_pct_ela = ($elapsed{$key}/$r)*100;
  $curr_cnt=$counts{$key};
  if ($key =~ /instrum/) {
     printf “%8.2fs  %5.1f%%  %8.0f  %5.2f  %-40s\n”, $curr_ela, $curr_pct_ela, 0, $curr_ela/$curr_cnt, $key;
     $curr_cnt=0;
  } else {
     if (($curr_ela) > 0 && ($curr_cnt) > 0) {
      printf “%8.2fs  %5.1f%%  %8.0f  %5.2f  %-40s\n”, $curr_ela, $curr_pct_ela, $curr_cnt, (1000*$curr_ela)/$curr_cnt, $key;
     }
  }
  $sum_counts=$sum_counts+$curr_cnt;
}
printf “%8s-  %5s-  %8s-  %5s-  %-40s\n”, “-“x8, “-“x5, “-“x8, “-“x5,”-“x40;
printf “%8.2fs  %5.1f%%  %8.0f  %9s  %-40s\n”, $r, 100, $sum_counts, “N/A”, “Totals”;
my $liopr=$lio/$rows;
print “LIO, Rows, and Statistic Summary\n”;
printf “\n%11s %5.2f\n”, “LIO:”, $lio;
printf “%11s %5.2f\n”, “Rows:”, $rows;
printf “%11s %5.2f\n”, “LIO/Row:”, $liopr;
my $liocpu=$cpubreakdown{“LIO CPU”};
my $parsecpu=$cpubreakdown{“Parse CPU”};
printf “%11s %5.2fs\n”, “LIO CPU:”, $liocpu;
printf “%11s %5.2fs\n”, “Parse CPU:”, $parsecpu;
print “\n\nWait Skew Data \n”;
print “============================================================\n”;
foreach $skey (sort {$elapbkt{$b} <=> $elapbkt{$a}} keys %elapbkt) {
 print “Wait Statistics: $skey\n”;
 $tt=$elapbkt{$skey}{$bkt1}+$elapbkt{$skey}{$bkt2}+$elapbkt{$skey}{$bkt3}+$elapbkt{$skey}{$bkt4}+$elapbkt{$skey}{$bkt5}+$elapbkt{$skey}{$bkt6}+$elapbkt{$skey}{$bkt7}+$elapbkt{$skey}{$bkt8};
 $tc=$countsbkt{$skey}{$bkt1}+$countsbkt{$skey}{$bkt2}+$countsbkt{$skey}{$bkt3}+$countsbkt{$skey}{$bkt4}+$countsbkt{$skey}{$bkt5}+$countsbkt{$skey}{$bkt6}+$countsbkt{$skey}{$bkt7}+$countsbkt{$skey}{$bkt8};
 printf “%-40s  %-10s  %-6s  %-8s  %-6s %-10s\n”, “Range”, “Time (ms)”, “%”, “Count”, “%”,”Mean (ms)”;
 printf “%-40s  %-10s  %-6s  %-8s  %-6s %-10s\n”, “-“x40, “-“x10, “-“x6, “-“x8, “-“x6, “-“x10;
 printf “%-40s %8.2fms %5.1f%% %8.0f %5.1f%% %8.2f\n”, “0.000 to 0.001 ms”, $elapbkt{$skey}{$bkt1}, 100*(($elapbkt{$skey}{$bkt1})/$tt), $countsbkt{$skey}{$bkt1},100*(($countsbkt{$skey}{$bkt1})/$tc), $elapbkt{$skey}{$bkt1}/($countsbkt{$skey}{$bkt1}+.000000000000001);
 printf “%-40s %8.2fms %5.1f%% %8.0f %5.1f%% %8.2f\n”, “0.001 to 0.010 ms”, $elapbkt{$skey}{$bkt2}, 100*(($elapbkt{$skey}{$bkt2})/$tt), $countsbkt{$skey}{$bkt2},100*(($countsbkt{$skey}{$bkt2})/$tc), $elapbkt{$skey}{$bkt2}/($countsbkt{$skey}{$bkt2}+.000000000000001);
 printf “%-40s %8.2fms %5.1f%% %8.0f %5.1f%% %8.2f\n”, “0.010 to 0.100 ms”, $elapbkt{$skey}{$bkt3}, 100*(($elapbkt{$skey}{$bkt3})/$tt), $countsbkt{$skey}{$bkt3},100*(($countsbkt{$skey}{$bkt3})/$tc), $elapbkt{$skey}{$bkt3}/($countsbkt{$skey}{$bkt3}+.000000000000001);
 printf “%-40s %8.2fms %5.1f%% %8.0f %5.1f%% %8.2f\n”, “0.100 to 1.000 ms”, $elapbkt{$skey}{$bkt4}, 100*(($elapbkt{$skey}{$bkt4})/$tt), $countsbkt{$skey}{$bkt4},100*(($countsbkt{$skey}{$bkt4})/$tc), $elapbkt{$skey}{$bkt4}/($countsbkt{$skey}{$bkt4}+.000000000000001);
 printf “%-40s %8.2fms %5.1f%% %8.0f %5.1f%% %8.2f\n”, “1.000 to 10.00 ms”, $elapbkt{$skey}{$bkt5}, 100*(($elapbkt{$skey}{$bkt5})/$tt), $countsbkt{$skey}{$bkt5},100*(($countsbkt{$skey}{$bkt5})/$tc), $elapbkt{$skey}{$bkt5}/($countsbkt{$skey}{$bkt5}+.000000000000001);
 printf “%-40s %8.2fms %5.1f%% %8.0f %5.1f%% %8.2f\n”, “10.00 to 100.0 ms”, $elapbkt{$skey}{$bkt6}, 100*(($elapbkt{$skey}{$bkt6})/$tt), $countsbkt{$skey}{$bkt6},100*(($countsbkt{$skey}{$bkt6})/$tc), $elapbkt{$skey}{$bkt6}/($countsbkt{$skey}{$bkt6}+.000000000000001);
 printf “%-40s %8.2fms %5.1f%% %8.0f %5.1f%% %8.2f\n”, “1 sec to 10   sec”, $elapbkt{$skey}{$bkt7}, 100*(($elapbkt{$skey}{$bkt7})/$tt), $countsbkt{$skey}{$bkt7},100*(($countsbkt{$skey}{$bkt7})/$tc), $elapbkt{$skey}{$bkt7}/($countsbkt{$skey}{$bkt7}+.000000000000001);
 printf “%-40s %8.2fms %5.1f%% %8.0f %5.1f%% %8.2f\n”, “> 10      seconds”, $elapbkt{$skey}{$bkt8}, 100*(($elapbkt{$skey}{$bkt8})/$tt), $countsbkt{$skey}{$bkt8},100*(($countsbkt{$skey}{$bkt8})/$tc), $elapbkt{$skey}{$bkt8}/($countsbkt{$skey}{$bkt8}+.000000000000001);
 printf “%-40s  %-10s  %-6s  %-8s  %-6s %-10s\n”, “-“x40, “-“x10, “-“x6, “-“x8, “-“x6, “-“x10;
}
What Next?
Look for anomalies in your skew data.  Run 10046wd.pl to print out specific outlier information, or any details information about time intervals that looks suspicious.  Maybe you’ve got hot blocks, bad blocks, or some other boundary condition.
[[email protected] 10046]$ ./10046wd.pl ./visx1_ora_25865.trc
Enter the wait event: cell smart table scan
1) 0.000 to 0.001 ms
2) 0.001 to 0.010 ms
3) 0.010 to 0.100 ms
4) 0.100 to 1.000 ms
5) 1.000 to 10.00 ms
6) 10.00 to 100.0 ms
7) 1 sec to 10   sec
8) > 10      seconds
Enter choice from above: 5
Looking for  waits in ./visx1_ora_25865.trc for option 5 …
WAIT #47346983551968: nam=’cell smart table scan’ ela= 23165 cellhash#=2520626383 p2=0 p3=0 obj#=38169 tim=1329758777699392
WAIT #47346983551968: nam=’cell smart table scan’ ela= 10249 cellhash#=88802347 p2=0 p3=0 obj#=41472 tim=1329758778187046
WAIT #47346983551968: nam=’cell smart table scan’ ela= 20340 cellhash#=398250101 p2=0 p3=0 obj#=1942739 tim=1329758779105182
WAIT #47346983551968: nam=’cell smart table scan’ ela= 25203 cellhash#=2520626383 p2=0 p3=0 obj#=1942739 tim=1329758779198601
WAIT #47346983551968: nam=’cell smart table scan’ ela= 10069 cellhash#=398250101 p2=0 p3=0 obj#=1942741 tim=1329758779725365
WAIT #47346983551968: nam=’cell smart table scan’ ela= 13140 cellhash#=398250101 p2=0 p3=0 obj#=1942741 tim=1329758779759378
WAIT #47346983551968: nam=’cell smart table scan’ ela= 10945 cellhash#=398250101 p2=0 p3=0 obj#=1942744 tim=1329758779941341
WAIT #47346983551968: nam=’cell smart table scan’ ela= 11047 cellhash#=398250101 p2=0 p3=0 obj#=1942744 tim=1329758779953465
WAIT #47346983551968: nam=’cell smart table scan’ ela= 13608 cellhash#=398250101 p2=0 p3=0 obj#=1942744 tim=1329758779971379
WAIT #47346983551968: nam=’cell smart table scan’ ela= 10813 cellhash#=88802347 p2=0 p3=0 obj#=1942744 tim=1329758780039645
WAIT #47346983551968: nam=’cell smart table scan’ ela= 16690 cellhash#=398250101 p2=0 p3=0 obj#=1942747 tim=1329758780611866
WAIT #47346983551968: nam=’cell smart table scan’ ela= 23837 cellhash#=2520626383 p2=0 p3=0 obj#=1942747 tim=1329758780722120
WAIT #47346983551968: nam=’cell smart table scan’ ela= 25260 cellhash#=2520626383 p2=0 p3=0 obj#=1955614 tim=1329758780779977
WAIT #47346983551968: nam=’cell smart table scan’ ela= 27813 cellhash#=398250101 p2=0 p3=0 obj#=2323281 tim=1329758780865354
WAIT #47346983551968: nam=’cell smart table scan’ ela= 13505 cellhash#=2520626383 p2=0 p3=0 obj#=43622 tim=1329758781172420
WAIT #47346983551968: nam=’cell smart table scan’ ela= 24114 cellhash#=2520626383 p2=0 p3=0 obj#=1943203 tim=1329758781580478
WAIT #47346983551968: nam=’cell smart table scan’ ela= 11956 cellhash#=398250101 p2=0 p3=0 obj#=41225 tim=1329758782264977
WAIT #47346983551968: nam=’cell smart table scan’ ela= 27131 cellhash#=398250101 p2=0 p3=0 obj#=48754 tim=1329758782520394
WAIT #47346983551968: nam=’cell smart table scan’ ela= 12410 cellhash#=2520626383 p2=0 p3=0 obj#=40889 tim=1329758783635086
The code for 10046wd.pl is below:
#!/u01/app/oracle/product/11.2.0.3/dbhome_1/perl/bin/perl
###########################################
# Name: 10046wd.pl
# Usage: 10046wd.pl <trace file name>
###########################################
use 5.010;
die “Usage: $0 <trace file>” if $#ARGV!=0;
sub promptUser {
   local($promptString,$defaultValue) = @_;
   if ($defaultValue) {
      print $promptString, “[“, $defaultValue, “]: “;
   } else {
      print $promptString, “: “;
   }
   $| = 1;               # force a flush after our print
   $_ = <STDIN>;         # get the input from STDIN (presumably the keyboard)
   chomp;
   if (“$defaultValue”) {
      return $_ ? $_ : $defaultValue;    # return $_ if it has a value
   } else {
      return $_;
   }
}
my $file=$ARGV[0]; ## input file
$waitevt= &promptUser(“Enter the wait event”);
print “1) 0.000 to 0.001 ms\n”;
print “2) 0.001 to 0.010 ms\n”;
print “3) 0.010 to 0.100 ms\n”;
print “4) 0.100 to 1.000 ms\n”;
print “5) 1.000 to 10.00 ms\n”;
print “6) 10.00 to 100.0 ms\n”;
print “7) 1 sec to 10   sec\n”;
print “8) > 10      seconds\n”;
$sel= &promptUser(“Enter choice from above”);
my $file=$ARGV[0];
print “Looking for $waitenvt waits in $file for option $sel …\n”;
if (-e $file) {
  open(X,”head -2 $file|tail -1|”);
  while (<X>) {
    ($a,$b,$c,$d,$version,$x,$y)=split(‘ ‘, $_);
    if ($version=~/^9/) {
        $resolution=1000000;
    } elsif ($version=~/^8/) {
        $resolution=100;
    } elsif ($version=~/^10/) {
        $resolution=1000000;
    } elsif ($version=~/^11/) {
        $resolution=1000000;
    } elsif ($version=~/^Edition/) {
        if ($y=~/^10/) {
          $resolution=1000000;
        } else { $resolution=1000000; }
    } else {
        die “Not ported to version $version\n”;}
  }
}
close(X);
open(F,”$file”);
while (<F>) {
   if (/$waitevt/) {
      $line=$_;
      if (/^WAIT #(\d+): nam='([^’]*)’ ela=\s*(\d+)/i) {
       given ($3) {
          when ([1..10]) {
            print “$line” if $sel eq “1”;
          }
          when ([11..100]) {
            print “$line” if $sel eq “2”;
          }
          when ([101..1000]) {
        print “$line” if $sel eq “3”;
          }
          when ([1001..10000]) {
            print “$line” if $sel eq “4”;
          }
          when ([10001..100000]) {
            print “$line” if $sel eq “5”;
          }
          when ([100001..1000000]) {
            print “$line” if $sel eq “6”;
          }
          when ([1000001..10000000]) {
           print “$line” if $sel eq “7”;
          }
          default {
           print “$line” if $sel eq “8”;
         }
       }
      }
   }
}
close(F);
Can I Get This Data from ASH?
Here’s a script to pull from V$ACTIVE_SESSION_HISTORY:
col samplestart format a21 head ‘Begin Time’
col sampleend format a21 head ‘End Time’
col aas format 999.99 head ‘AAS’
col aas_cpu format 999.99 head ‘AAS per |CPU’
col event format a55 head ‘Event’
col time_waited format 99999999999 head ‘Time Waited’
col s1 format 999999 head ‘000.001|ms’
col s2 format 999999 head ‘000.010|ms’
col s3 format 999999 head ‘000.100|ms’
col s4 format 999999 head ‘001.000|ms’
col s5 format 999999 head ‘010.000|ms’
col s6 format 999999 head ‘100.000|ms’
col s7 format 999999 head ‘001.000| s’
col s8 format 999999 head ‘010.000| s’
col c1 format 999999 head ‘Cnt’
col c2 format 999999 head ‘Cnt’
col c3 format 999999 head ‘Cnt’
col c4 format 999999 head ‘Cnt’
col c5 format 999999 head ‘Cnt’
col c6 format 999999 head ‘Cnt’
col c7 format 999999 head ‘Cnt’
col c8 format 999999 head ‘Cnt’
set lines 300
set colsep |
COLUMN bt NEW_VALUE _bt NOPRINT
COLUMN et NEW_VALUE _et NOPRINT
select min(cast(sample_time as date)) bt,
sysdate et
from v$active_session_history;
WITH xtimes (xdate) AS
  (SELECT to_date(‘&_bt’) xdate FROM dual
  UNION ALL
  SELECT xdate     +(
    &&interval_mins/1440)
  FROM xtimes
  WHERE xdate      +(
    &&interval_mins/1440) < sysdate
  )
select samplestart,sampleend,event,
        nvl(sum(bkt1),0) s1, count(bkt1) c1,
                nvl(sum(bkt2),0) s2, count(bkt2) c2,
        nvl(sum(bkt3),0) s3, count(bkt3) c3,
        nvl(sum(bkt4),0) s4, count(bkt4) c4,
        nvl(sum(bkt5),0) s5, count(bkt5) c5,
        nvl(sum(bkt6),0) s6, count(bkt6) c6,
        nvl(sum(bkt7),0) s7, count(bkt7) c7,
        nvl(sum(bkt8),0) s8, count(bkt8) c8 from (
SELECT samplestart,
  sampleend,
  event ,
  (
  CASE
    WHEN time_waited BETWEEN 1 AND 10
    THEN 1000*(time_waited/1000000)
  END ) bkt1,
  (
  CASE
    WHEN time_waited BETWEEN 10 AND 100
    THEN 1000*(time_waited/1000000)
  END ) bkt2,
  (
  CASE
    WHEN time_waited BETWEEN 10 AND 100
    THEN 1000*(time_waited/1000000)
  END ) bkt3,
  (
  CASE
    WHEN time_waited BETWEEN 100 AND 1000
    THEN 1000*(time_waited/1000000)
  END ) bkt4,
  (
  CASE
    WHEN time_waited BETWEEN 1000 AND 10000
    THEN 1000*(time_waited/1000000)
  END ) bkt5,
  (
  CASE
    WHEN time_waited BETWEEN 10000 AND 100000
    THEN 1000*(time_waited/1000000)
  END ) bkt6,
  (
  CASE
 WHEN time_waited BETWEEN 100000 AND 1000000
    THEN 1000*(time_waited/1000000)
  END ) bkt7,
  (
  CASE
    WHEN time_waited > 1000000
    THEN 1000*(time_waited/1000000)
  END ) bkt8
FROM
  (SELECT TO_CHAR(s1.xdate,’DD-MON-RR HH24:MI:SS’) samplestart,
    TO_CHAR(s1.xdate+(
    &&interval_mins /1440),’DD-MON-RR HH24:MI:SS’) sampleend,
    s2.event,
    s2.time_waited time_waited,
    s2.time_waited total_waits
  FROM xtimes s1,
    v$active_session_history s2
  WHERE s2.sample_time BETWEEN s1.xdate AND s1.xdate+(
    &&interval_mins                                 /1440)
  )
)
where event is not null
and event like ‘%’||’&event_to_check’||’%’
group by samplestart,sampleend,event
order by samplestart,event
/
undefine interval_mins
undefine event_to_check
And here’s one to pull from DBA_HIST_ACTIVE_SESS_HISTORY:
col samplestart format a21 head ‘Begin Time’
col sampleend format a21 head ‘End Time’
col aas format 999.99 head ‘AAS’
col aas_cpu format 999.99 head ‘AAS per |CPU’
col event format a55 head ‘Event’
col time_waited format 99999999999 head ‘Time Waited’
col s1 format 999999 head ‘000.001|ms’
col s2 format 999999 head ‘000.010|ms’
col s3 format 999999 head ‘000.100|ms’
col s4 format 999999 head ‘001.000|ms’
col s5 format 999999 head ‘010.000|ms’
col s6 format 999999 head ‘100.000|ms’
col s7 format 999999 head ‘001.000| s’
col s8 format 999999 head ‘010.000| s’
col c1 format 999999 head ‘Cnt’
col c2 format 999999 head ‘Cnt’
col c3 format 999999 head ‘Cnt’
col c4 format 999999 head ‘Cnt’
col c5 format 999999 head ‘Cnt’
col c6 format 999999 head ‘Cnt’
col c7 format 999999 head ‘Cnt’
col c8 format 999999 head ‘Cnt’
set colsep |
set lines 300
COLUMN bt NEW_VALUE _bt NOPRINT
COLUMN et NEW_VALUE _et NOPRINT
COLUMN bt NEW_VALUE _bt NOPRINT
COLUMN et NEW_VALUE _et NOPRINT
select min(cast(hist.sample_time as date)) bt,
sysdate et
from dba_hist_active_sess_history hist,
v$database d,
v$instance i
where hist.dbid=d.dbid
and i.instance_number=hist.instance_number;
WITH xtimes (xdate) AS
  (SELECT to_date(‘&_bt’) xdate FROM dual
 UNION ALL
  SELECT xdate     +(
    &&interval_mins/1440)
  FROM xtimes
  WHERE xdate      +(
    &&interval_mins/1440) < sysdate
  )
select samplestart,sampleend,event,
        nvl(sum(bkt1),0) s1, count(bkt1) c1,
        nvl(sum(bkt2),0) s2, count(bkt2) c2,
        nvl(sum(bkt3),0) s3, count(bkt3) c3,
        nvl(sum(bkt4),0) s4, count(bkt4) c4,
        nvl(sum(bkt5),0) s5, count(bkt5) c5,
        nvl(sum(bkt6),0) s6, count(bkt6) c6,
        nvl(sum(bkt7),0) s7, count(bkt7) c7,
        nvl(sum(bkt8),0) s8, count(bkt8) c8 from (
SELECT samplestart,
  sampleend,
  event ,
  (
  CASE
    WHEN time_waited BETWEEN 1 AND 10
    THEN 1000*(time_waited/1000000)
  END ) bkt1,
  (
  CASE
    WHEN time_waited BETWEEN 10 AND 100
    THEN 1000*(time_waited/1000000)
  END ) bkt2,
  (
  CASE
    WHEN time_waited BETWEEN 10 AND 100
    THEN 1000*(time_waited/1000000)
  END ) bkt3,
  (
  CASE
    WHEN time_waited BETWEEN 100 AND 1000
    THEN 1000*(time_waited/1000000)
  END ) bkt4,
  (
  CASE
    WHEN time_waited BETWEEN 1000 AND 10000
      THEN 1000*(time_waited/1000000)
  END ) bkt5,
  (
  CASE
    WHEN time_waited BETWEEN 10000 AND 100000
    THEN 1000*(time_waited/1000000)
  END ) bkt6,
  (
  CASE
    WHEN time_waited BETWEEN 100000 AND 1000000
    THEN 1000*(time_waited/1000000)
  END ) bkt7,
  (
  CASE
    WHEN time_waited > 1000000
    THEN 1000*(time_waited/1000000)
  END ) bkt8
FROM
  (SELECT TO_CHAR(s1.xdate,’DD-MON-RR HH24:MI:SS’) samplestart,
    TO_CHAR(s1.xdate+(
    &&interval_mins /1440),’DD-MON-RR HH24:MI:SS’) sampleend,
    s2.event,
    s2.time_waited time_waited,
    s2.time_waited total_waits
  FROM xtimes s1,
    dba_hist_active_sess_history s2
  WHERE s2.sample_time BETWEEN s1.xdate AND s1.xdate+(
    &&interval_mins                                 /1440)
  )
)
where event is not null
and event like ‘%’||’&event_to_check’||’%’
group by samplestart,sampleend,event
order by samplestart,event
/
undefine interval_mins
undefine event_to_check
Some output …
    |   |   |000.001|   |000.010|   |000.100|   |001.000|   |010.000|   |100.000|   |001.000|   |010.000|
Begin Time     |End Time   |Event   | ms| Cnt| ms| Cnt| ms| Cnt| ms| Cnt| ms| Cnt| ms| Cnt|  s| Cnt|  s| Cnt
———————|———————|——————————————————-|——-|——-|——-|——-|——-|——-|——-|——-|——-|——-|——-|——-|——-|——-|——-|——-
11-FEB-12 20:00:00   |11-FEB-12 20:30:00   |cell smart table scan   |  0|  0|  0|  0|  0|  0|  0|  0|  0|  0| 10|  1|  0|  0|  0|  0
11-FEB-12 22:00:00   |11-FEB-12 22:30:00   |cell smart table scan   |  0|  0|  0|  0|  0|  0|  0|  0|  2|  1|  0|  0|  0|  0|  0|  0
13-FEB-12 23:00:00   |13-FEB-12 23:30:00   |cell smart table scan   |  0|  0|  0|  0|  0|  0|  1|  1|  0|  0| 24|  1|  0|  0|  0|  0
13-FEB-12 23:30:00   |14-FEB-12 00:00:00   |cell smart table scan   |  0|  0|  0|  0|  0|  0|  0|  1|  0|  0|  0|  0|  0|  0|  0|  0
14-FEB-12 01:30:00   |14-FEB-12 02:00:00   |cell smart table scan   |  0|  0|  0|  0|  0|  0|  0|  0|  0|  0| 22|  1|  0|  0|  0|  0
14-FEB-12 02:30:00   |14-FEB-12 03:00:00   |cell smart table scan   |  0|  0|  0|  0|  0|  0|  0|  0|  9|  1|  0|  0|  0|  0|  0|  0
14-FEB-12 05:00:00   |14-FEB-12 05:30:00   |cell smart table scan   |  0|  0|  0|  0|  0|  0|  0|  0|  1|  1|  0|  0|  0|  0|  0|  0
14-FEB-12 07:00:00   |14-FEB-12 07:30:00   |cell smart table scan   |  0|  0|  0|  2|  0|  2|  0|  0|  0|  0|  0|  0|  0|  0|  0|  0
14-FEB-12 08:30:00   |14-FEB-12 09:00:00   |cell smart table scan   |  0|  0|  0|  0|  0|  0|  0|  1|  0|  0|  0|  0|  0|  0|  0|  0
14-FEB-12 09:00:00   |14-FEB-12 09:30:00   |cell smart table scan   |  0|  0|  0|  0|  0|  0|  0|  0|  2|  1|  0|  0|  0|  0|  0|  0
    |   |   |000.001|   |000.010|   |000.100|   |001.000|   |010.000|   |100.000|   |001.000|   |010.000|
Begin Time     |End Time   |Event   | ms| Cnt| ms| Cnt| ms| Cnt| ms| Cnt| ms| Cnt| ms| Cnt|  s| Cnt|  s| Cnt
———————|———————|——————————————————-|——-|——-|——-|——-|——-|——-|——-|——-|——-|——-|——-|——-|——-|——-|——-|——-
14-FEB-12 10:30:00   |14-FEB-12 11:00:00   |cell smart table scan   |  0|  0|  0|  0|  0|  0|  0|  0|  1|  1|  0|  0|  0|  0|  0|  0
14-FEB-12 11:00:00   |14-FEB-12 11:30:00   |cell smart table scan   |  0|  0|  0|  0|  0|  0|  0|  1|  0|  0|  0|  0|  0|  0|  0|  0
14-FEB-12 13:00:00   |14-FEB-12 13:30:00   |cell smart table scan   |  0|  0|  0|  0|  0|  0|  1|  1|  0|  0|  0|  0|  0|  0|  0|  0
14-FEB-12 14:00:00   |14-FEB-12 14:30:00   |cell smart table scan   |  0|  0|  0|  0|  0|  0|  0|  1|  0|  0|  0|  0|  0|  0|  0|  0