Profile::Log - collect loggable application profiling stats
use Profile::Log; ... sub event_processor { my $timer = Profile::Log->new() if PROFILE; do_something(); $timer->did("minor") if PROFILE > 1; $timer->mark("parallel") if PROFILE; do_parallel_things(); wait_for_thing1(); $timer->did("thing1", "parallel") if PROFILE; wait_for_thing2(); $timer->did("thing2", "parallel") if PROFILE; finish_up(); $timer->did("finish") if PROFILE > 1; # this module does not handle logging itself. print LOG $timer->logline if PROFILE; } # later... available processing methods my $timer = Profile::Log->new($log_line); print $timer->zero; # profile start time print $timer->end; # profile stop time # ... t.b.c. ...
Profile::Log is about breaking down time spent in "critical paths", such as in transaction processing servers, into logical pieces - with easily tunable operation that does not incur undue performance penalities when it is not being used.
Profile::Log
Profile::Log exports the PROFILE constant into the environment, depending on how it is configured (see "CONFIGURATION"). This will be set if profiling has been selected for the given script or module. As this is exported as a "constant subroutine", using the module as per the above synopsis will not incur any penalty at all (except, in the case above, the allocation of one undef scalar and the compile-time inclusion of Profile::Log itself; in long-running application servers, this is an extremely minor concern).
PROFILE
The timing information is logged in a way that suits syslog, and is casually easy to inspect; the above example, on profiling level 2, might log (though all on one line):
0=12:34:56.123504; tot=0.504; minor: 0.020; m0:parallel=0.000; \ m0:thing1=0.450; m0:thing2=0.454; finish: 0.030
The first item is the time that the Profile::Log object was created. The "tot" is the total length of time from when the object was created to the time that it was stopped (such as by asking for the log line).
On profiling level 1, you would instead get (assuming the same times for each component):
0=12:34:56.123504; tot=0.504; m0:parallel=0.020; \ m0:thing1=0.450; m0:thing2=0.454
This module exports the PROFILE constant to the caller's namespace. This will be set to 0 by default, or a number if configured in the per-user or environment specified configuration file. See "CONFIGURATION" for details.
If PROFILE is already defined as a subroutine or use constant in the calling package, then that is not touched.
use constant
my $timer = Profile::Log->new() if PROFILE;
Mark beginning of a profiled section, by creating a new Profile::Log object.
Normally, you don't pass any arguments to the Profile::Log->new constructor. However, if you want to reconstruct a previous Profile::Log object from a line from your logs, then you can pass that in instead.
Profile::Log->new
my $loaded_timer = Profile::Log->new($log_line);
For now, you need to strip off any leading syslog wrappers to the front of the string you pass in as $log_line.
syslog
$log_line
It is also possible to feed in lines that came out of syslog(8). These are expected to be in the form:
Mon DD HH:MM:SS hostname ...
These must be fed into the alternate constructor ->new_from_syslog. Information present in the syslog line, such as the hostname, any process name (sans PID), and extra information leading up to the beginning of the ->logline() part are put into tags.
->new_from_syslog
->logline()
->did($event, [$mark])
Indicate that the time elapsed since the timer was constructed or the last time ->did() or ->mark() was called to the current time was spent doing "$event". If you specify a $mark (see below), then all the time back from when you created that mark is considered to have been spent doing $event.
->did()
->mark()
$event
$mark
->mark($mark)
Set a time mark for later back-reference. Typically you would call this just before doing something that involves running things in parallel, and call ->did() above with the optional $mark parameter when each independent task completes.
Returns the timing information in a summarised format, suitable for sending to syslog or something similar.
This method automatically stops the timer the first time it is called.
These methods are about making sure custom details about what is being logged can easily be logged with the profiling information.
For instance, in application servers it is often useful to log the type of transaction being processed, or the URL. In multi-tier systems, you need to log a unique identifier with each request if you are to correlate individual timings through the system.
Also, these methods cover getting useful information out of the object once you have read it in from a log file.
->tag($tag, [$value])
Set (2 argument version) or get (1 argument version) an arbitrary tag. The $tag name should not contain a semicolon or equals sign, and the $value must not contain any semicolons. This is not enforced.
$tag
$value
->tags
Returns a list of tags of this profile, in no particular order.
->zero
Return the number of seconds between midnight (UTC) and the time this profiling object was created.
In list context, returns a Unix epoch time and a number of microseconds, Time::HiRes style.
Time::HiRes
->diff($t2)
Returns the difference between two times, in seconds. If the dates are fully specified, then it will return an asolute (floating point) number of seconds.
This method is available as the overloaded cmp operator, for easy use with sort.
cmp
sort
->end
Return the number of seconds since midnight (UTC) and the time this profiling object's clock was stopped.
->marks
Returns a list of marks as an array. This will always include "0", the starting mark.
->iter
Returns an iterator that iterates over every delta, and mark, in the Profiler object.
The iterator responds to these methods; note that these are not method calls:
$iter->("next")
iterate. returns a true value unless there is nowhere to iterate to.
$iter->("start")
Returns the offset from time 0 that this delta started in fractional seconds.
$iter->("length")
Returns the length of this delta in (fractional) seconds.
$iter->("name")
Returns the name of this delta, including the mark identifier (m followed by a number and a colon, such as "m0:").
m
m0:
->mark_iter([$mark])
Returns an iterator that iterates exactly once over every delta that was timed relative to $mark.
If you don't pass a mark in, it iterates only over items that weren't timed relative to $mark.
If you don't like the decisions I've made about only displaying milliseconds in the log, then you may sub-class Profile::Log and provide these functions instead. These are called as object methods, though the object itself is not used to compute the result.
->getTimeStamp([$sec, $usec])
Formats an absolute timestamp from a Time::HiRes array. Defaults to formatting as: HH:MM:SS.SSS
HH:MM:SS.SSS
->getInterval($sec | @tv_interval )
Formats an interval. This function accepts either a floating point number of seconds, or arguments as accepted by Time::HiRes::tv_interval.
Time::HiRes::tv_interval
The function returns a string in scalar context, but in list context returns any rounding error also, in floating point seconds.
Designed and built by Sam Vilain, samv@cpan.org, brought to you courtesy of Catalyst IT Ltd - http://www.catalyst.net.nz/.
All code and documentation copyright © 2005, Catalyst IT Ltd. All Rights Reserved. This module is free software; you may use it and/or redistribute it under the same terms as Perl itself.
1 POD Error
The following errors were encountered while parsing the POD:
Non-ASCII character seen before =encoding in '©'. Assuming UTF-8
To install Profile::Log, copy and paste the appropriate command in to your terminal.
cpanm
cpanm Profile::Log
CPAN shell
perl -MCPAN -e shell install Profile::Log
For more information on module installation, please visit the detailed CPAN module installation guide.