This is part 3 of my series discussing a new technique for analyzing extended SQL trace files that I’m calling a “Trace Event Timeline”. The timeline is presented in a stacked bar chart format based on non-uniform intervals. Each stacked bar is the sum of the time spent in each recorded event during that particular timed interval. The intervals are non-uniform because they are taken only at points in between either WAIT events or recursive depth zero PARSE, EXEC or FETCH statements. A target interval length is derived by dividing the total trace file duration by the number of specified intervals, currently 20. When the running timeline of the trace file exceeds the target interval a new interval is started.

The purpose of the technique is to provide more information about when events occurred during the tracing period. Having just a resource profile of the trace file leaves out information about the event duration skew. An example might be having a large amount of ”SQL*Net message from client time” that exists almost completely at the start and end of the trace period. This might be in contrast to having that relatively evenly distributed across the entire interval. In the first case it might simply be a “scoping” problem with the start and end of the trace whereas the second example might be part of the actual performance issue (i.e. long client side processing separated by row fetches from the database).

As I mentioned in part 1 of this series, the idea for an event timeline occurred to me while I looking at a process that would do a bunch of database work very fast and then pause for a bit and would then speed up again. All sorts of conjecture about database overload were made, but all indications from a workload perspective showed that the database server was barely doing any work at all. The following shows the resource profile from a trace taken during the period that this behavior occurred:

                               Total Event  % Event      Total  --------------- Cumulative ----------------
Event Name                      Time (sec)     Time     Events  Avg Time(sec)  Min Time(sec)  Max Time(sec)
----------------------------   -----------  -------   --------  -------------  -------------  -------------
SQL*Net message from client     255.000799    48.11    152,647       0.001671       0.000138       0.290118
CPU Service                     244.962734    46.22    864,046       0.000284       0.000000       0.054992
unaccounted-for                  18.943126     3.57
db file sequential read          10.345820     1.95      3,262       0.003172       0.000017       0.295407
SQL*Net message to client         0.364421     0.07    152,647       0.000002       0.000000       0.002573
log file switch completion        0.285168     0.05          4       0.071292       0.003946       0.239785
log file sync                     0.130075     0.02         28       0.004646       0.000005       0.017599
latch: library cache              0.002779     0.00         36       0.000077       0.000005       0.001123
latch: cache buffers chains       0.002359     0.00          8       0.000295       0.000005       0.000621
SQL*Net more data from client     0.001583     0.00        201       0.000008       0.000005       0.000051
buffer busy waits                 0.000276     0.00          6       0.000046       0.000017       0.000144
latch: session allocation         0.000082     0.00          1       0.000082       0.000082       0.000082
latch: shared pool                0.000062     0.00          1       0.000062       0.000062       0.000062
SQL*Net more data to client       0.000034     0.00          1       0.000034       0.000034       0.000034
-----------------------------  -----------  -------  ---------  -------------  -------------  -------------
Total                           530.039318   100.00  1,172,888

Notice that 94% of the time was spent almost equally in just two events, “SQL*Net message from client” and “CPU service”. One might assume from looking at this resource profile, and even the individual events with a tkprof output, that the “SQL*Net message from client” could just be a scoping problem. Perhaps we started the trace too early or ended it too late (i.e. before the process started or after it ended).[1] However, from the trace event timeline shown below we see that this is not the case at all:

What we do see is that the “EXEC” event (i.e. CPU service for EXEC calls) dominates the timeline and then virtually stops for a short period of time, when we see the “SQL*Net message from client” event accumulate most of the time, and then the “EXEC” event takes over again. In fact, this mirrors the behavior that was observed during the actual running of the process, and from this information we can be pretty sure that the delay or “slowdown” is not happening because of the database. If there were contention or some resource shortage we would see that event and not the “SQL*Net message from client” event.

Hopefully I have provided a reasonably clear picture of what a trace event timeline is, how it can be created, and what it can be used for. We’ll have to see if this becomes a useful technique for those problems that are obscured by the skew of event time across a trace file timeline.

In Part 2 of this post I’m going to describe how the trace event timeline is created. I think it’s important to discuss which events are being captured and how the intervals are derived since it affects the output of the graph and of course, the validity of the technique. There will also be a Part 3 which will discuss the event timeline graph and how it may be used.

There are several issues that crop up when thinking about how to slice a trace file into intervals and what is valid to use as event totals. When I initially came up with the idea of an event timeline I posed the question to Jeff Holt at Method-R.com in their forum as to what he thought about the idea. He raised these same issues, and suffice it to say that trying to do this at the “statement” level would be very hard. Reconciling the recursive SQL and trying to account for the time across multiple intervals was beyond the scope of what I was trying to achieve. That’s the beauty of the Interval Resource Profiler. It only summarizes the entire trace file or interval, and it does not attempt the much more detailed analysis of statement level attribution. This makes it fairly easy from a scripting perspective to use non-uniform intervals based on statement timings for wait events and recursive depth zero parse, execute and fetch statements.

Now for some background on the current state of extended SQL trace files. As of 11.1.0.6 a SQL trace file looks something like this (this is just a small part of one trace file):

