Use DBI_TRACE to follow DBI’s work.

There is a lot going on when you use DBI to interact with a database. Tack on a few layers of abstraction from Object Relational Modelers (ORM’s) such as DBIx::Class and you can end up with a tricky maze of subroutine calls to dig through when you need to track down issues. DBI comes with a built-in tracing feature to make it easier though.

To enable tracing, simply set the DBI_TRACE environment variable to some value between 0 and 15, each of which represents a different level of tracing. A value of 1 enables minimal tracing. The verbosity of the trace increases as the value gets larger. The trace levels are in the main DBI documentation:

Level	Description
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

You can turn it on for one run of your program:

% DBI_TRACE=1 perl my_program.pl

Or you can turn it on for your entire session (using whatever your shell does):

% export DBI_TRACE=1
% perl my_program.pl

Here’s the output from just calling connect. As you can see, a lot of the information is about the internal workings of DBI:

	DBI 1.604-nothread default trace level set to 0x0/1 (pid 10602) at dbi_trace.pl line 5
    Note: perl is running without the recommended perl -w option
    -> DBI->connect(DBI:mysql:database=some_db;host=example.com, username, ****)
    -> DBI->install_driver(mysql) for freebsd perl=5.008009 pid=10602 ruid=3032 euid=3032
       install_driver: DBD::mysql version 3.0008 loaded from /usr/local/lib/perl5/site_perl/5.8.9/mach/DBD/mysql.pm
    <- install_driver= DBI::dr=HASH(0x825a6c8)
    !! warn: 0 CLEARED by call to connect method
    <- connect('database=some_db;host=example.com', 'username', ...)= DBI::db=HASH(0x8276900) at DBI.pm line 637
    <- STORE('PrintError', 1)= 1 at DBI.pm line 689
    <- STORE('AutoCommit', 1)= 1 at DBI.pm line 689
    <- STORE('Username', 'comdog_2_w')= 1 at DBI.pm line 692
    <> FETCH('Username')= 'comdog_2_w' ('Username' from cache) at DBI.pm line 692
    <- connected('DBI:mysql:database=some_db;host=example.com', 'username', ...)= undef at DBI.pm line 698
    <- connect= DBI::db=HASH(0x8276900)
    <- STORE('dbi_connect_closure', CODE(0x825a734))= 1 at DBI.pm line 707
    <- DESTROY(DBI::db=HASH(8276870))= undef at dbi_trace.pl line 7
    <- disconnect_all= (not implemented) at DBI.pm line 715
!   <- DESTROY(DBI::dr=HASH(825a6c8))= undef during global destruction

The output of even the most high-level trace can quickly become hard to read while your program is running. To redirect the trace to a file, you can specify a file name after the logging level:

% DBI_TRACE=15=my_program.trace my_program.pl

If you can't turn on tracing in the environment, you can programatically turn it on inside your script. If you want to trace everything that DBI does, you can turn it on for the entire program:

use DBI;

# to standard output
DBI->trace(1);

# or save it to a file
DBI->trace( 1, 'my_program.trace' );

You can also enable tracing on particular connections or handles once you narrow your search for the problem:

use DBI;

my $dbh = DBI->connect( ... );
$dbh->trace( 1, 'long_dbi_trace.txt' );

my $sth = $dbh->prepare( ... );
$sth->trace( 3, 'short_dbi_handle_trace.txt' );