Timer

Overview

nano::timer and nano::autotimer are C++ utility classes to simplify timing in the Nano node.

Use cases include:

• During debugging when performance issues are lost in profiling tool averaging (e.g. a function is usually fast, but you suspect occasional slowdowns due to waiting on locks)
• Logging durations when the timing configuration is enabled.
• As input to duration/timing based logic.

Child timers with accumulation and averaging is supported. The timer units can be any std::chrono unit, and there's a unit() function that provides a text representation.

Timers

Autotimer

This is a one-liner when you need to measure the duration of any scope (such as function):

nano::autotimer<std::chrono::microseconds> timer ("block processing");

The autotimer goes out of scope, it'll output the timing information to a stream. By default this is std::cout, but you can supply any std::ostream you want as a second parameter.

When measuring functions, the PRETTY_FUNCTION macro can be passed if you want the entire signature as part of the output.

Starting and stopping manually

auto timer = nano::timer<std::chrono::milliseconds> ("process_receive_many");
timer.start ();
...
timer.stop (std::cout);

Output:

process_receive_many: 60486 microseconds

Start timer on construction

nano::timer<std::chrono::milliseconds> timer (nano::timer_state::started, 
                                              "process_receive_many");
...
timer.stop (std::cout);

Restarting

A timer can be restarted. The tick count is set to zero.

timer.restart ();

Getting the duration

Calling stop () or pause () without an argument returns the duration. This can be used for custom formatting, as well as to perform logic based on duration.

BOOST_LOG (log) << boost::str (boost::format ("Verified blocks in %1% %2%") 
                   % timer.stop ().count () % timer_l.unit ());

Child timers

With accumulation

nano::timer<std::chrono::milliseconds> timer ("process_receive_many");
timer.start ();

...

// Create a child timer that will be started and paused for a segment of the
// code inside the loop. Any number of child timers can be created.
auto& timer_erase = timer.child ("erase");
while (some_condition)
{
   ...
   timer_erase.start ();
   expensive_erase_operation ();
   timer_erase.pause ();
   ...
}

timer.stop (std::cout);

Output:

process_receive_many.erase: 158 microseconds (24 measurements, 6.58 microseconds avg)
process_receive_many: 60486 microseconds

In other words, 60 ms was spent in process_receive_many, of which 158 µs was spent erasing. Each erase took 6.58 µs on average.

Without accumulation

If stop (std::cout) (or any other stream) is called instead of pause () in the above example, each loop iteration will produce a measurement output:

process_receive_many.erase: 8 microseconds
process_receive_many.erase: 14 microseconds
process_receive_many.erase: 17 microseconds
process_receive_many.erase: 20 microseconds
process_receive_many.erase: 25 microseconds
process_receive_many: 4513 microseconds

Output filtering

You can set a minimum duration to reduce noise. For instance timer_erase.set_minimum (20us); ensures that only measurements at or above 20 µs are printed:

process_receive_many.erase: 20 microseconds
process_receive_many.erase: 25 microseconds
process_receive_many: 4513 microseconds

Deadlines

Call before_deadline and after_deadline to see if the timer is currently above or below the given duration.

while (!state_blocks.empty () && timer_l.before_deadline (std::chrono::seconds (2)))
{
    verify_state_blocks (lock_a, 2048);
}