help understanding weird Benchmark results

[Warren Bare]

Hi Folks,

I'm getting weird results from Benchmark.  Maybe someone can help me understand this.  I'm running on amd-64 (Threadripper 16 core 32 thread) Windows 10.  Go 1.14.3

I have the benchmark below (main_test.go) on a minimum "hello world" main.go (just like playground).

When I run the benchmark as it is below, I get the results included just below here.  Notice it reports 0.135 ns/op but the time is actually 135 ms so it is off by a factor of 1 billion.  It is like it trying to report in seconds but did not change the label from ns to s.

Further, if I increase the loop 10x from 10_000_000 to 100_000_000, then it prints Duration 1.349 seconds (good) and now the Benchmark time has increased by a factor of 10 billion and is now correctly reported as 1349224200 ns/op

What am I missing here?

BenchmarkMarshalSample-32       1000000000           0.135 ns/op           0 B/op          0 allocs/op

--- BENCH: BenchmarkMarshalSample-32

    main_test.go:14: Duration 136.1221ms

    main_test.go:14: Duration 135.1214ms

    main_test.go:14: Duration 134.1763ms

    main_test.go:14: Duration 135.1217ms

    main_test.go:14: Duration 135.1298ms

    main_test.go:14: Duration 135.1217ms

    main_test.go:14: Duration 135.1218ms

    main_test.go:14: Duration 135.1213ms

    main_test.go:14: Duration 135.1298ms

    main_test.go:14: Duration 135.1216ms

    ... [output truncated]

PASS

package main

import (

    "math/rand"

    "testing"

    "time"

)

func BenchmarkMarshalSample(b *testing.B) {

    start := time.Now()

    for i := 0; i < 10_000_000; i++ {

        rand.Int63()

    }

    b.Log("Duration", time.Now().Sub(start))

}

[Volker Dobler]

You are supposed to run the loop b.N times, not

some fixed constant. Also make sure the compiler

doesn't optimize away the whole function.

V.

[Warren Bare]

>You are supposed to run the loop b.N times, not some fixed constant. 

I understand.  This is a simulation of a single bigger task that takes a while.  I'm not trying to time the rand function inside the loop.  The loop is simply to burn time.  This simple function is a minimal example that demonstrates a problem I was having with my own real benchmark test.

I don't know for sure that the compiler is NOT optimizing away this rand function, but I can tell you this problem was happening on my own code that can not be optimized away.  

Thanks.

[Michael Jones]

as was explained, the loop needs to be "for i:=0; i < b.N; i++"

as was mentioned, the compiler's dead code elimination efforts can frustrate benchmarking. they way to make sure the test code survives is to not let it be dead code. for example

// external var dummy

func

for i:=0; i < b.N; i++ {

  dummy += rand.Int63()

}

--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/2abb7390-3c3c-4172-aead-021dbf500bad%40googlegroups.com.

--

Michael T. Jones
michae...@gmail.com

[Warren Bare]

OK, I added a sum of the rand to the demo code and the results are the same.  Since it is displaying the sum, it seems clear that the code is not optimized away.

Again, I am NOT trying to time each iteration of the loop.  This is a minimal demonstration of a weirdness I was seeing in my own benchmarks.  Just pretend the loop is one chunk of code that takes time and is not optimized away.

Any other ideas?

func BenchmarkMarshalSample(b *testing.B) {

    var sum int64

    start := time.Now()

    for i := 0; i < 10_000_000; i++ {

        sum += rand.Int63n(0xFFFFFFFF)

    }

    b.Logf("Sum %e Duration %v", float64(sum), time.Now().Sub(start))

}

[Warren Bare]

OK, I got it.  You were trying to change the code I was benchmarking, and I did not realize you were trying to say a benchmark must have the ability to run b.N times.

Yes, that was the problem.  This fixed it:

func BenchmarkMarshalSample(b *testing.B) {

    var sum int64

    for i:= 0; i < b.N; i++ {

        start := time.Now()

        for x := 0; x < 10_000_000; x++ {

[Marvin Renich]

* Warren Bare <warre...@gmail.com> [200519 13:53]:

> OK, I added a sum of the rand to the demo code and the results are the
> same. Since it is displaying the sum, it seems clear that the code is not
> optimized away.
>
> Again, I am NOT trying to time each iteration of the loop. This is a
> minimal demonstration of a weirdness I was seeing in my own benchmarks.
> Just pretend the loop is one chunk of code that takes time and is not
> optimized away.
>
> Any other ideas?
>
> func BenchmarkMarshalSample(b *testing.B) {
> var sum int64
> start := time.Now()
> for i := 0; i < 10_000_000; i++ {
> sum += rand.Int63n(0xFFFFFFFF)
> }
> b.Logf("Sum %e Duration %v", float64(sum), time.Now().Sub(start))
> }

You do not clearly understand how benchmarking in the testing package
works. In order to get meaningful results, your benchmark function
_must_ iterate b.N times. The benchmark framework is going to run your
function several times, with different values of b.N until it can get a
meaningful time, and then it does the math to give you "per iteration"
times. Read carefully the section "Benchmarks" under
https://golang.org/pkg/testing/.

For the above case (given that you are not trying to time one
invocation of rand.Int63n, but a fixed number) you would write your code
like this:

func BenchmarkMarshalSample(b *testing.B) {
var sum int64
start := time.Now()

for j := 0; j < b.N; j++ {

for i := 0; i < 10_000_000; i++ {
sum += rand.Int63n(0xFFFFFFFF)
}
}
b.Logf("Sum %e Duration %v", float64(sum), time.Now().Sub(start))
}

The benchmark results will give the time for _one_ iteration of the
_outer_ loop, so the "op" in "ns/op" will be 10_000_000 iterations of
the inner loop.

...Marvin

[mi...@treatwell.com]

As Michael Jones said, you still need to play by the testing package's benchmark rules for it to be able to benchmark your code.

So something along these lines.

func BenchmarkMarshalSample(b *testing.B) {
    for i:=0; i < b.N; i++ {
        var sum int64
        // start := time.Now()

        for i := 0; i < 10_000_000; i++ {
            sum += rand.Int63n(0xFFFFFFFF)
        }

        // b.Logf("Sum %e Duration %v", float64(sum), time.Now().Sub(start))
    }
}