EXEC #6:c=0,e=83,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1219708745416872
WAIT #6: nam='SQL*Net message to client' ela= 1 driver #bytes=1 p3=0 obj#=-1 tim=1219708745416904
FETCH #6:c=0,e=84,p=0,cr=8,cu=0,mis=0,r=1,dep=0,og=1,tim=1219708745417024
STAT #6 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS  (cr=8 pr=0 pw=0 time=0 us cost=5 size=89 card=1)'
STAT #6 cnt=1 pid=1 pos=1 obj=71003 op='TABLE ACCESS BY INDEX ROWID ODM_PUBLICOBJECT (cr=4 pr=0 pw=0 time=0 us cost=3 size=73 card=1)'
STAT #6 cnt=1 pid=2 pos=1 obj=71009 op='INDEX UNIQUE SCAN SYS_C009848 (cr=3 pr=0 pw=0 time=0 us cost=2 size=0 card=1)'
STAT #6 cnt=1 pid=1 pos=2 obj=70836 op='TABLE ACCESS BY INDEX ROWID ODM_DOCUMENT (cr=4 pr=0 pw=0 time=0 us cost=2 size=16 card=1)'
STAT #6 cnt=1 pid=4 pos=1 obj=70839 op='INDEX UNIQUE SCAN SYS_C009781 (cr=3 pr=0 pw=0 time=0 us cost=1 size=0 card=1)'
WAIT #6: nam='SQL*Net message from client' ela= 1202 driver #bytes=1 p3=0 obj#=-1 tim=1219708745418336
FETCH #6:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1219708745418358
WAIT #6: nam='SQL*Net message to client' ela= 1 driver #bytes=1 p3=0 obj#=-1 tim=1219708745418375
WAIT #6: nam='SQL*Net message from client' ela= 87423 driver #bytes=1 p3=0 obj#=-1 tim=1219708745505813
EXEC #3:c=0,e=84,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1219708745505944
WAIT #3: nam='SQL*Net message to client' ela= 1 driver #bytes=1 p3=0 obj#=-1 tim=1219708745506104
FETCH #3:c=0,e=174,p=0,cr=11,cu=0,mis=0,r=3,dep=0,og=1,tim=1219708745506134
WAIT #3: nam='SQL*Net message from client' ela= 2607 driver #bytes=1 p3=0 obj#=-1 tim=1219708745508784

Oracle continues to add events and fields but the basic trace file format remains essentially the same (see Metalink note 39817.1). The first thing to notice is that the WAIT, PARSE, EXEC and FETCH statements all have “tim=” values. These values provide the basis for a running timeline for the interval being traced (see Optimizing Oracle Performance for the best description of a trace file). Unfortunately the “tim=” values for the WAIT statements do not yet appear to make sense in the overall timing (this is apparently due to Oracle bug 8342329), and aren’t available in older releases. However this can be dealt with by keeping a running timeline and using the “ela=” or elapsed time values to supplement the timeline between PARSE, EXEC and FETCH statements. This is, in fact, the approach taken with the Interval Resource Profiler.

Now, what about slicing a trace file into intervals? Given that we’re only interested in the entire trace file interval and that we have a running timeline, we can create non-uniform intervals as long as we don’t “double count” recursive CPU time (again see Optimizing Oracle Performance for a description of double counting recursive statements). That leaves us with creating our interval “splits” between WAIT events or recursive depth zero PARSE, EXEC and FETCH statements. The side effect of this is that the event totals for each interval may or may not be the same, hence the non-uniform part. This ultimately affects the graph representation as well, and I’ll cover that in part 3. Adding this code to the Interval Resource Profiler was actually pretty easy since the timeline tracking and event summarization was already there.

The basic timeline tracking consists of checking to see if the start time has been set for statements with a “tim=” value that are not WAIT events. If the start time has not been set then the timeline is set to the current time minus any previously recorded WAIT event time. If it has been set then if the current time is less than the start time the start time is reset to the current time. Otherwise the end time is set (the normal situation) and a check is made to see if we’ve passed over an event time boundary, and if so then a new boundary time is set.

Timeline

#
# Track interval time start and end
#
if ($time_start == 0) {
  $time_start = ($8 - $time_offset);
  $time_offset = 0;
  $time_end = $8;
  $time_skew = $time_end;
}
elsif ($8 < $time_start) {
  $time_start = $8;
}
else {
  $time_end = $8;
  #
  # Adjust the skew interval
  #
  if (($time_end-$time_skew) > $time_skew_intvl) {
    $time_skew = $time_end;
  }
}
#

If a PARSE, EXEC or FETCH statement and the recursive depth is zero (i.e. dep = 0) then the CPU time “c=” is added to the appropriate event total for this interval (i.e. PARSE, EXEC or FETCH).

PARSE|EXEC|FETCH

#
# Track the interval events for P|E|F dep=0
#
if ($10 == 0) {
  my $cmd = "'" . $1 . "'";
  if (defined $intvl_skew->{$time_skew}->{$cmd}) {
    $intvl_skew->{$time_skew}->{$cmd} += $3;
  }
  else {
    $intvl_skew->{$time_skew}->{$cmd} = $3;
  }
}
#

If this is a WAIT statement then the timeline consists of either adding the time to the “time_offset”, if the start time hasn’t been set, or adding it to the end time (in case no more tim= values are seen). The end time is then checked to see if we’ve passed  over an event time boundary and if so then we set a new one.

WAITs

#
if ($time_start == 0) {
  $time_offset = $ela;
}
$time_end += $ela;
#
# Adjust the skew interval
#
if (($time_end-$time_skew) > $time_skew_intvl) {
  $time_skew = $time_end;
}
#

The elapsed time (i.e. “ela=”) is then added to the event time for this interval.

#
# Track the interval events
#
if (defined $intvl_skew->{$time_skew}->{$nam}) {
  $intvl_skew->{$time_skew}->{$nam} += $ela;
}
else {
  $intvl_skew->{$time_skew}->{$nam} = $ela;
}
#

The only hard part left is determining what the base interval time should be for the event timeline. The Interval Resource Profiler is a two pass parser, so currently the event timeline interval is calculated in pass one by taking the entire trace file interval time and dividing it by the desired number of event intervals, currently 20. Then in pass 2 the previously described logic is applied to calculate the event timeline using the interval as $time_skew_intvl.

