DBIx::LogProfile - Log DBI::Profile data into Log::Any or Log4perl
% DBI_PROFILE='2/DBIx::LogProfile/Log:Any:Level:trace' ex.pl
% cat ex.log
"!Statement" : "DELETE FROM Vertex WHERE vertex = ?"
"count" : 10626,
"total_duration" : 0.0804088115692139
"first_duration" : 0.000133037567138672,
"shortest_duration" : 0,
"longest_duration" : 0.000622987747192383,
"time_of_first_sample" : 1539396350.63128,
"time_of_last_sample" : 1539396364.50785,
"path" : "!Statement",
# Values as per DBI::Profile::as_node_path_list().
# Additionally `path` indicating the `Path`, and
# one pair for each element of the path.
# Formatting of the values in your logfile will vary
# based on your configuration of the logger you use.
This module allows you to smuggle DBI::Profile data (like SQL statements that have been executed, alongside frequency and time statistics) into an existing application's log without making changes to the application itself, using the environment variable DBI_PROFILE. This can be useful when you have a centralised structured logging facility and need information about DBI activity in it.
In addition to the options for parent DBI::Profile the following options are supported:
Log => 'Any' for Log::Any or 'Log4perl' for Log::Log4perl
Level => One of 'trace', 'debug', 'info', 'warn', ...
Limit => Maximum number of lines to log subject to OrderByDesc
OrderByDesc => One of
For instance, if your Path is !Statement, OrderByDesc is count and Limit is set to 1, like in
then this module will log only the most frequently processed statement and collected profile data in structured fields using the trace log level using Log::Any (the defaults).
The values will be passed as structured data to the logger, as hash for Log::Any, and as MDC data for Log::Log4perl. The log message for either is a string containing the substring DBIx::LogProfile.
This module will log an error using Log::Any if it fails to report profile data to the logger. This module logs but does not rethrow exceptions caught in that process.
Note that DBI::Profile supports a normaliser function that can replace variable parts of queries using some heuristics, which is very useful to group queries that are not prepared with bind parameters. You can enable it like so:
Instead of reporting individual statements like
the statements would then be grouped like
You can call this method on a DBIx::LogProfile object to manually force flushing the accumulated profile data to the logger. There is normally no need to do that, this module will automatically flush the profile data through the DBIx::LogProfile destructor (unless that is called during global destruction) and during the module's END code block.
The primary use case is to enable this module's mechanism through the DBI_PROFILE environment variable interpreted by DBI without the need to change any other code. The logic described above seems to be the best way to support that (alternative suggestions welcome).
However, when set through the environment variable, DBI keeps the profiler object around essentially until the application exits which may be unhelpful for long-lived Perl processes. In that case it may be useful to regularily do something like this in the application:
my ($dbh, $info) = @_;
return unless UNIVERSAL::isa(
This should have no effect if DBIx::LogProfile is not actually used at runtime, and would flush all relevant profile data if it is.
Thanks to the people on #perl on Freenode for the suggestion to call flush_to_logger during END.
Copyright (c) 2018 Bjoern Hoehrmann <email@example.com>.
This module is licensed under the same terms as Perl itself.
To install DBIx::LogProfile, copy and paste the appropriate command in to your terminal.
perl -MCPAN -e shell
For more information on module installation, please visit the detailed CPAN module installation guide.