7
\$\begingroup\$

I was trying to emulate python's timeit in C++. My main aim for this is to measure the performance of small functions of C++ code that I write and print some basic stats like avg., min, max.

Code:

ctimeit.h:

#ifndef CTIMEIT_H
#define CTIMEIT_H

#include <chrono>
#include <cmath>
#include <iostream>
#include <limits>

namespace ctimeit {
using GetTime = std::chrono::high_resolution_clock;
using std::chrono::duration_cast;
std::string format_time(int64_t);

template <size_t N = 1000, typename Callable, typename... Args>
void timeit(Callable func, Args&&... Funcargs) {
  /*
   * Measure the average execution time of `func` which takes `Funcargs`
   * after `N` executions.
   */

  double total_time{0};
  int64_t min_exec_time{std::numeric_limits<int64_t>::max()}, max_exec_time{0};

  for (size_t i = 0; i < N; ++i) {
    auto start = GetTime::now();
    func(std::forward<Args>(Funcargs)...);
    auto end = GetTime::now();

    auto run_time =
        duration_cast<std::chrono::nanoseconds>(end - start).count();
    min_exec_time = std::min(min_exec_time, run_time);
    max_exec_time = std::max(max_exec_time, run_time);
    total_time += run_time;
  }

  std::cout << "Average time taken : " << format_time(total_time / N) << " ("
            << N << " runs)\n"
            << "Max time taken     : " << format_time(max_exec_time) << "\n"
            << "Min time taken     : " << format_time(min_exec_time) << "\n";
}

std::string format_time(int64_t run_time) {
  /*
   * For setting the scale of execution time.
   */

  std::string formats[]{"ns", "µs", "ms", "s"};
  float scaling[]{1, 1e3, 1e6, 1e9};
  int pow = std::floor(std::log10(run_time));
  int idx = std::max(0, pow / 3);
  return std::to_string(run_time / scaling[idx]) + formats[idx];
}

}  // namespace ctimeit

#endif  // CTIMEIT_H

Output:

std::cout<<"-------SomeFunc---------\n";
timeit(SomeFunc, v); //default N i.e 1000
std::cout<<"-------anotherFunc with N arg---------\n";
timeit<100>(anotherFunc, 10, 20, 40.f);


-------SomeFunc---------
Average time taken : 904.073975µs (1000 runs)
Max time taken     : 4.574131ms
Min time taken     : 834.716003µs
-------anotherFunc with N arg---------
Average time taken : 45.000000ns (100 runs)
Max time taken     : 137.000000ns
Min time taken     : 39.000000ns

Any suggestions to improve my code or if there's anything wrong I'm doing in measuring the execution time?

\$\endgroup\$
6
  • 1
    \$\begingroup\$ The example output (with exact nanoseconds) suggests that you're trying to show more precision than your platform provides. \$\endgroup\$ Oct 1, 2021 at 13:01
  • \$\begingroup\$ @TobySpeight Yes, I think I'm passing total_time/N which is double to format_time which takes int64_t, losing all the precision. And scaling array is in float too that's why the output has less precision. Thank you I would have completely missed these details if not for your comment. \$\endgroup\$
    – Ch3steR
    Oct 1, 2021 at 13:10
  • \$\begingroup\$ Related: codereview.stackexchange.com/questions/58055/stopwatch-template \$\endgroup\$
    – Edward
    Oct 1, 2021 at 15:23
  • \$\begingroup\$ If you actually want to time your code well, use an external profiler. They do a much better job. \$\endgroup\$ Oct 2, 2021 at 11:18
  • \$\begingroup\$ I'd definitely recommend reading up on significant figures and suggest you modify how you output your numbers during the next revision of your program. \$\endgroup\$
    – Mast
    Oct 3, 2021 at 9:37

3 Answers 3

10
\$\begingroup\$

Your code is unfortunately using a very naive method to measure the execution time of a function. I'll discuss a few of the issues and how to solve them below.