Once the event timeline has been calculated, it’s just a matter of graphing the results. This can be done in Perl using the GD Graphics Library package, this was how the graph in part 1 was created, or the results can be output to a CSV file and input into an Excel spreadsheet. In either case a pivot on the data must be performed in order to get the event time as a column for each interval row in order to create the graph. This will be part of the discussion of Part 3.

I was working on a problem recently where a process was “slow”. So naturally I got one of the DBAs to trace a sample of one of the runs and we took a look at it. The interesting part was that it was about half and half between SQL*Net message from client and CPU (EXEC statements). It turns out that the process would do a bunch of database work very fast and then just pause, issuing statements but much more slowly, and then it would speed up again. Naturally everyone blamed the database, but from the trace file one might assume that it was at least partly a client issue. The problem was that from the trace file there was no way to tell that the behavior was “skewed”, running fast then slowing down then running fast again.

This led me to thinking that it would be very handy in some cases to know a little bit more about when certain events occur within a traced session. Some of our famous brethren will usually say that that’s just a scoping problem, and while that is probably true, in the real world it’s not always so obvious, or easy to do something about. So I decided to modify the AppsDBA Interval Resource Profiler to see if I could create an “Event Timeline”. The following is the result:

The idea is that the graph displays the event totals in a timeline as they occurred. It seems to make it easier to determine roughly when actions took place. In other words, is there event skew? Not skew for a particular event, which is what the Hotsos/Method-R Profiler gives you, but across the entire trace interval. The timeline should help determine if all of the activity took place in a small set of intervals, or evenly across the whole interval, or perhaps like my original problem in spurts. The resource profile that goes along with this graph looks like the following:

                          Total Event  % Event    Total  --------------- Cumulative ----------------
Event Name                 Time (sec)     Time   Events  Avg Time(sec)  Min Time(sec)  Max Time(sec)
------------------------  -----------  -------  -------  -------------  -------------  -------------
SQL*Net message from         0.801698    77.92      262       0.003060       0.000280       0.150290
client
SQL*Net more data from       0.132364    12.87      520       0.000255       0.000003       0.019935
client
CPU Service                  0.058989     5.73      478       0.000123       0.000000       0.010998
unaccounted-for              0.033580     3.26
library cache pin            0.000746     0.07        4       0.000187       0.000147       0.000254
library cache lock           0.000610     0.06        3       0.000203       0.000161       0.000237
gc current grant busy        0.000563     0.05        1       0.000563       0.000563       0.000563
SQL*Net message to           0.000285     0.03      262       0.000001       0.000000       0.000031
Client
SQL*Net more data to         0.000016     0.00        1       0.000016       0.000016       0.000016
client
------------------------  -----------  -------  -------  -------------  -------------  -------------
Total                        1.028851   100.00    1,531

I’ll have more to say about this in the near future.

Conditional compilation was a feature added to Oracle 10gR2 for PL/SQL, but appears to be available in releases 9.2 and 10.1. It seems like a cool feature but I had never needed it for anything that I could think of. However as I’ve spent more and more time writing PL/SQL lately I’ve realized that it is an excellent way of protecting instrumentation that may be dependent on external calls. My example involves the Hotsos Instrumentation Library for Oracle (ILO) which I have been using a lot lately. Without conditional compilation, code written that calls the ILO will fail to compile if the ILO hasn’t been installed. However with conditional compilation the code can be “hidden” and can be used without change even if the ILO has not been installed. The following will show an example. I’ve taken the liberty of renaming the HOTSOS_ILO_TASK call to HOTSOS1_ILO_TASK simply because the package is installed in my test database.

My first example attempts to compile my procedure after setting my selection directive (i.e. hotsos_ilo) to true. The code will fail to compile due to the lack of the HOTSOS1_ILO_TASK package.

SQL> alter session set plsql_ccflags = 'hotsos_ilo:true';

Session altered.

SQL> create or replace procedure test_cond
2 is
3 begin
4 $IF $$hotsos_ilo $THEN
5 HOTSOS1_ILO_TASK.BEGIN_TASK(
6 module => 'Set Module',
7 action => 'Set Action');
8 $END
9 --
10 dbms_lock.sleep(5);
11 --
12 $IF $$hotsos_ilo $THEN
13 HOTSOS1_ILO_TASK.END_TASK;
14 $END
15 end;
16 /


Warning: Procedure created with compilation errors.

SQL> show errors
Errors for PROCEDURE TEST_COND:

LINE/COL ERROR
-------- -----------------------------------------------------------------
5/5 PL/SQL: Statement ignored
5/5 PLS-00201: identifier 'HOTSOS1_ILO_TASK.BEGIN_TASK' must be
declared
13/5 PL/SQL: Statement ignored
13/5 PLS-00201: identifier 'HOTSOS1_ILO_TASK.END_TASK' must be
declared


The next example shows a successful compilation after setting the selection directive (i.e. hotsos_ilo) to false.

SQL> alter session set plsql_ccflags = 'hotsos_ilo:false';

Session altered.

SQL> --
SQL> create or replace procedure test_cond
2 is
3 begin
4 $IF $$hotsos_ilo $THEN
5 HOTSOS1_ILO_TASK.BEGIN_TASK(
6 module => 'Set Module',
7 action => 'Set Action');
8 $END
9 --
10 dbms_lock.sleep(5);
11 --
12 $IF $$hotsos_ilo $THEN
13 HOTSOS1_ILO_TASK.END_TASK;
14 $END
15 end;
16 /


Procedure created.

SQL>

