How to get timestamps in Perl DBI files?
I have a problem where the application accidentally dies during a DBI call. We cannot reliably reproduce this in our test or production environment, so I need to monitor it in our production system to try and figure out what's going on.
I am logging all traffic DBI
through an environment variable DBI_TRACE
.
DBI_TRACE=3=dbi.log script.pl
However, the problem is that there are no timestamps in the DBI log files, so it is difficult to find them to find what was happening during the stamp.
Is there a way to enable DBI logging with timestamps?
source to share
The DBI documentation contains code on how to enable timestamped logs using tiered file handles. The downside is that you lose the luxury of using environment variables and have to set trace options in code:
$dbh->trace('SQL', $fh);
Where $ fh contains a reference to an object that is "subclassed" of PerlIO :: Via
source to share
You can use File :: Tee to redirect STDERR and add a timestamped prefix.
For example:
use strict;
use warnings;
use File::Tee 'tee';
my $logfile = "/path/to/timestamped/logfile.log";
my $filter = sub { return localtime() . ' ' . $_[0] };
my $pid = tee STDERR, { preprocess => $filter, reopen => $logfile };
print STDERR "something bad happened.";
The advantage is that it won't interfere with your existing STDERR - all error messages will keep going to the same place. But the stream is duplicated and also written to $logfile
, with whatever conversion you want with $filter
.
source to share
If overriding is STDERR
not an option, and if you are on a UNIXy system (what the various messages suggest to you), you can direct the trace output to fifo and run a timestamping filter there:
$ mkfifo /tmp/fifo
$ perl -MTime::HiRes=time -npe 's/^/time . " "/e' < /tmp/fifo > /tmp/timestamped.log &
[1] 12345
$ DBI_TRACE=1=/tmp/fifo script.pl
This filtering program can be anything, even logger , which adds timestamps provided by syslogd on my system.
source to share
I wrote a minimalistic perl logger with custom dynamic logging, giving you the following API:
use strict ; use warnings ; use Exporter;
use Configurator ;
use Logger ;
# anonymous hash !!!
our $confHolder = () ;
sub main {
# strip the remote path and keep the bare name
$0=~m/^(.*)(\\|\/)(.*)\.([a-z]*)/;
my $MyBareName = $3;
my $RunDir= $1 ;
# create the configurator object
my $objConfigurator = new Configurator($RunDir , $MyBareName );
# get the hash having the vars
$confHolder = $objConfigurator ->getConfHolder () ;
# pring the hash vars
print $objConfigurator->dumpIni();
my $objLogger = new Logger (\$confHolder) ;
$objLogger->LogMsg ( " START MAIN " ) ;
$objLogger->LogMsg ( "my \$RunDir is $RunDir" ) ;
$objLogger->LogMsg ( "this is a simple message" ) ;
$objLogger->LogErrorMsg ( "This is an error message " ) ;
$objLogger->LogWarningMsg ( "This is a warning message " ) ;
$objLogger->LogInfoMsg ( "This is a info message " ) ;
$objLogger->LogDebugMsg ( "This is a debug message " ) ;
$objLogger->LogTraceMsg ( "This is a trace message " ) ;
$objLogger->LogMsg ( "using the following log file " . "$confHolder->{'LogFile'}" ) ;
$objLogger->LogMsg ( " STOP MAIN \n\n" ) ;
} #eof main
#Action !!!
main();
1 ;
__END__
source to share
I doubt there is a problem in the DBI itself, although it is possible. DBI tracing can be very verbose, although I can see that you are using trace level 3. Use DBIx :: Log4perl and you will get custom timestamps, method invocation, SQL, bindings, etc. and all you need to do , this will change your connection call.
source to share
I suggest looking at DBI :: Log .
It prints to STDERR by default, so to replicate your usage, you call it like this:
perl -MDBI :: Log script.pl 2> dbi.log
The result gives you a much better general idea of what happened in your DBI-based SQL access:
- containing timestamps ,
- replace placeholders (binding parameters) with actual values that allow you to rerun queries directly in SQL for debugging, and
- containing a trace of the calls to the Perl code that resulted in the corresponding SQL query.
source to share