Avoid std::chrono::high_resolution_clock

While the name sounds like it's what you want, there is unfortunately no guarantee whether this clock follows the wall clock or the monotonic clock. This means that if you are unfortunate enough that your NTP daemon is making an adjustment to the wall clock time while your benchmark is running, the results will be incorrect. std::chrono::steady_clock is the best clock from the C++ standard to use to avoid surprises.

Even then, this might not be the best clock to measure the time your process spends executing functions. Consider that your operating system might have to handle interrupts or schedule other tasks on the same CPU core your benchmark is running on. Most operating systems have some clocks that will only count while your process is running. These are not standardized, but on POSIX systems you could consider using clock_gettime() with CLOCK_PROCESS_CPUTIME_ID.

Measuring time costs time

Calling GetTime::now() itself costs time; it might involve having to make system calls depending on the operating system. If you are going to take the time twice for each time you call func(), and if func() is a relatively fast function, you might start measuring the performance of GetTime::now() instead of the performance of func(). I did some tests where I ran your original code and a modified version that moves the calls to GetTime::now() out of the loop. The result for a function that does a few calculations was:

  • Your code: 48 ns
  • Modified code: 28 ns

This is a difference of 20 ns, which corresponds exactly with some measurements of how long clock_gettime(CLOCK_REALTIME) takes on my machine.

Another way to avoid the issue is to keep measuring time like you do now, but run the loop twice: once while calling func(), another time while calling a function that does nothing. Subtract the two to get the time actually spent inside func(), without including the overhead of time measurent and function call overhead.

Be aware of clock granularity

Clocks are not infinitely precise. On Linux on x86 processors, the steady_clock and high_resolution_clocks typically have a resolution of 1 ns. If you are measuring a function that takes just a few nanoseconds, this means you will have roundoff errors each time you measure the time. Those roundoff errors accumulate in your loop. This is another reason to just take the time before and after the loop to get a good average.

Also consider that there are systems where the clocks have a lower resolution. For example, if you are on a platform where the system clock's resolution is only one microsecond, but the function you are trying to measure only takes 500 nanoseconds, you really need to run the function multiple times between time measurements.

Avoid casting durations too early

This is already mentioned by Toby Speight, just use GetTime::duration as the type for run_time, total_time, min_exec_time and max_exec_time. This type has the right precision for durations measured using the GetTime clock. (Maybe also just rename this to clock, otherwise it sounds like a function.)

Only convert to a floating point number right before printing the measured durations, so basically have format_time() take a duration as a parameter. The exception is the average time; you want to convert the total time to a floating point number before dividing by N.

Do a warm-up before taking actual measurements

Calling a function for the first time might take longer than calling the same function a subsequent time, because the first time it might not have been loaded into the CPU's caches, the CPU's branch predictor might not know how to predict it, any memory allocations might be expensive in the beginning, any file I/O might not hit the page cache yet, and so on. You need a warm-up run to ensure all these things have "warmed up". This will take more than just calling the function once. I suggest you run the whole loop twice, and only use the statistics from the second time you run the loop. You might even consider running the loop many times, and only stopping when the results have stabilized.

Automatically scale the number of loop iterations

Consider running a loop with just a small number of iterations first to get a rough estimate of how long the function takes. Then decide for how long you want to run the benchmark, something between 1 and 10 seconds is a reasonable default. Then you can automatically choose the number of iterations based on the desired runtime of the benchmark divided by the estimated time the function takes.

