NAME

Profile::Log - collect loggable application profiling stats

SYNOPSIS

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. ...

DESCRIPTION

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 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).

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

EXPORTS

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.

CONSTRUCTOR

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.

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.

ALTERNATE CONSTRUCTOR

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.

OBJECT METHODS

TIMING METHODS

->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.

->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.

->logline()

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.

TRACKING AND INSPECTING METHODS

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.

->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.

->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.

->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:").

->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.

TIMESTAMP FORMATTING

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

->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.

The function returns a string in scalar context, but in list context returns any rounding error also, in floating point seconds.

AUTHOR AND LICENSE

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.

cpanm Profile::Log

perl -MCPAN -e shell
install Profile::Log