NAME
Timer::Milestones - measure code execution time succinctly by setting milestones
VERSION
This is version 0.001.
SYNOPSIS
use Timer::Milestones qw(start_timing mark_milestone stop_timing
time_method);
start_timing();
time_method('Some::ThirdParty::Module::do_slow_thing');
my @objects = _set_up_objects();
mark_milestone('Everything set up');
for my $object (@objects) {
_do_something_potentially_slow($object);
}
mark_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
Telling the user
12 min 7 s ( 68.78%)
8 min 30 s Some::ThirdParty::Module::do_slow_thing (x3)
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 mark_milestone stop_timing);
start_timing();
...;
mark_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->mark_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".
Timing other people's code
Adding calls to "mark_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
In: %args (optional)Supplied with a function name, e.g. DBIx::Class::Storage::DBI::_dbh_execute, and an optional hash of arguments, wraps it with a temporary shim that records the time spent inside this function. That shim is removed, and the original code restored, when timing stops. Details of the functions called are included between milestones in the resulting report.
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.
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.