I’ve been a proponent of using services both to help categorize database connections and to use them to help classify workload. For applications where “you can’t touch the code” this can be the only way to come up with categories to measure application workload. Recently I’ve started using a “backup” service to identify the cost backups contribute to overall system workload. The problem with services however is that there are only limited ways to associate a service to a connection. For “internal” connections a service can be associated with a scheduler job through a job class, and can also be associated with parallel execution or parallel DML, or with advanced queuing (although I’ve only used scheduler jobs with services). As for client connections, the service is assigned with the “SERVICE_NAME” parameter on the connect string. This implies a connection through the listener since this is typically part of Oracle net services. This can pose a problem for backups since this creates, in my opinion, an unnecessary dependence on the listener being up in order to take advantage of running the backup process through a service.

Typically a backup program, and we’ll talk about RMAN here but it could be any product really, will connect to the database through a “bequeath” connection by setting the ORACLE_SID environment variable as part of the environment setup. This type of connection doesn’t require that a listener be available, and also doesn’t need a tnsnames.ora entry. Unfortunately there is also no way to associate the connection with a service that I’ve found. However, I have stumbled upon a solution. It turns out that it is possible to define a “bequeath” connection in the tnsnames.ora file and subsequently use the SERVICE_NAME parameter as part of the connect string. This type of connection, even though part of the tnsnames.ora file, doesn’t require a listener to work. I stumbled upon this in Metalink note 132764.1, and it seems that it has always existed, at least since Oracle7 and SQL Net V2, based on some of the other notes available on Metalink.

The following will show an example of setting up the TNS entry and then setting up the backup service and running RMAN connected to the new backup service.

The first task is to create the service in the database. The following example is for a single instance database, in RAC you should use srvctl.

SQL> show parameters service

NAME                         TYPE        VALUE
---------------------------- ----------- -------------------------------------------
service_names                string      orcl.appsdba.com
SQL> alter system set service_names = "orcl.appsdba.com,backup.appsdba.com" scope=both;

System altered.

SQL> show parameters service

NAME                         TYPE        VALUE
---------------------------- ----------- -------------------------------------------
service_names                string      orcl.appsdba.com,backup.appsdba.com
SQL>

Verify the listener service registration:

$ lsnrctl services

LSNRCTL for Linux: Version 10.1.0.5.0 - Production on 25-JUN-2008 10:12:00

Copyright (c) 1991, 2004, Oracle.  All rights reserved.

Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=orcl)))
Services Summary...
Service "PLSExtProc" has 1 instance(s).
  Instance "PLSExtProc", status UNKNOWN, has 1 handler(s) for this service...
    Handler(s):
      "DEDICATED" established:0 refused:0
         LOCAL SERVER
Service "backup.appsdba.com" has 1 instance(s).
  Instance "orcl", status READY, has 1 handler(s) for this service...
    Handler(s):
      "DEDICATED" established:1 refused:0 state:ready
         LOCAL SERVER
Service "orcl" has 1 instance(s).
  Instance "orcl", status UNKNOWN, has 1 handler(s) for this service...
    Handler(s):
      "DEDICATED" established:0 refused:0
         LOCAL SERVER
Service "orcl.appsdba.com" has 1 instance(s).
  Instance "orcl", status READY, has 1 handler(s) for this service...
    Handler(s):
      "DEDICATED" established:1 refused:0 state:ready
         LOCAL SERVER
The command completed successfully
$

Let’s show the service registration in the database:

SQL> select * from v$services where service_id = 10;

SERVICE_ID NAME                       NAME_HASH
---------- -------------------------- ----------
NETWORK_NAME
------------------------------------------------
CREATION_ CREATION_DATE_HASH
--------- ------------------
        10 backup.appsdba.com         833319543
backup.appsdba.com
25-JUN-08          638794112

SQL>

Now, we’ll show the tnsnames.ora entry. Note that the protocol is “beq” for bequeath and that we’ve used the SERVICE_NAME for our backup service. Also note that as part of the definition we’ve concatenated the “oracle” executable name and our oracle SID name for the ARGV0 value.

ORCL_BACKUP =
  (DESCRIPTION =
    (ADDRESS =
      (PROTOCOL = BEQ)
      (PROGRAM = oracle)
      (ARGV0 = oracleorcl)
      (ARGS = '(DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))')
    )
    (CONNECT_DATA =
      (SERVICE_NAME = backup.appsdba.com)
    )
  )

Now let’s test the database connection:

$ sqlplus system@orcl_backup

SQL*Plus: Release 10.1.0.5.0 - Production on Wed Jun 25 10:19:06 2008

Copyright (c) 1982, 2005, Oracle.  All rights reserved.

Enter password: 

Connected to:
Oracle Database 10g Enterprise Edition Release 10.1.0.5.0 - Production
With the Partitioning, OLAP and Data Mining options

SQL> select USERNAME, SERVER, PROGRAM, STATUS, SERVICE_NAME
from v$session where username = 'SYSTEM';

USERNAME                       SERVER    PROGRAM                            STATUS
------------------------------ --------- ---------------------------------- --------
SERVICE_NAME
----------------------------------------------------------------
SYSTEM                         DEDICATED sqlplus@appsdba.com (TNS V1-V3)    ACTIVE
backup.appsdba.com

SQL>

So, we’ve connected to the database and verified through the v$session view that we’ve connected to our backup service.
Now let’s connect with RMAN:

$ $ORACLE_HOME/bin/rman nocatalog target /@orcl_backup

Recovery Manager: Release 10.1.0.5.0 - Production

Copyright (c) 1995, 2004, Oracle.  All rights reserved.

connected to target database: ORCL (DBID=3806185278)
using target database controlfile instead of recovery catalog

RMAN>

In another session we’ll query v$session again:

SQL> l
  1  select username, status, program, service_name from v$session
  2* where username = 'SYS'
SQL> /

