NAME Log::Defer - Deferred logs and timers SYNOPSIS use Log::Defer; use JSON::XS; ## or whatever my $logger = Log::Defer->new(\&my_logger_function); $logger->info("hello world"); undef $logger; # write out log message sub my_logger_function { my $msg = shift; print JSON::XS->new->pretty(1)->encode($msg); } Prints: { "start" : 1340421702.16684, "end" : 0.000249, "logs" : [ [ 0.000147, 30, "hello world" ] ] } DESCRIPTION This module doesn't actually log anything! To use this module for normal logging purposes you also need a logging library (some of them are mentioned in "SEE ALSO"). What this module does is allow you to defer recording log messages until after some kind of "transaction" has completed. 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. This module preserves as much structure as possible which allows you to record machine-parseable log messages if you so choose. USAGE The simplest use case is outlined in the SYNOPSIS. You create a new Log::Defer object and pass in a code ref. This code ref will be called once the Log::Defer object is destroyed or all references to the object go out of scope. If a transaction has several possible 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. STRUCTURED LOGS So what is the point of this module? Most logging libraries are convenient to use, usually even more-so than Log::Defer. However, this module allows you to record log messages in a format that can be easily analysed if you so choose. Line-based log protocols are nice because they are compact and since people are used to them they are "easy" to read. However, doing analysis on line-based or, even worse, ad-hoc unstructured multi-line formats is more difficult than it needs to be. And given the right tools, reading structured log messages can actually be easier than reading line-based logs. LOG MESSAGES Log::Defer objects provide a very basic "log level" system. In order of increasing verbosity, here are the possible logging methods: $logger->error("..."); # 10 $logger->warn("..."); # 20 $logger->info("..."); # 30 $logger->debug("..."); # 40 The only thing that this module does with the log level is record it in the log message. Here is an example of issuing a warning: $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: [ 0.201223, 20, "something weird happened", { username => "jimmy" } ] The first element is a timestamp of when the "warn" method was called in seconds since the "start" (see TIMERS below). The second element is the verbosity level. If you wish to implement "log levels" (ie filter out debug messages), you can grep them out when your recording callback is called. DATA Instead of log messages, you can directly access a "data" hash reference with the "data" method: $log->data->{junkdata} = 'some data'; This is useful for recording info related to a whole transaction like say a connecting IP address. Anything you put in the "data" hash reference will be passed along untouched to your defered callback. TIMERS Timer objects can be created by calling the "timer" method on the logger object. This method should be passed a description of what you are timing. The timer starts as soon as the timer object is created and only stops once the last reference to the timer is destroyed or goes out of scope, or if the logger object itself is destroyed/goes out of scope. When the logger object is first created, the current time is recorded and is stored in the "start" element of the log hash. "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 that includes 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; }); }); } EXAMPLE LOG MESSAGE Each structured log message will be passed into the callback provided to "new". The message is a perl hash reference that contains various other perl data-structures. What you do at this point is up to you. What follows is a prettified example of a JSON-encoded log message. Normally all unnecessary white-space would be removed and it would be stored on a single line so that ad-hoc command-line "grep"ing still works. { "start" : 1340353046.93565, "end" : 0.202386, "logs" : [ [ 0.000158, 30, "This is an info message (verbosity=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 ] } } FUTURE WORK We plan do some cool stuff with structured logs. Here's a mock-up of a timer rendering idea: parsing request |======| fetching results |==========| fetching stage 2 |==========================| update cache |==========| 0 0.05073 0.129351 0.0012 0.084622 SEE ALSO 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. Some caveats related to non-monotonous clocks are discussed in Time::HiRes. AUTHOR Doug Hoyte, "" COPYRIGHT & LICENSE Copyright 2012 Doug Hoyte. This module is licensed under the same terms as perl itself.