\$\endgroup\$
6
  • \$\begingroup\$ More than I expected. Thank you for such a detailed review and on where I can improve. I was wondering why max time taken is significantly higher than avg., good to know why. Great review I'll try to incorporate all the mention points. Thank you. \$\endgroup\$
    – Ch3steR
    Oct 2, 2021 at 5:49
  • \$\begingroup\$ On granularity: "Also consider that there are systems where the clocks have a lower resolution [...] you really need to run the function multiple times between time measurements." Actually not really; imagine a task that takes 1 hour and you try to measure its duration using a device with a resolution of 1 day. If sampled repeatedly and randomly, in the majority of measurements the task will appear to start and end on the same day with duration = 0. However 1 in 24 times, it will run through midnight, appearing to take 24 hours. Averaging the measurements, the 1 hour duration is still found. \$\endgroup\$
    – Greedo
    Oct 2, 2021 at 9:42
  • 1
    \$\begingroup\$ @Greedo That only works if you do exactly a multiple of 24 measurements in that scenario. But it's much more likely you don't do the right amount of measurements for the measured average to be the actual average. To minimize the error in the measurement, just measure the duration of the whole loop instead of summing the durations of each individual iteration. \$\endgroup\$
    – G. Sliepen
    Oct 2, 2021 at 11:47
  • \$\begingroup\$ @G.Sliepen Imagine you sample 1000 times, 41 take 24 hours, 959 take 0 then the average is 0.98 hours which is not exactly 1 but that's fine - you can quantify the uncertainty of this estimate using the student-t distribution. The problem with doing them back to back is the central limit theorem - if you want to know the distribution of values, not just the average (so max/min like OP uses, or maybe StDev or shape of distribution) then squashing everything together you lose that info and runtimes appear more gaussian than they really were. This will make max/min closer to the mean than reality \$\endgroup\$
    – Greedo
    Oct 2, 2021 at 13:07
  • \$\begingroup\$ ... so yeah, if your measurement resolution gives some uncertainty to a single measurement, then by taking n in a loop and measuring only once, you can divide that uncertainty by sqrt(n), like measuring many sheets of paper in a stack with a ruler rather than one by one. However you lose information about variation in thickness of the paper, as this gets averaged out. You can estimate it by measuring several stacks and working out the StDev, then scaling that up by sqrt(n), however this assumes the paper thickness is gaussian and there's no way to validate this because that info is lost. \$\endgroup\$
    – Greedo
    Oct 2, 2021 at 13:21
6
\$\begingroup\$

I'm guessing int64_t is intended to be std::int64_t? Don't assume that all compilers declare these types in the global namespace as well as std. If std::int64_t is present, it's declared in <cstdint>, so be sure to include that. Your code could be more portable if you used e.g. std::uint_fast64_t - or in this case, std::chrono::nanoseconds::rep.

std::size_t is consistently misspelt, too.


Accumulating values into a double is likely to lose precision. I'd be inclined to keep the total as a duration, rather than converting to numeric type.


  int idx = std::max(0, pow / 3);
  return std::to_string(run_time / scaling[idx]) + formats[idx];

Although we've taken care here not to run off the beginning of the array, we haven't taken the same care with the end (kiloseconds). We probably want

const std::array formats = {"ns", "µs", "ms", "s"};
auto idx = std::clamp(pow / 3, 0, static_cast<int>(formats.size() - 1));

Also, be careful using names such as pow which are also in the C standard library. That can hamper quick comprehension by your code's readers.

This utility function format_time() probably deserves its own unit tests, to ensure that extremes are handled well.

\$\endgroup\$
6
  • 5
    \$\begingroup\$ I really wouldn't categorize the issue of the type names not necessarily being in the global namespace in a conforming implementation as a spelling error. It's a mistake in not knowing that it's not guaranteed. \$\endgroup\$
    – JDługosz
    Oct 1, 2021 at 13:49
  • \$\begingroup\$ Thank you @Toby. I was under the false impression that int64_t are available in the global scope. Great review! std::array formats = {"ns"...} what would be the type of array is it array<std:string> or array<const char *>? \$\endgroup\$
    – Ch3steR
    Oct 2, 2021 at 5:45
  • \$\begingroup\$ @Ch3steR several implementations make it available in the root namespace. This is allowed, but it is not guaranteed and thus must not be relied upon. \$\endgroup\$
    – spectras
    Oct 2, 2021 at 23:11
  • \$\begingroup\$ That would be an array of const char* (since auto s = "ns" deduces to const char*). If you wanted std::string, there's a suffix operator in std::literals. \$\endgroup\$ Oct 5, 2021 at 6:50
  • \$\begingroup\$ The types are or are not required to be in the global namespace depending on which header was used to introduce them. Looking at the headers included by OP's code, I don't think those names are guaranteed to be available anywhere. #include <inttypes.h> would guarantee they exist in the global namespace, where the code expects to find them. \$\endgroup\$
    – Ben Voigt
    Oct 6, 2021 at 17:45