USERNAME                       STATUS   PROGRAM
------------------------------ -------- --------------------------------
SERVICE_NAME
----------------------------------------------------------------
SYS                            ACTIVE   sqlplus@appsdba.com (TNS V1-V3)
SYS$USERS

SYS                            INACTIVE rman@appsdba.com (TNS V1-V3)
backup.appsdba.com

SYS                            INACTIVE rman@appsdba.com (TNS V1-V3)
backup.appsdba.com

SQL>

Now let’s verify that we can still connect with no listener:

/u01/app/oracle/local/bkup$ lsnrctl stop

LSNRCTL for Linux: Version 10.1.0.5.0 - Production on 25-JUN-2008 10:33:09

Copyright (c) 1991, 2004, Oracle.  All rights reserved.

Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=orcl)))
The command completed successfully
/u01/app/oracle/local/bkup$

Now let’s see if we can connect with our normal TNS alias:

/u01/app/oracle/local/bkup$ sqlplus system@orcl

SQL*Plus: Release 10.1.0.5.0 - Production on Wed Jun 25 10:33:23 2008

Copyright (c) 1982, 2005, Oracle.  All rights reserved.

Enter password:
ERROR:
ORA-12541: TNS:no listener

Enter user-name:

And no, we can’t because the listener is down. Now let’s see if our backup connection will work:

/u01/app/oracle/local/bkup$ $ORACLE_HOME/bin/rman nocatalog target /@orcl_backup

Recovery Manager: Release 10.1.0.5.0 - Production

Copyright (c) 1995, 2004, Oracle.  All rights reserved.

connected to target database: ORCL (DBID=3806185278)
using target database controlfile instead of recovery catalog

RMAN> exit

Recovery Manager complete.
/u01/app/oracle/local/bkup$

And indeed it does. We now have a backup service and it is independent of the Oracle network listener.

I’ve been working on a project with a very large subpartitioned table and I’ve been trying to come up with a sensible statistics generation strategy. This application is on a Linux based RAC system currently running 10g R2 (10.2.0.3). I’ve been trying to use every source of information available and of course, many 10053 traces. I came across this little blurb on Jonathon Lewis’ web site:

Sub-Partition stats (12^th June)

Page 39, Second paragraph:

The problem of partitions and table-level statistics echoes on down the chain to subpartitions. If you want to query exactly one subpartition of one partition, then the optimizer uses the statistics for that one subpartition.

This is wrong. It looks as if Oracle hardly uses sub-partition statistics at all. I have a test case on 10.2.0.1 which shows the optimizer using the partition level statistics to calculate the cardinality of a very simple query that has been identified as targeting exactly one sub-partition of one partition.  However, the access path is a full table scan of that sub-partition, and the cost of the scan is clearly derived from the number of blocks in the sub-partition.

Thanks to Adrian Billington for bringing this to my attention.

I must say that this mirrors what I’ve found. For the queries that I’ve been modeling, the 10053 traces lead me to believe that the optimizer only considers the row and block counts for the pruned subpartitions in its calculations. All other information, including histogram statistics, all appear to be taken from the partition level only.   

The following excerpt from a 10053 trace is the only place that I’ve found where the optimizer considers the subpartition statistics:

Table Stats::
Table: mytab Alias: mytab (making adjustments for partition skews)
ORIGINAL VALUES:: #Rows: 286200000 #Blks: 1598304 AvgRowLen: 82.00
SUBPARTITIONS::
PRUNED: 1
ANALYZED: 1 UNANALYZED: 0
Partition [5]
#Rows: 286200000 #Blks: 1598304 AvgRowLen: 82.00
#Rows: 25004700 #Blks: 135309 AvgRowLen: 82.00 <== This is the only place that reflects subpartition stats.

The following blog post by Tom Kyte (http://tkyte.blogspot.com/2008/01/why-do-people-do-this.html) prompted me to re-evaluate my error handling in the PL/SQL that I’ve written for a large project that I’m working on. Tom feels very strongly about exception handling, and while I don’t disagree, I hadn’t considered the value of the originating line number as all that important. In reading some of the sources cited at the end of this article I got curious about seeing just how hard it would be to save a little more information about the original error, including the original line number. The following are the results of my investigation.

I should note that all of this was done with Oracle 10g and utilizes the DBMS_UTILITY and its “format” functions. Earlier releases won’t be able to make use of some/all(?) of these features, but I guess that’s the price of progress. I offer the following basic tenets of exception handling with a nod to both Tom and Steven Feuerstein for the inspiration:

1) Trap exceptions as close to the point of the error being raised as possible.

2) Never hide an exception. Exceptions should be raised because of errors and errors should always be propogated to the calling function (the client application in Tom speak).

2a) If a WHEN OTHERS is used then it MUST re-raise the exception.

3) Always capture the line number and error message where the exception is raised (this can be hard if you’re following number 1).

4) Handle all exceptions that can be handled. Do the work up front rather than forcing someone to debug your “generic” exceptions later.

The following example is taken straight from the Oracle documentation (1) with the exception of changes to the “Top_With_Logging” procedure. I’ve commented the original code in the exception handler and added calls for each of the three DBMS_UTILITY “format” functions.


