NAME
Timer::Milestones - measure code execution time succinctly by setting milestones
VERSION
This is version 0.003.
SYNOPSIS
use Timer::Milestones qw(:all);
start_timing();
time_function('_my_own_function_elsewhere');
time_function('Some::ThirdParty::Module::do_slow_thing');
my @objects = _set_up_objects();
add_milestone('Everything set up');
for my $object (@objects) {
_do_something_potentially_slow($object);
# This code depends on a whole bunch of variables being set in the
# calling context, so don't bother refactoring it away into a separate
# function if it turns out that it's not actually slow.
state $code_to_time_individually = time_function(
sub {
...
},
report_name_as => 'Possibly slow inlined code',
summarise_calls => 1,
summarise_arguments => sub {
my ($object) = @_;
$object->type,
},
);
$code_to_time_individually->($object);
}
add_milestone('Telling the user')
for my $object (@objects) {
_inform_user($object);
}
...
stop_timing();Spits out to STDERR e.g.
START: Tue Feb 4 16:03:08 2020
3 s ( 0.28%)
Everything set up
5 min 30 s ( 31.22%)
3 min 7 s Some::ThirdParty::Module::do_slow_thing
15 s Possibly slow inlined code (x10)
Outgoing (x7)
Incoming (x3)
Telling the user
12 min 7 s ( 68.78%)
8 min 30 s Some::ThirdParty::Module::do_slow_thing (x3)
40 s _my_own_function_elsewhere
END: Tue Feb 4 16:20:48 2020DESCRIPTION
At its simplest, Timer::Milestones is yet another timer module. It is designed to have the smallest possible interface, so adding timing calls to your code doesn't make it look unreadable.
It can also time execution time of functions in other modules, as a more informative (and quicker!) alternative to running everything under Devel::NYTProf.
Functional vs OO interface
You can use Timer::Milestones via a functional interface:
use Timer::Milestones qw(start_timing add_milestone stop_timing);
start_timing();
...;
add_milestone('Half-way through');
...;
stop_timing();Or via an OO interface:
use Timer::Milestones;
{
my $timer = Timer::Milestones->new;
# $timer->start_timing automatically called
...;
$timer->add_milestone('Half-way through');
...;
}
# $timer->stop_timing automatically called when $timer is destroyedThe OO interface is simpler if you're timing a monolithic block of code. If you need to add timing calls throughout code scattered across multiple files, you're better off with the functional interface as you don't need to pass a Timer::Milestone object around.
Milestones and reports
At its simplest, the report you get will include when timing started and when timing ended. These are displayed in your locale's local time, on the assumption that that's what makes sense to you.
As soon as you add milestones, you will also be told how much time passed between the start, each milestone, and the end. Times are specified in both human-friendly periods (a number of milliseconds; seconds; minutes and seconds; or hours and minutes), and percentages of the total elapsed time.
If you decide that you want to time individual functions as well, they'll be mentioned with the milestones they follow. If you provide a coderef to summarise the arguments passed to them that will be included; if you decide that you don't need to see individual timings for each function call, just an overall time, you'll get a shorter list of function calls and an overall time.
Basic functionality
new
Out: $timerCreates a new Timer::Milestones object, and calls "start_timing" on it.
start_timing
If timing hadn't already been started, starts timing. Otherwise does nothing. Automatically called by "new", but you'll need to call it explicitly when using the functional interface.
add_milestone
In: $name (optional)Adds another milestone. If supplied with a name, uses that name for the milestone; otherwise, generates a name from the place it was called from (package, function, line number).
Throws an exception if a timing report has already been generated by "generate_report".
generate_intermediate_report
Out: $reportReturns a report on the milestones that have elapsed so far, or undef if a report has previously been generated and no new milestones have been reached since then.
generate_final_report
Out: $reportStops timing, and returns a report for all of the milestones.
stop_timing
Stops timing, and spits out the result of "generate_intermediate_report" to STDERR. This is called automatically in OO mode when the object goes out of scope. This does nothing if you've already called "generate_final_report". Also stops wrapping functions handed to "time_function".
Timing other people's code
Adding calls to "add_milestone" throughout your code is all very well, but sometimes you want to time a small handful of methods deep in someone else's code (or deep in your code - same difference). By carefully targeting only a few methods to time, you can avoid the pitfalls of profiling with Devel::NYTProf, where code that does zillions of fast method calls will appear to be much slower than it is when not profiling.
time_function
In: $function_name_or_coderef
In: %args (optional)
Out: \&wrapped_functionSupplied with a function name or a coderef, and an optional hash of arguments, wraps it with a temporary shim that records the time spent inside this function. Details of the functions called are included between milestones in the resulting report.
Returns the resulting wrapped function. This is useful if you supplied a coderef to be wrapped with timing code.
Optional arguments are as follows:
- summarise_arguments
-
A coderef, which will be passed the arguments passed to the function, and which should return a scalar that will be included in the report.
- summarise_calls
-
If set to a true value, repeated calls to this function will be summarised rather than listed individually: the first time a function call is found, it will also mention all subsequent calls.
This can combine with
summarise_arguments: calls which result in an identical return value from that coderef will be combined. - report_name_as
-
If specified, the name to use in reports instead of the default name.
The exact behaviour of this function depends on the nature of the first argument, $function_name_or_coderef.
If you specify a fully-qualified function name (e.g.
DBIx::Class::Storage::DBI::_execute), time_function will look for that exact function, insert a wrapper into the symbol table, and use that full name in reports by default.If you specify an unqualified function name (e.g.
do_stuff), it is assumed to be a function in the calling package, insert a wrapper into the symbol table, and the unqualified name will be used in reports by default.If you specify a coderef, the symbol table will not be modified, and the default name in reports will be of the form
CODE(0xdeadbeef)- so if you're passing more than one coderef to time_function, strongly consider overriding the default name.
When "stop_timing" is called, all wrapping in the symbol table will be undone; but note that this means "what was in the symbol table when time_function was called will be put back". So if you decide that you want to time the same function with two separate Timer::Milestones objects, it is very important to stop timing in the reverse order that you started timing.
SEE ALSO
Timer::Simple, which is simpler but more verbose.
Devel::Timer, which does some similar things.
Devel::NYTProf, which is probably worth using as a first pass, even if you don't necessarily trust its idea of what's actually slow.
AUTHOR
Sam Kington <skington@cpan.org>
The source code for this module is hosted on GitHub https://github.com/skington/timer-milestones - this is probably the best place to look for suggestions and feedback.
COPYRIGHT
Copyright (c) 2020 Sam Kington.
LICENSE
This library is free software and may be distributed under the same terms as perl itself.