The DBI has a powerful tracing mechanism built in. It enables you to see what's going on 'behind the scenes', both within the DBI and the drivers you're using.
Which details are written to the trace output is controlled by a combination of a trace level, an integer from 0 to 15, and a set of trace flags that are either on or off. Together these are known as the trace settings and are stored together in a single integer. For normal use you only need to set the trace level, and generally only to a value between 1 and 4.
Each handle has it's own trace settings, and so does the DBI. When you call a method the DBI merges the handles settings into its own for the duration of the call: the trace flags of the handle are OR'd into the trace flags of the DBI, and if the handle has a higher trace level then the DBI trace level is raised to match it. The previous DBI trace setings are restored when the called method returns.
Trace levels are as follows:
0 - Trace disabled.
1 - Trace top-level DBI method calls returning with results or errors.
2 - As above, adding tracing of top-level method entry with parameters.
3 - As above, adding some high-level information from the driver
and some internal information from the DBI.
4 - As above, adding more detailed information from the driver.
This is the first level to trace all the rows being fetched.
5 to 15 - As above but with more and more internal information.
Trace level 1 is best for a simple overview of what's happening. Trace levels 2 thru 4 a good choice for general purpose tracing. Levels 5 and above are best reserved for investigating a specific problem, when you need to see "inside" the driver and DBI.
The trace output is detailed and typically very useful. Much of the trace output is formatted using the "neat" function, so strings in the trace output may be edited and truncated by that function.
Trace flags are used to enable tracing of specific activities within the DBI and drivers. The DBI defines some trace flags and drivers can define others. DBI trace flag names begin with a capital letter and driver specific names begin with a lowercase letter, as usual.
Curently the DBI only defines two trace flags:
ALL - turn on all DBI and driver flags (not recommended) SQL - trace SQL statements executed (not yet implemented)
The "parse_trace_flags" and "parse_trace_flag" methods are used to convert trace flag names into the coresponding integer bit flags.
The $h->trace method sets the trace settings for a handle and DBI->trace does the same for the DBI.
In addition to the "trace" method, you can enable the same trace information, and direct the output to a file, by setting the DBI_TRACE environment variable before starting Perl. See "DBI_TRACE" for more information.
Finally, you can set, or get, the trace settings for a handle using the TraceLevel attribute.
All of those methods use parse_trace_flags() and so allow you set both the trace level and multiple trace flags by using a string containing the trace level and/or flag names separated by vertical bar ("|") or comma (",") characters. For example:
local $h->{TraceLevel} = "3|SQL|foo";
Initially trace output is written to STDERR. Both the $h->trace and DBI->trace methods take an optional $trace_file parameter, which may be either the name of a file to be openned by DBI in append mode, or a reference to an existing writable (possibly layered) filehandle. If $trace_file is a filename, and can be opened in append mode, or $trace_file is a writable filehandle, then all trace output (currently including that from other handles) is redirected to that file. A warning is generated if $trace_file can't be opened or is not writable.
Further calls to trace() without $trace_file do not alter where the trace output is sent. If $trace_file is undefined, then trace output is sent to STDERR and, if the prior trace was openned with $trace_file as a filename, the previous trace file is closed; if $trace_file was a filehandle, the filehandle is not closed.
NOTE: If $trace_file is specified as a filehandle, the filehandle should not be closed until all DBI operations are completed, or the application has reset the trace file via another call to trace() that changes the trace file.
NOTE:
As of version 5.8, Perl provides the ability to layer various "disciplines" on an open filehandle via the PerlIO module.
A simple example of using PerlIO layers is to use a scalar as the output:
my $scalar = '';
open( my $fh, "+>:scalar", \$scalar );
$dbh->trace( 2, $fh );
Now all trace output is simply appended to $scalar.
A more complex application of tracing to a layered filehandle is the use of a custom layer (Refer to Perlio::via for details on creating custom PerlIO layers.). Consider an application with the following logger module:
package MyFancyLogger;
sub new
{
my $self = {};
my $fh;
open $fh, '>', 'fancylog.log';
$self->{_fh} = $fh;
$self->{_buf} = '';
return bless $self, shift;
}
sub log
{
my $self = shift;
return unless exists $self->{_fh};
my $fh = $self->{_fh};
$self->{_buf} .= shift;
#
# DBI feeds us pieces at a time, so accumulate a complete line
# before outputing
#
print $fh "At ", scalar localtime(), ':', $self->{_buf}, "\n" and
$self->{_buf} = ''
if $self->{_buf}=~tr/\n//;
}
sub close {
my $self = shift;
return unless exists $self->{_fh};
my $fh = $self->{_fh};
print $fh "At ", scalar localtime(), ':', $self->{_buf}, "\n" and
$self->{_buf} = ''
if $self->{_buf};
close $fh;
delete $self->{_fh};
}
1;
To redirect DBI traces to this logger requires creating a package for the layer:
package PerlIO::via::MyFancyLogLayer;
sub PUSHED
{
my ($class,$mode,$fh) = @_;
my $logger;
return bless \$logger,$class;
}
sub OPEN {
my ($self, $path, $mode, $fh) = @_;
#
# $path is actually our logger object
#
$$self = $path;
return 1;
}
sub WRITE
{
my ($self, $buf, $fh) = @_;
$$self->log($buf);
return length($buf);
}
sub CLOSE {
my $self = shift;
$$self->close();
return 0;
}
1;
The application can then cause DBI traces to be routed to the logger using
use PerlIO::via::MyFancyLogLayer;
open my $fh, '>:via(MyFancyLogLayer)', MyFancyLogger->new();
$dbh->trace('SQL', $fh);
Now all trace output will be processed by MyFancyLogger's log() method.
Many of the values embeded in trace output are formatted using the neat() utility function. This means they may be quoted, sanitized, and possibly truncated if longer than $DBI::neat_maxlen. See "neat" for more details.
You can add tracing to your own application code using the "trace_msg" method.
It can sometimes be handy to compare trace files from two different runs of the same script. However using a tool like diff on the original log output doesn't work well because the trace file is full of object addresses that may differ on each run.
The DBI includes a handy utility called dbilogstrip that can be used to 'normalize' the log content. It can be used as a filter like this:
DBI_TRACE=2 perl yourscript.pl ...args1... 2>&1 | dbilogstrip > dbitrace1.log
DBI_TRACE=2 perl yourscript.pl ...args2... 2>&1 | dbilogstrip > dbitrace2.log
diff -u dbitrace1.log dbitrace2.log
See dbilogstrip for more information.