testing: add Elapsed() method to testing.B

[mmcloughlin]

Propose to add an Elapsed method to testing.B, as follows:

// Elapsed returns the measured elapsed time of the benchmark. If the timer is
// running, it will be stopped.
func (b *B) Elapsed() time.Duration {
    b.StopTimer()
    return b.duration
}

Motivation

Custom benchmark metrics are a powerful feature. Go introduced partial support with the testing.B.ReportMetric() API following #26037. However, this API seems to leave a gap in supporting rate metrics. Specifically, rate metrics are those that would be divided by the total benchmark time and reported with the /s suffix, such as the built-in MB/s. These cannot be reported using the existing API since there is no way to access the measured time.

Rate metrics have many use cases. The existence of MB/s proves at least one. You could also imagine reporting packets/s for a network benchmark, points/s for a geometry benchmark. I was just working on a benchmark for the avo assembler and wanted to report instructions/s.

Rate metrics are supported by other benchmark libraries, such as Google Benchmark, which has become somewhat of a de-facto standard for C++ benchmarking. Google Benchmark's user counters are configurable to support rate metrics with the kIsRate flag, along with many others. Google Benchmark also supports the special-case SetItemsProcessed to support examples like packets/s or points/s mentioned previously. As an example, the abseil library uses SetItemsProcessed to report the rate items are pushed to a vector.

I don't think there are satisfactory workarounds for this at the moment. You can measure the time yourself and use it to report a rate metric with ReportMetric. Alternatively, you can abuse SetBytes and post-process the output or inform your users to interpret it differently.

Propose extending the testing.B API such that this is possible. Ideas:

• Add a ReportRate method, similar to ReportMetric but the value will be divided by time.
• Add a SetItemsProcessed method similar to Google Benchmark.
• Expose the measured time so users can compute the rate themselves and report it with the existing API.

Following discussion below, we propose the Elapsed() method given above.

[ianlancetaylor]

CC @aclements

[josharian]

You can measure the time yourself and use it to report a rate metric with ReportMetric.

This isn't too onerous a workaround; measuring elapsed time is both short and simple.

An alternative fix here is to add methods on testing.B that let you query the accumulated metrics, e.g. func (b *B) Elapsed() time.Duration). Sample usage:

  for i := 0; i < b.N; i++ {
    // do stuff
  }
  b.StopTimer()
  b.ReportMetric(customMetric / float64(b.Elapsed().Nanoseconds()), "custom/ns")

[mmcloughlin]

This isn't too onerous a workaround; measuring elapsed time is both short and simple.

Sure, not onerous in terms of lines of code. However, it seems to me that timing code execution is a core responsibility of a benchmark framework, so it seems odd to cede that responsibility to your users.

I haven't even looked at the code under the hood, but you could imagine that the testing package wanted to use a higher precision timer than the time packages uses by default. It's nice that this is hidden from users and can be changed in the future if necessary.

An alternative fix here is to add methods on testing.B that let you query the accumulated metrics, e.g. func (b *B) Elapsed() time.Duration). Sample usage:

  for i := 0; i < b.N; i++ {
    // do stuff
  }
  b.StopTimer()
  b.ReportMetric(customMetric / float64(b.Elapsed().Nanoseconds()), "custom/ns")

Yes, this would be great. This is what I had in mind with the "Expose the measured time so users can compute the rate themselves and report it with the existing API" idea in the description. It does seem slightly awkward that you'd need some contract about calling StopTimer first.

[aclements]

I wouldn't be opposed to exposing the measured elapsed time of the benchmark. While it's true that often this isn't hard to measure for yourself, it becomes much harder in benchmarks that use StopTimer and StartTimer, and having a way to retrieve the framework's own measured time would ensure that any custom time-rate measurements had exactly the same denominator as the built-in ns/op measurement. Having a consistent denominator does depend on calling StopTimer before retrieving the elapsed time, as Josh did.

[mmcloughlin]

Peeking at the internals, this could be as simple as adding a Duration() time.Duration method that returns the b.duration field. The nuance is just what it should do if it's called when the timer is running. Should it:

• Compute duration at that instant and return it, leaving the timer running
• Return 0 if timerOn is true
• panic if timerOn is true

[aclements]

Returning 0 seems like it would invite bugs, but I'm not sure between the other two options.

[josharian]

The nuance is just what it should do if it's called when the timer is running.

A fourth option: stop the timer. Easy to document, yields the correct outcome in most situations with a minimum of fuss.

Duration() time.Duration

I would advocate for Elapsed over Duration, because duration could also mean the target duration of the benchmark run.

[mmcloughlin]

How do we progress this proposal through the process to get a decision? Based on the discussion I think the simplest concrete proposal is the addition of the following method to *testing.B:

// Elapsed returns the measured elapsed time of the benchmark. If the timer is
// running, it will be stopped.
func (b *B) Elapsed() time.Duration {
    b.StopTimer()
    return b.duration
}

Perhaps an additional note in the documentation for ReportMetric would be in order?

[rsc]

Leaving the timer running seems much less surprising than silently stopping the timer.
Otherwise this seems fine to me.

[rsc]

This proposal has been added to the active column of the proposals project
and will now be reviewed at the weekly proposal review meetings.
— rsc for the proposal review group

[mmcloughlin]

Great to see this taken up!

Leaving the timer running seems much less surprising than silently stopping the timer.

Yes, I can see the argument for that.

[rsc]

Assuming Elapsed reports elapsed time but does not change the running state of the timer, does anyone object to adding Elapsed?