CREATE OR REPLACE PROCEDURE Top_With_Logging IS
-- NOTE: SqlErrm in principle gives the same info as Format_Error_Stack.
-- But SqlErrm is subject to some length limits,
-- while Format_Error_Stack is not.
BEGIN
P5();
EXCEPTION
WHEN OTHERS THEN
-- Log_Errors ( 'Error_Stack...' || Chr(10) ||
-- DBMS_UTILITY.FORMAT_ERROR_STACK() );
-- Log_Errors ( 'Error_Backtrace...' || Chr(10) ||
-- DBMS_UTILITY.FORMAT_ERROR_BACKTRACE() );
--
DBMS_OUTPUT.PUT_LINE ( '----------' );
DBMS_OUTPUT.PUT_LINE ( 'FORMAT_CALL_STACK:' );
DBMS_OUTPUT.PUT_LINE( DBMS_UTILITY.FORMAT_CALL_STACK() );
--
DBMS_OUTPUT.PUT_LINE ( '----------' );
DBMS_OUTPUT.PUT_LINE ( 'FORMAT_ERROR_STACK:' );
DBMS_OUTPUT.PUT_LINE( DBMS_UTILITY.FORMAT_ERROR_STACK() );
--
DBMS_OUTPUT.PUT_LINE ( '----------' );
DBMS_OUTPUT.PUT_LINE ( 'FORMAT_ERROR_BACKTRACE:' );
DBMS_OUTPUT.PUT_LINE( DBMS_UTILITY.FORMAT_ERROR_BACKTRACE() );
--
DBMS_OUTPUT.PUT_LINE ( '----------' );
END Top_With_Logging;
/


The following will show the creation of each of the test procedures
as shown in the original example:

SQL*Plus: Release 10.2.0.3.0 - Production on Thu Jan 31 09:12:37 2008

Copyright (c) 1982, 2006, Oracle. All Rights Reserved.

Connected to:
Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP and Data Mining options

SQL> CREATE OR REPLACE PROCEDURE P0 IS
e_01476 EXCEPTION; pragma exception_init ( e_01476, -1476 );
BEGIN
RAISE e_01476;
END P0;
/ 2 3 4 5 6

Procedure created.

SQL> l
1 CREATE OR REPLACE PROCEDURE P0 IS
2 e_01476 EXCEPTION; pragma exception_init ( e_01476, -1476 );
3 BEGIN
4 RAISE e_01476;
5 END P0;
6*
SQL> CREATE OR REPLACE PROCEDURE P1 IS
BEGIN
P0();
END P1;
/
SHOW ERRORS

CREATE OR REPLACE PROCEDURE P2 IS
BEGIN
P1();
END P2;
/
SHOW ERRORS

CREATE OR REPLACE PROCEDURE P3 IS
BEGIN
P2();
END P3;
/
SHOW ERRORS

CREATE OR REPLACE PROCEDURE P4 IS
BEGIN P3(); END P4;
/
CREATE OR REPLACE PROCEDURE P5 IS
BEGIN P4(); END P5;
/
SHOW ERRORS 2 3 4 5
Procedure created.

SQL> No errors.
SQL> SQL> 2 3 4 5
Procedure created.

SQL> No errors.
SQL> SQL> 2 3 4 5
Procedure created.

SQL> No errors.
SQL> SQL> 2 3
Procedure created.

SQL> 2 3
Procedure created.

SQL>
No errors.
SQL>
SQL> CREATE OR REPLACE PROCEDURE Top_Naive IS
BEGIN
P5();
END Top_Naive;
/ 2 3 4 5

Procedure created.

SQL> CREATE OR REPLACE PROCEDURE Top_With_Logging IS
-- NOTE: SqlErrm in principle gives the same info as Format_Error_Stack.
-- But SqlErrm is subject to some length limits,
-- while Format_Error_Stack is not.
BEGIN
P5();
EXCEPTION
WHEN OTHERS THEN
-- Log_Errors ( 'Error_Stack...' || Chr(10) ||
-- DBMS_UTILITY.FORMAT_ERROR_STACK() );
-- Log_Errors ( 'Error_Backtrace...' || Chr(10) ||
-- DBMS_UTILITY.FORMAT_ERROR_BACKTRACE() );
--
DBMS_OUTPUT.PUT_LINE ( '----------' );
DBMS_OUTPUT.PUT_LINE ( 'FORMAT_CALL_STACK:' );
DBMS_OUTPUT.PUT_LINE( DBMS_UTILITY.FORMAT_CALL_STACK() );
--
DBMS_OUTPUT.PUT_LINE ( '----------' );
DBMS_OUTPUT.PUT_LINE ( 'FORMAT_ERROR_STACK:' );
DBMS_OUTPUT.PUT_LINE( DBMS_UTILITY.FORMAT_ERROR_STACK() );
--
DBMS_OUTPUT.PUT_LINE ( '----------' );
DBMS_OUTPUT.PUT_LINE ( 'FORMAT_ERROR_BACKTRACE:' );
DBMS_OUTPUT.PUT_LINE( DBMS_UTILITY.FORMAT_ERROR_BACKTRACE() );
--
DBMS_OUTPUT.PUT_LINE ( '----------' );
END Top_With_Logging;
/

2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28
Procedure created.

SQL>

Now we’ll run the first example calling the Top_Naive procedure which will simply call the P5 procedure which will invoke the chain of procedures with the P0 procedure raising an error. The Top_Naive procedure has no exception handling so we see the full chain of events. Notice that the initial exception that occurs in P0 tells us the line number of the offending statement (during the install above I listed the PO procedure to show the line numbers).

SQL> Set ServerOutput On
call Top_Naive()SQL>
2 /
call Top_Naive()
*
ERROR at line 1:
ORA-01476: divisor is equal to zero
ORA-06512: at "TEST.P0", line 4
ORA-06512: at "TEST.P1", line 3
ORA-06512: at "TEST.P2", line 3
ORA-06512: at "TEST.P3", line 3
ORA-06512: at "TEST.P4", line 2
ORA-06512: at "TEST.P5", line 2
ORA-06512: at "TEST.TOP_NAIVE", line 3

Now we’ll run the second example and see the bare output of each of the three DBMS_UTILITY “format” functions:

