RSH::Logging - Utility for instrumenting code using Log::Log4perl.
# In frameworks and other units of code use RSH::Logging qw(start_event stop_event); ... start_event('My piece of work'); ... stop_event(); # At the entry point or "top" of your unit of work use RSH::Logging qw(start_event_tracking stop_event_tracking print_event_tracking_results); use Log::Log4perl qw(:easy); our $logger = get_logger(__PACKAGE__); ... start_event_tracking($logger, 'My Business Function'); ... stop_event_tracking(); # print the results to logging print_event_tracking_results($logger); # print the results to a file (using ">filename") print_event_tracking_results($filename); # print the results to a file handle print_event_tracking_results($fh); # print the results to STDERR print_event_tracking_results(); # all of which will give you something like: TOTAL TIME 0.000766s (1305.483/s) .------------------------------+-----------. | Event | Time | +------------------------------+-----------+ | + My Business Function | 0.000766s | | + Reusable foo module | 0.000615s | | + Database code | 0.000141s | | + My piece of work | 0.000191s | '------------------------------+-----------'
RSH::Logging is kind of like poor-man's profiling or dtrace. It is designed on the same concepts behind logging packages like Log::Log4perl, that when event tracking is off, there be little to no overhead incurred by leaving the code in place. This allows you to instrument all your code and frameworks and then dynamically turn on this kind of profiling information when you need it.
Below are some best practices to using RSH::Logging.
The start_event_tracking and stop_event_tracking will mark the "top" or beginning of a transaction. If you are truly writing modular code, you will never know when the beginning of a transaction is until you assemble all your modular code and execute it as a part of a business function or script. As a result, you should always defer marking the transaction boundaries and printing out the results to the final client of your code.
For example, if you write a data access object that loads data into objects and a generic database framework, both of these should only use start_event and stop_event. It would be your CGI script that would do the start_event_tracking and stop_event_tracking, thus marking the total transaction--which your events in the data access object and the generic database framework would be contained within. For example, the final event tree would look something like this:
TOTAL TIME 0.000766s (1305.483/s) .------------------------------+-----------. | Event | Time | +------------------------------+-----------+ | + foobar.cgi | 0.000766s | | + foobar business function | 0.000615s | | + get database handle | 0.000141s | | + load foobar by id | 0.000191s | '------------------------------+-----------'
Where "get database handle" is your generic database framework and "load foobar by id" is your data access object. You can see that the "foobar.cgi" is the script marking the transaction via start_event_tracking and stop_event_tracking.
NOTE: if you call start_event_tracking within a block of code that has already called start_event_tracking, it will be treated as just another call to start_event.
While RSH::Logging will not do anything if tracking isn't enabled, unnecessary overhead can be incurred if you don't specify an event string. If no event string lable is sent to start_event, caller() is used to find out who called--and that string is used as the event name. The call to caller() can be avoided by specifying an event name. While caller() is not horribly expensive, it will add to overhead for the total time if you make enough calls to it.
Traversing the events and printing them to a table will always have some cost. You should allow the logging system to help you mitigate this. RSH::Logging will output the event table only if the logger has DEBUG enabled. If the logger is only printing INFO levels, the tree will not be processed or printed.
If for some reason you don't print the results to the logger, at least wrap the call to print_event_tracking_results with a check on the logger:
print_event_tracking_results($event_trace_file) if ($logger->is_debug());
This will prevent you from incurring overhead unnecessarily in production.
This takes a little trial and error to get the feel for, but can best be illustrated with an example.
If you have a method "convert_value" that may be called 100 times, putting a start_event in the convert_value body will then generate 100 events in your event tree. This will make it hard to pin-point problem areas in your code, as the event tree will be 100+ events in length (many of them perhaps very small time values).
If you have a situation like this, move the start_event call up one level. So for some situation like the following:
sub convert_value { start_event('convert_value'); ... stop_event(); } foreach $element (@elements) { convert_value($element); }
Do the following:
sub convert_value { ... } start_event('convert_value for elements'); foreach $element (@elements) { convert_value($element); } stop_event();
This will make the final event tree easier to parse.
None by default.
You may choose to conditionally export the following:
start_event_tracking
stop_event_tracking
start_event
stop_event
get_event_tracking_results
print_event_tracking_results
event_tracking_in_progress
Returns 1 if events are currently being tracked, 0 otherwise.
Called to signal the beginning of a transaction or the "top" of an event tree. This call should be deferred to client code, such as top-level scripts or business functions.
This call starts event tracking if the supplied logger is processing DEBUG messages. If the logger is undefined or not processing DEBUG messages, the call returns immediately and event tracking is not started (all calls to start_event will exit immediately, preventing any unnecessary overhead in the intrumented code).
If the logger is processing DEBUG messages, event tracking is started and a call is made to start_event with the given event name and optional descriptive note. If no event name is specified, the results of caller() are used for the event name.
Called to signal the end of a transaction or event tree. This call should be deferred to client code, such as top-level scripts or business functions.
Stops event tracking and places the current event tree in a variable to be used by get_event_tracking_results and print_event_tracking_results. Neither get_event_tracking_results or print_event_tracking_results will process anything until stop_event_tracking has been called.
Prints the event tree to a specified target if event tracking was started and stopped successfully. The target may be either a Logger from Log::Log4perl (recommended and preferred), a filename (in which case it will be opened for writing via ">filename"), or a file handle (subclass of IO::Handle). If event tracking was never started (either because start_event_tracking was not called or the supplied logger was not processing DEBUG messages) or is stop_event_tracking was not called, this method will exit quickly and do nothing.
If there are event tracking results to process, the events will be composed into a table, with each row's indentation representing whether it is a parent, peer, or child of the surrounding rows. The following table is an example:
.------------------------------+-----------. | Event | Time | +------------------------------+-----------+ | + My Business Function | 0.000766s | | + Reusable foo module | 0.000615s | | + Database code | 0.000141s | | + My piece of work | 0.000191s | '------------------------------+-----------'
"My Business Function" is the top-most event, the top of the call stack. At this point, start_event_tracking was called with an event name of "My Business Function". At some point between start_event_tracking and stop_event_tracking, "Reusable foo module" was called--thus it is a child of "My Business Function". The module then made two calls, one to "Database code" and another to "My piece of work"--these two events are peers and children of the module event. Other calls may have been made, but they were not instrumented using start/stop_event.
If the second parameter is "true", then chunking will be used if supported for the $to_target value. Only filehandles and Log4Perl are supported currently.
$to_target
Get the event tree. The format of the event tree isn't really for public consumption, but if for some reason you wanted to perform your own processing, this is how you would go about doing it.
The event tree is a hash of hashes. The general structure is:
{ event => 'event name', note => 'descriptive note (optional)', start => Time::HiRes::gettimeofday() value, stop => Time::HiRes::gettimeofday() value, children => [array of child event hashes] }
This method will return undef if stop_event_tracking has not been called.
Returns a count of the number of events. Everytime a start_event is called will increase the count until another event tracking result is created (i.e. stop_event_tracking + start_event_tracking).
Starts an event, using the optional event name and descriptive note. If tracking has not been started via start_event_tracking, this methd will return immediately, incurring no more overhead. If event tracking has been started, a new event will be logged in the event tree with its start time (via Time::HiRes::gettimeofday()). If there is already a current event, the new event is added as a child to the current event, the current event is stored on the stack, and the new event becomes the current event.
If the event name is not specified, caller() is used to populate the value.
Stops the current event (if there is one). If event tracking has not been started, this method returns immediately, incurring no additional overhead. If the current event was a child, the parent is popped from the stack and made the new current event.
Log::Log4perl
http://www.rshtech.com/software/
Matt Luker <mluker@cpan.org>
<mluker@cpan.org>
Copyright 2007 by Matt Luker <mluker@rshtech.com>.
<mluker@rshtech.com>
This library is free software; you can redistribute it and/or modify it under the same terms as Perl itself.
BECAUSE THIS SOFTWARE IS LICENSED FREE OF CHARGE, THERE IS NO WARRANTY FOR THE SOFTWARE, TO THE EXTENT PERMITTED BY APPLICABLE LAW. EXCEPT WHEN OTHERWISE STATED IN WRITING THE COPYRIGHT HOLDERS AND/OR OTHER PARTIES PROVIDE THE SOFTWARE "AS IS" WITHOUT WARRANTY OF ANY KIND, EITHER EXPRESSED OR IMPLIED, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. THE ENTIRE RISK AS TO THE QUALITY AND PERFORMANCE OF THE SOFTWARE IS WITH YOU. SHOULD THE SOFTWARE PROVE DEFECTIVE, YOU ASSUME THE COST OF ALL NECESSARY SERVICING, REPAIR, OR CORRECTION.
IN NO EVENT UNLESS REQUIRED BY APPLICABLE LAW OR AGREED TO IN WRITING WILL ANY COPYRIGHT HOLDER, OR ANY OTHER PARTY WHO MAY MODIFY AND/OR REDISTRIBUTE THE SOFTWARE AS PERMITTED BY THE ABOVE LICENCE, BE LIABLE TO YOU FOR DAMAGES, INCLUDING ANY GENERAL, SPECIAL, INCIDENTAL, OR CONSEQUENTIAL DAMAGES ARISING OUT OF THE USE OR INABILITY TO USE THE SOFTWARE (INCLUDING BUT NOT LIMITED TO LOSS OF DATA OR DATA BEING RENDERED INACCURATE OR LOSSES SUSTAINED BY YOU OR THIRD PARTIES OR A FAILURE OF THE SOFTWARE TO OPERATE WITH ANY OTHER SOFTWARE), EVEN IF SUCH HOLDER OR OTHER PARTY HAS BEEN ADVISED OF THE POSSIBILITY OF SUCH DAMAGES.
To install RSH::Logging, copy and paste the appropriate command in to your terminal.
cpanm
cpanm RSH::Logging
CPAN shell
perl -MCPAN -e shell install RSH::Logging
For more information on module installation, please visit the detailed CPAN module installation guide.