Timer::Milestones - measure code execution time succinctly by setting milestones
This is version 0.003.
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 2020
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.
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 destroyed
The 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.
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.
Out: $timer
Creates a new Timer::Milestones object, and calls "start_timing" on it.
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.
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".
Out: $report
Returns 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.
Stops timing, and returns a report for all of the milestones.
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".
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.
In: $function_name_or_coderef In: %args (optional) Out: \&wrapped_function
Supplied 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:
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.
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.
summarise_arguments
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.
DBIx::Class::Storage::DBI::_execute
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.
do_stuff
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.
CODE(0xdeadbeef)
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.
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.
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 (c) 2020 Sam Kington.
This library is free software and may be distributed under the same terms as perl itself.
To install Timer::Milestones, copy and paste the appropriate command in to your terminal.
cpanm
cpanm Timer::Milestones
CPAN shell
perl -MCPAN -e shell install Timer::Milestones
For more information on module installation, please visit the detailed CPAN module installation guide.