SQL> Set ServerOutput On
SQL> call Top_With_Logging();
----------
FORMAT_CALL_STACK:
----- PL/SQL Call Stack -----
object line object
handle number name
0xee5cbec8 16 procedure TEST.TOP_WITH_LOGGING

----------
FORMAT_ERROR_STACK:
ORA-01476: divisor is equal to zero

----------
FORMAT_ERROR_BACKTRACE:
ORA-06512: at "TEST.P0", line 4
ORA-06512: at "TEST.P1", line 3
ORA-06512: at "TEST.P2", line 3
ORA-06512: at "TEST.P3", line 3
ORA-06512:
at "TEST.P4", line 2
ORA-06512: at "TEST.P5", line 2
ORA-06512: at "TEST.TOP_WITH_LOGGING", line 6

----------

Call completed.

SQL>

We see that the FORMAT_CALL_STACK function only shows us the information from the call to the FORMAT_CALL_STACK function. The FORMAT_ERROR_STACK call shows us the actual error message message only, and the FORMAT_ERROR_BACKTRACE call shows us the full execution path with originating line number. Note that we still need the FORMAT_ERROR_STACK call in order to get the original error message.

Another way to achieve the same thing would be to capture the exception at the source. The following shows a different take on handling the exception and being able to capture the line number and error message. This example simply outputs the messages using DBMS_OUTPUT, but in reality this could be logged to an error table:

CREATE OR REPLACE PROCEDURE P0 IS
e_01476 EXCEPTION; pragma exception_init ( e_01476, -1476 );
BEGIN
RAISE e_01476;
EXCEPTION
WHEN others THEN
dbms_output.put_line(SQLERRM);
dbms_output.put_line(DBMS_UTILITY.FORMAT_ERROR_BACKTRACE());
raise; -- Note that we still raise an exception!
END P0;
/

SQL> CREATE OR REPLACE PROCEDURE P0 IS
e_01476 EXCEPTION; pragma exception_init ( e_01476, -1476 );
BEGIN
RAISE e_01476;
EXCEPTION
WHEN others THEN
dbms_output.put_line(SQLERRM);
dbms_output.put_line(DBMS_UTILITY.FORMAT_ERROR_BACKTRACE());
raise;
END P0;
/ 2 3 4 5 6 7 8 9 10 11

Procedure created.

SQL> call Top_Naive();
ORA-01476: divisor is equal to zero
ORA-06512: at "TEST.P0", line 4

call Top_Naive()
*
ERROR at line 1:
ORA-01476: divisor is equal to zero
ORA-06512: at "TEST.P0", line 9
ORA-06512: at "TEST.P1", line 3
ORA-06512: at "TEST.P2", line 3
ORA-06512: at "CPPTEST.P3", line 3
ORA-06512: at "TEST.P4", line 2
ORA-06512: at "TEST.P5", line 2
ORA-06512: at "TEST.TOP_NAIVE", line 3

SQL>

Now we see that the error message and line number are output and then the exception is propogated back to the initial invoking procedure. This provides an easy way to trap all exception information and provides the possiblity of capturing the entire exception path. This may not be as important for an interactive system, but can be invaluable for a “batch” system running in an automated fashion.

Sources:

(1) Oracle® Database PL/SQL Packages and Types Reference, 10g Release 2 (10.2),
Part Number B14258-01, Section on DBMS_UTILITY

(2) http://www.oracle.com/technology/oramag/oracle/05-mar/o25plsql.html

(3) http://tkyte.blogspot.com/2008/01/why-do-people-do-this.html

(4) http://asktom.oracle.com/pls/asktom/f?p=100:11:0::::P11_QUESTION_ID:433029981484

(5) http://asktom.oracle.com/pls/asktom/f?p=100:11:0::::P11_QUESTION_ID:4684561825338

Recently I’ve had the opportunity to get more familiar with the Oracle scheduler. In the example I will talk about here, the scheduler was used to automate the refresh of a materialized view and an Oracle Text (i.e. context) index associated with that view. As of Oracle 10.2 when you create a materialized view Oracle will use the old dbms_jobs interface to automagically build an automatic refresh job. In this case I decided to use the newer dbms_scheduler interface since I wanted to tie the materialized view refresh and the Oracle Text index refresh together since the index is dependent on the materialized view. This requires that you first create the materialized view as an “ON DEMAND” job and then write your own commands to create the scheduler pieces to run the refresh.

As it turns out this is more involved than one might think. To do this involves creating a program definition for each “step”, defining a chain and the steps in that chain, and then chain rules to tell Oracle what to do when a step completes successfully or errors out. Lastly you actually define the job that will run in the scheduler. The following shows the syntax for each of these steps.