4
\$\begingroup\$

There's a glaring bug in how you forward arguments

template <size_t N = 1000, typename Callable, typename... Args>
void timeit(Callable func, Args&&... Funcargs) {
    // ...
    for (size_t i = 0; i < N; ++i) {
        // ...
        func(std::forward<Args>(Funcargs)...);
    // ...
}

Consider this

timeit([](std::string s){ s += s; }, std::string("Lorem ipsum dolor sit amet"));

You move the string in the first iteration, and henceforth the string is in a valid but unspecified state, usually just empty. Either way, that's not what you want. A quick fix is

template <typename... Args, typename Callable, typename Tuple, size_t... Is>
void forward_apply(Callable func, Tuple& args, std::index_sequence<Is...>) {
    func(std::forward<Args>(get<Is>(args))...);
}

template <size_t N = 1000, typename Callable, typename... Args>
void timeit(Callable func, Args&&... Funcargs) {
    // ...
    for (size_t i = 0; i < N; ++i) {
        auto args = std::tuple(Funcargs...);
        // ...
        forward_apply<Args&&...>(func, args, std::index_sequence_for<Args...>{});
    // ...
}

where you make a copy of the arguments without timing them, and then forward them as specified by the argument types.

At this point, timeit has rather convoluted semantics. What if the arguments aren't copyable? Should Callable be copied and forwarded similarly to the arguments? A solution provided by the standard library is to use std::reference_wrapper to opt out of copying. However, the complexity for both users and implementer gets even greater.

You could limit the scope of what timeit is supposed to do

template <size_t N = 1000, typename Callable>
void timeit(Callable&& func) {
    // ...
    for (size_t i = 0; i < N; ++i) {
        // ...
        func();
    // ...
}

The semantics is simple: timeit repeatedly calls operator() on the func object passed in, and it's up to the user to decide what to do with arguments. It is however impossible to omit argument copying time in such a design.

\$\endgroup\$
6
  • \$\begingroup\$ Great point about Callable being not copyable. Should I make Callable a forwarding reference too? would that be good? \$\endgroup\$
    – Ch3steR
    Oct 2, 2021 at 5:54
  • 1
    \$\begingroup\$ Thank you for the review again. Since I started learning C++ recently it took some time to understand everything. It made me think maybe redesigning my whole approach might not be a bad idea. \$\endgroup\$
    – Ch3steR
    Oct 2, 2021 at 8:18
  • \$\begingroup\$ Maybe a solution to keep this simple is to just not pass Funcargs to timeit(). Instead, let the caller pass a lambda which has captured the arguments. \$\endgroup\$
    – G. Sliepen
    Oct 2, 2021 at 9:23
  • \$\begingroup\$ @G.Sliepen I considered that, but then it means you always benchmark whatever you do with the arguments. If the user doesn't want to include the copying time, they can't. \$\endgroup\$
    – Passer By
    Oct 2, 2021 at 10:05
  • \$\begingroup\$ @Ch3steR Whether to forward Callable is a design choice. You could require that Callable::operator() not modify its state, which is what your current version means. You could also do what I did with the arguments (copy and forward). Or you could use std::reference_wrapper to opt out of copying. If it were me though, I'd choose the first. \$\endgroup\$
    – Passer By
    Oct 2, 2021 at 10:10

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.