The Perl Toolchain Summit needs more sponsors. If your company depends on Perl, please support this very important event.
 / 
DBIx-LogProfile-0.02
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
  ...
    "!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.

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.

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:

  DBI_PROFILE='&norm_std_n3/DBIx::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.