--
-- Create the scheduler programs
--
BEGIN
DBMS_SCHEDULER.CREATE_PROGRAM (
program_name => 'TABLE_MV_PGM',
program_type => 'PLSQL_BLOCK',
program_action => 'BEGIN DBMS_MVIEW.REFRESH(''TABLE_MV'', ''F'', ''''); END;',
enabled => TRUE,
comments => 'Refresh materialized view');
END;
/
--
BEGIN
DBMS_SCHEDULER.CREATE_PROGRAM (
program_name => 'TABLE_MV_CTXIDX_PGM',
program_type => 'PLSQL_BLOCK',
program_action => 'BEGIN ctxsys.drvdml.auto_sync_index(''TABLE_MV_CTXIDX'', 12582912, NULL, NULL, NULL, 0); END;',
enabled => TRUE,
comments => 'Refresh text index');
END;
/
--
-- Define the job chain
--
BEGIN
DBMS_SCHEDULER.CREATE_CHAIN (
chain_name => 'TABLE_CHAIN',
rule_set_name => NULL,
evaluation_interval => NULL,
comments => 'Job Chain to refresh TABLE materialized view');
END;
/
--
-- Define the chain steps
--
BEGIN
DBMS_SCHEDULER.DEFINE_CHAIN_STEP (
chain_name => 'TABLE_CHAIN',
step_name => 'Step1',
program_name => 'TABLE_MV_PGM');
END;
/
--
BEGIN
DBMS_SCHEDULER.DEFINE_CHAIN_STEP (
chain_name => 'TABLE_CHAIN',
step_name => 'Step2',
program_name => 'TABLE_MV_CTXIDX_PGM');
END;
/
--
-- Define the chain rules
--
BEGIN
DBMS_SCHEDULER.DEFINE_CHAIN_RULE (
chain_name => 'TABLE_CHAIN',
condition => 'TRUE',
action => 'START Step1',
rule_name => 'TABLE_Rule1',
comments => 'Start the chain');
END;
/
--
BEGIN
DBMS_SCHEDULER.DEFINE_CHAIN_RULE (
chain_name => 'TABLE_CHAIN',
condition => 'Step1 COMPLETED',
action => 'START Step2',
rule_name => 'TABLE_Rule2');
END;
/
--
BEGIN
DBMS_SCHEDULER.DEFINE_CHAIN_RULE (
chain_name => 'TABLE_CHAIN',
condition => 'Step1 COMPLETED AND Step2 COMPLETED',
action => 'END',
rule_name => 'TABLE_Rule3');
END;
/
--
-- Enable the chain
--
BEGIN
DBMS_SCHEDULER.ENABLE ('TABLE_CHAIN');
END;
/
--
-- Create the job
--
BEGIN
DBMS_SCHEDULER.CREATE_JOB (
job_name => 'TABLE_JOB',
job_type => 'CHAIN',
job_action => 'TABLE_CHAIN',
repeat_interval => 'freq=daily;byhour=23;byminute=0;bysecond=0',
enabled => TRUE);
END;
/

It is possible to set this up in Enterprise Manager, although I had problems with the Grid Control version and found it easier to use the scripts above to create the programs, chain and job. I do however find it much easier to administer the scheduler components in Grid Control once it is set up. I have not been as impressed with the Database Control flavor of Enterprise Manager though, and I’m not sure why the two are different for administering the scheduler.

I’ve been using the timestamp data type to capture timing information for a process and my first try at it didn’t work very well. I don’t think Oracle’s documentation is very good at helping figure them out either, so I thought I’d share the PL/SQL that I used to decipher what I needed to make use of timestamp data:

declare
l_starttim TIMESTAMP;
l_elapsedtim INTERVAL DAY TO SECOND;
p_tottime VARCHAR2(100);
l_loadtime VARCHAR2(100);
begin
l_starttim := SYSTIMESTAMP;
dbms_lock.sleep(5);
IF l_elapsedtim IS NULL THEN
l_elapsedtim := SYSTIMESTAMP-l_starttim;
ELSE
l_elapsedtim := l_elapsedtim + (SYSTIMESTAMP-l_starttim);
END IF;
--
dbms_output.put_line(to_char(l_starttim));
dbms_output.put_line(to_char(l_elapsedtim));
--
l_starttim := SYSTIMESTAMP;
dbms_lock.sleep(5);
IF l_elapsedtim IS NULL THEN
l_elapsedtim := SYSTIMESTAMP-l_starttim;
ELSE
l_elapsedtim := l_elapsedtim + (SYSTIMESTAMP-l_starttim);
END IF;
--
dbms_output.put_line(to_char(l_starttim));
dbms_output.put_line(to_char(l_elapsedtim));
--
p_tottime := TO_CHAR(l_elapsedtim);
dbms_output.put_line('p_tottime: '||p_tottime);
DBMS_OUTPUT.PUT_LINE('Hour: '||extract(HOUR FROM l_elapsedtim));
DBMS_OUTPUT.PUT_LINE('Minute: '||extract(MINUTE FROM l_elapsedtim));
DBMS_OUTPUT.PUT_LINE('Seconds: '||ROUND(extract(SECOND FROM l_elapsedtim),2));
--
l_loadtime := SUBSTR(TO_CHAR(extract(HOUR FROM l_elapsedtim),'00'),2)||':'||
SUBSTR(TO_CHAR(extract(MINUTE FROM l_elapsedtim),'00'),2)||
':'||SUBSTR(TO_CHAR(ROUND(extract(SECOND FROM l_elapsedtim),2),'00.99'),2);
dbms_output.put_line('l_loadtime: '||l_loadtime);
end;
/

I was reviewing the Open World presentations and came across Cary Millsap’s presentation titled “IOUG: Why You Can’t See Your Real Performance Problems“. Now I’ve seen Cary speak many times but I didn’t get to see this presentation at Open World. After reviewing his slides I wish I had. I think he’s really hit the nail on the head as to why you must use extended SQL trace data to identify performance problems. He has actually tied several topics that he’s used in the past together to make a very persuasive argument as to why other methods fail to find performance problems as effectively as trace data does. This made me realize that there was a very heavy emphasis at this Open World conference on using what I’ll call “database” oriented data to identify performance problems. In other words, AWR, ADDM, ASH, direct sampling of v$ views, OEM and all manner of “advisors” were touted as the way to identify your performance problem. It seems that Cary’s “discovery” of using extended SQL trace data to “profile” performance problems has fallen out of favor. Whether this has truly happened or not, it seems to me that it is rare to hear anyone other than a Hotsos employee talk about using extended SQL trace data to start out a tuning exercise. Of course AppsDBA.com has offered a free interval resource profiler for several years now, so maybe we also qualify as profiling practitioners. It just seems surprising to me that so many are still so intent on finding the “holy grail” of performance tuning when it is sitting right under their noses, if they just looked.