There’s this weird situation in the industry. On one hand there are people who spent years working with databases. They know pretty much all the weird intricacies of their DB of choice and the concepts like tracing are so basic as to not even requiring their attention.

On the other hand there are plenty of people just starting. And if we’re talking about performance optimizing, it’s not like they’re newbies. From what I see most of them are the same experienced developers just working with different technologies. It’s just that this time their issue lies in the database they use and they lack the necessary bit of knowledge.

They’re left with searching on google and piecing these obscure bits of knowledge and outdated techniques together. To be perfectly honest I’m writing this post to direct folks asking me these questions to it. So that when I ask for a trace file to look at I know they can actually get one ;)

This is a repost from my old blog that is now lost to time and carelessness. I found some of my drafts and reedited a handful that might be interesting to read.

So you might have read it before but it's not like I have a massive following so you probably haven't ;)

Why trace?

To see what a given session is doing at the moment it may be enough to just query V$SESSION. We’re gonna see what query it is executing now, what event it is waiting for, etc. And it’s all useful.

But if something is slow, I want tangible metrics. I want to know what is going on and how slow it is exactly. So I trace a session for a while instead of just getting a momentary snapshot of what it’s doing.

What’s in a trace file?

The output of tracing is a trace file. And it has lots info.

Which SQL queries were run and how many times.
How long did a query take.
Which plan did the database use for each query.
Total run times.
Wait times (if switched on).

How to start and stop tracing?

Timed statistics caveat

Make sure you’re gathering timed statistics. Trace files without times may be fine in some cases, but I feel like they’re useless for performance optimizing.

SHOW PARAMETER timed_statistics

You want this parameter to be TRUE.

NAME                    TYPE        VALUE
----------------------- ----------- ---------------------------
timed_statistics        boolean     TRUE

If that’s not what you get, well, go ahead.

ALTER SYSTEM SET timed_statistics = TRUE

Own session

If you were able to pinpoint the slow code then wrap it in trace start/stop commands and run it in your own session.

DBMS_SESSION.SESSION_TRACE_ENABLE;

... some code ...

DBMS_SESSION.SESSION_TRACE_DISABLE;

There’re actually two optional parameters that SESSION_TRACE_ENABLE accepts: waits and binds.

DBMS_SESSION.SESSION_TRACE_ENABLE(
   waits  IN   BOOLEAN DEFAULT TRUE,
   binds  IN   BOOLEAN DEFAULT FALSE);

It’s pretty obvious what they do — gather detailed info on wait times and bind variables used. Defaults are pretty sensible so leave them as they are unless you count on seeing values of the bind variables.

Someone else’s session

More often though you know that some task is taking too long but have no idea what’s going wrong exactly. Some process is running and you want to trace it. How? You have to find the SID and SERIAL# first. Check V$SESSION and find your culprit.

What you’re gonna use then are two procedures very similar to those we saw before, but from the DBMS_MONITOR package.

DBMS_MONITOR.SESSION_TRACE_ENABLE(
    session_id   IN  BINARY_INTEGER DEFAULT NULL,
    serial_num   IN  BINARY_INTEGER DEFAULT NULL,
    waits        IN  BOOLEAN DEFAULT TRUE,
    binds        IN  BOOLEAN DEFAULT FALSE)

DBMS_MONITOR.SESSION_TRACE_DISABLE(
   session_id      IN     BINARY_INTEGER DEFAULT NULL,
   serial_num      IN     BINARY_INTEGER DEFAULT NULL);

Same as with the DBMS_SESSION, the SESSION_TRACE_ENABLE offers two optional arguments for collecting wait and bind info. Even the defaults are the same.

BEGIN
-- We're interested in a session with sid=17, serial#=423

DBMS_MONITOR.SESSION_TRACE_ENABLE(17, 423, TRUE, TRUE);

-- Wait for a while

DBMS_MONITOR.SESSION_TRACE_DISABLE(17, 423);

END;

For how long should you trace?

Look, I don’t know. How about start with a minute and see how that goes? Here’s what you have to keep in mind.

Tracing should be enabled before a query starts for this query to show up in a trace file. If a query runs slow and halts the session down and that’s when you start tracing, you’re not gonna see it.
Tracing slows down the session. And the clients are already complaining. Keep it brief.
Trace files take up space on device. That’s not usually a problem, but I warned you.

How to find a trace file?

V$PROCESS

This one is great for tracing other sessions as you already know the SID and SERIAL#. Every process has a trace file name associated with it. Here’s how you find it.

SELECT S.SID,
       S.SERIAL#,
       S.USERNAME,
       P.PID,
       P.PROGRAM,
       P.TRACEFILE
FROM   V$SESSION    S,
       V$PROCESS    P
WHERE  S.SID     = :sid
AND    S.SERIAL# = :serial
AND    P.ADDR    = S.PADDR

The absolute path to the trace file is in the TRACEFILE column.

Trace file directory

When dealing with a performance issue I usually trace a process several times to see if whatever I tried works. So I’ll just cd to a trace file directory and look for the latest traces.

The trace file directory is under the ORACLE_HOME of the database instance. Look it up in the instance parameters:

SHOW PARAMETER dump_dest

This is how they usually look.

NAME                                               TYPE        VALUE                                                                                               
-------------------------------------------------- ----------- ----------------------------------------------------------------------------------------------------
background_dump_dest                               string      /opt/oracle/diag/rdbms/<instance_name>/<instance_name>/trace                                                            
core_dump_dest                                     string      /opt/oracle/diag/rdbms/<instance_name>/<instance_name>/cdump                                                            
user_dump_dest                                     string      /opt/oracle/diag/rdbms/<instance_name>/<instance_name>/trace

Depending on the type of a session the you can find the trace file in on of these. User sessions trace files are put inside the user_dump_dest.

You’re probably the only one doing this stuff at any given moment, so just use ls -ltr to check out the newest files first.

TRACEFILE_IDENTIFIER

This works only with tracing your own session but works extremely well. There may be a lot of traces in the directory so you might want to set up a tracefile_identifier to make looking your trace up a little easier.

ALTER SESSION SET tracefile_identifier='MYTRACE';

Oracle will put this string in the filename of your trace. Of course you can only set this identifier in your own session. Other sessions are off limits.

As usual, please, for the love of all that’s holy, write something reasonable, ok?

V$DIAG_INFO

If your instance uses ADR (Automatic Diagnostic Repository), check out this query to find the absolute path to a trace file. Works for the current session only.

SELECT VALUE FROM V$DIAG_INFO WHERE NAME = 'Default Trace File';

Trace file caveat

You may have noticed that a database instance maps exactly one trace file to a process. This means your consecutive traces will get appended to an existing trace file.

When tracing the same process again to see what changed make sure to delete an existing trace.

How to preprocess a trace file?

Raw trace files are hard to read. There’s a lot of info and it’s difficult to fish something useful out of there. In some rare cases you might want to take a look, but trust me, at most you’re gonna be overwhelmed.

So we all use tkprof to process trace files into a somewhat readable form.

The tool is fairly straightforward to use:

tkprof someinstance_ora_24257.trc someinstance_ora_24257.prf

First parameter is a raw trace file and the second is an output file. I usually name the output file the same as the raw file but with a .prf extension.

Tkprof has plenty of cool options worth checking. What I use the most is the SORT="(FCHELA,EXEELA)" to show the queries taking the most fetch time and execution time first.

tkprof someinstance_ora_24257.trc someinstance_ora_24257.prf sort="(prsela,exeela,fchela)"

Reading them is a bit of an art and I’ll probably write about it some day but usually I just go for big numbers and I’m rarely disappointed.