/ 
DBIx-LogProfile-0.01
River stage zero No dependents
/ DBIx::LogProfile

NAME

DBIx::LogProfile - Log DBI::Profile data into Log::Any or Log4perl

SYNOPSIS

% DBI_PROFILE='2/DBIx::LogProfile/Log:Any:Level:trace' ex.pl
% cat ex.log
...
  "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",
  "key1"                 :
    "\n    DELETE FROM Vertex WHERE vertex_name = ?\n  "
...
# Values as per DBI::Profile::as_node_path_list().
# Additionally `path` indicating the `Path`, and 
# a `key<N>` value for each value on that path.
#
# Formatting of the values in your logfile will vary
# based on your configuration of the logger you use.

DESCRIPTION

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.

CONSTRUCTOR

new( %options )

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 
  count
  total_duration
  first_duration
  shortest_duration
  longest_duration
  time_of_first_sample
  time_of_last_sample
  key1
  key2
  ...

For instance, if your Path is !Statement, OrderByDesc is 'count' and Limit is set to 1, like in

DBI_PROFILE='2/DBIx::LogProfile/OrderByDesc:count:Limit:1'

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.

Note that DBI::Profile supports a normliser 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 e.g. like so:

DBI_PROFILE='&norm_std_n3/DBIx::LogProfile::LogProfile/...'

Instead of reporting individual statements like

SELECT 1
SELECT 2
...

the statements would then be grouped like

SELECT <N>

METHODS

flush_to_logger()

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:

DBI->visit_handles(sub {
  my ($dbh, $info) = @_;
  return unless UNIVERSAL::isa(
    $dbh->{Profile},
    'DBIx::LogProfile'
  );
  $dbh->{Profile}->flush_to_logger();
});

This should have no effect if DBIx::LogProfile is not actually used at runtime, and would flush all relevant profile data if it is.

BUG REPORTS

SEE ALSO

* DBI::LogProfile

ACKNOWLEDGEMENTS

Thanks to the people on #perl on Freenode for the suggestion to call flush_to_logger during END.

AUTHOR / COPYRIGHT / LICENSE

Copyright (c) 2018 Bjoern Hoehrmann <bjoern@hoehrmann.de>.
This module is licensed under the same terms as Perl itself.