Log::Defer - Deferred logs and timers
use Log::Defer; use JSON::XS; ## or whatever sub my_logger_function { my $msg = shift; print JSON::XS->new->pretty(1)->encode($msg); } my $logger = Log::Defer->new({ cb => \&my_logger_function, verbosity => 30, }); $logger->info("hello world"); my $timer = $logger->timer('some timer'); undef $timer; ## stops timer undef $logger; ## write out log message
Prints:
{ "start" : 1340421702.16684, "end" : 0.000249, "logs" : [ [ 0.000147, 30, "hello world" ] ] }
I believe a lot of log processing is done too early. This module helps you to defer log processing in two ways:
Typically this transaction is something like an HTTP request or a cron job. Generally log messages are easier to read if they are recorded atomically and are not intermingled with log messages created by other transactions.
Sometimes you don't know how logs should be rendered until long after the message has been written. If you aren't sure what information you'll want to display, or you expect to display logs in multiple different formats, it makes sense to store your logs in a highly structured format so they can be processed as late as possible.
This module doesn't actually write out logs! To use this module for normal logging purposes you also need a logging library (some of them are mentioned in "SEE ALSO").
The simplest use case is outlined in the SYNOPSIS. You create a new Log::Defer object and pass in a code ref callback. This callbac will be called once the Log::Defer object is destroyed or once all references to the object go out of scope.
With Log::Defer, if a transaction has several possible code paths it can take, there is no need to manually ensure that every possible path ends up calling your logging routine at the end. The log writing will be deferred until the logger object is destroyed or goes out of scope.
In an asynchronous application where multiple asynchronous tasks are kicked off concurrently, each task can keep a reference to the logger object and the log writing will be deferred until all tasks are finished.
Log::Defer makes it easy to gather timing information about the various stages of your request. This is explained further below.
Free-form line-based log protocols are probably the most common log formats by far. The formats are usually just happenstance -- whatever happened to be convenient for the programmer.
Unfortunately, doing analysis on ad-hoc unstructured multi-line formats requires a lot of time-consuming parsing work. As well as being a perl module, Log::Defer is also a specification for a structured logging format.
Although this module doesn't impose any external encoding for log messages on you, some tools like the visualisation tool only support JSON at this time.
FIXME: QQQ Normally all unnecessary white-space would be removed and it would be stored on a single line so that ad-hoc command-line greping still works.
grep
Log::Defer objects provide a very basic "log level" system. In order of increasing verbosity, here are the normal logging methods and their numeric log level:
$logger->error("..."); # 10 $logger->warn("..."); # 20 $logger->info("..."); # 30 $logger->debug("..."); # 40
You can also use custom log levels:
$logger->add_log(25, "...");
If you pass in a verbosity argument to the Log::Defer constructor, messages with a higher log level will not be included in the final log message. Otherwise, all log messages are included.
verbosity
Even if you include noisy debug logs you can filter them out with the visualisation tool at display time. The verbosity argument is only useful for reducing the size of log messages or eliminating unnecessary processing overhead (see the no-overhead debug logs section below).
Note that you can pass in multiple items to a log message and they don't even need to be strings:
$logger->warn("something weird happened: $@", { username => $username });
In the deferred logging callback, the log messages are recorded in the logs element of the $msg hash. It is an array ref and here would be the element pushed onto logs by the warn method call above:
logs
$msg
warn
[ 0.201223, 20, "something weird happened: peer timeout", { username => "jimmy" } ]
The first element is a timestamp of how long the warn method was called after the start in seconds (see TIMERS below). The second element is the verbosity level of this message.
start
If you would like to compute complex messages in debug mode but don't want to burden your production systems with this overhead, you can use delayed message generation:
$logger->debug(sub { "Connection: " . dump_connection_info($conn) });
The sub won't be invoked unless the logger object is instantiated with verbosity of 40 or higher (or you omit verbosity altogether).
Instead of log messages, you can directly add items to a data hash reference with the data method:
data
$log->data->{ip} = $ENV{REMOTE_ADDR};
This is a useful place to recording info that needs to be extracted since you don't need to crawl through log message entries. Anything you put in the data hash reference will be passed along untouched to your defered callback.
When the logger object is first created, the current time is recorded as a Time::HiRes absolute timestamp and is stored in the start element of the log hash. All other times are relative offsets from start.
When the logger object is destroyed, the time elapsed since start is stored in end.
end
In addition to start and duration of the entire transaction, you can also record timing data of sub-portions of your transaction by using timer objects.
Timer objects are created by calling the timer method on the logger object. This method should be passed a description of what you are timing.
timer
The timer starts as soon as the timer object is created and stops once the last reference to the timer is destroyed or goes out of scope. If the logger object itself is destroyed or goes out of scope then all outstanding timers are terminated at that point.
start is a Time::HiRes absolute timestamp. All other times are relative offsets from this start time. Everything is in seconds.
Here is a fairly complicated example showing how to use concurrent timers:
sub handle_request { my $request = shift; my $logger = Log::Defer->new(\&my_logging_function); my $headers = do { my $parse_timer = $logger->timer('parsing request'); parse_request($request); }; my $fetch_timer = $logger->timer('fetching results'); async_fetch_results($headers, sub { ## stop first timer by undefing ref, then start new timer undef $fetch_timer; $fetch_timer = $logger->timer('fetching stage 2'); async_fetch_stage_2($headers, sub { $logger; ## keep reference alive undef $fetch_timer; send_response(); }); my $update_cache_timer = $logger->timer('update cache'); async_update_cach(sub { $logger; ## keep reference alive undef $update_cache_timer; }); }); }
Each structured log message will be passed into the callback provided to new as a perl hash reference that contains various other perl data-structures. What you do at this point is up to you.
new
Here is a prettified example of a JSON-encoded message:
{ "start" : 1340353046.93565, "end" : 0.202386, "logs" : [ [ 0.000158, 30, "This is an info message (log level=30)" ], [ 0.201223, 20, "Warning! \n\n Here is some more data:", { "whatever" : 987 } ] ], "data" : { "junkdata" : "some data" }, "timers" : { "junktimer" : [ 0.000224, 0.100655 ], "junktimer2" : [ 0.000281, 0.202386 ] } }
See the Log::Defer::Viz module for a command line utility that renders Log::Defer logs. Timers are shown something like this:
download file |===============================================| cache lookup |==============| update cache |=========================================| DB lookup |======================| sent reply X ________________________________________________________________________________ times in ms 0.2 32.4 100.7 80.7 119.2
As mentioned above, this module doesn't actually log messages to disk/syslog/anything so you still must use some other module to record your log messages. There are many libraries on CPAN that can do this and there should be at least one that fits your requirements. Some examples are: Sys::Syslog, Log::Dispatch, Log::Handler, Log::Log4perl, Log::Fast, AnyEvent::Log.
Additionally, this module doesn't provide any official serialization format. There are many choices for this, including JSON::XS, Sereal, Storable, and Data::MessagePack.
Currently the timestamp generation system is hard-coded to Time::HiRes::time. You should be aware of some caveats related to non-monotonous clocks that are discussed in Time::HiRes.
Time::HiRes::time
Doug Hoyte, <doug@hcsw.org>
<doug@hcsw.org>
Copyright 2012-2013 Doug Hoyte.
This module is licensed under the same terms as perl itself.
To install Log::Defer, copy and paste the appropriate command in to your terminal.
cpanm
cpanm Log::Defer
CPAN shell
perl -MCPAN -e shell install Log::Defer
For more information on module installation, please visit the detailed CPAN module installation guide.