I took a quick glance at the code, and I think I figured it out. The
benchmark code, including StartTimer() and StopTimer() use time.Now(). On
my windows machine time.Now() has an accuracy of 1ms. So by calling it for
every iteration, when the actual time is 600ns just makes the whole thing
wildly inaccurate. That 1ms accuracy is ok when the benchmark calls it once
then runs the code 2 million times. But when called each time the accuracy
of the time.Now() code becomes dominant.
It is just an educated guess, but that is what it looks like to me.
Perhaps there should be some sort of warning in the docs?
On Tuesday, March 24, 2020 at 4:01:17 PM UTC-4, Orson Cart wrote:
>
> On Tuesday, 24 March 2020 19:51:24 UTC, Jake Montgomery wrote:
>>
>> Strange. I hope someone has a real answer for you.
>>
>> In the meantime, you can simplify your example to demonstrate the issue:
>>
>
> Thanks for taking a look at the code Jake. Just one question: you have the
> call to b.StopTimer outside of the loop and the call to b.StartTimer
> inside. Was that intentional?
>
> I'd have thought that the call to b.StartTimer would be a no-op after the
> first iteration.
>
>
>
>
>
>
>
>
>>
>> package demo_test
>>
>> import (
>> "testing"
>> )
>>
>> var Foo1 []string
>> var Count int = 8
>>
>> func Benchmark1(b *testing.B) {
>> for i := 0; i < b.N; i++ {
>> Foo1 = foo(Count)
>> }
>> }
>>
>> func Benchmark2(b *testing.B) {
>> b.StopTimer()
>> for i := 0; i < b.N; i++ {
>> // Hypothetical setup here
>> b.StartTimer()
>> Foo1 = foo(Count)
>> b.StopTimer()
>> }
>> }
>>
>>
>> func foo(count int) []string {
>> testData := []string{}
>> for i := 0; i < count; i++ {
>> testData = append(testData, "a")
>> }
>>
>> return testData
>> }
>>
>> I get:
>>
>> goos: windows
>> goarch: amd64
>> Benchmark1-4 2101567 584 ns/op
>> Benchmark2-4 1000000 1668 ns/op
>> PASS
>>
>> So it appears that StopTimer() and StartTimer() are introducing some
>> overhead. I am surprised that it is this large.
>>
>> Good Luck
>>
>>
>>
>> On Tuesday, March 24, 2020 at 12:24:08 PM UTC-4, Orson Cart wrote:
>>>
>>> I posted this earlier but I realised that the code had a fundamental
>>> error in it. I've corrected here it but the underlying problem still exists.
>>>
>>> I've recently started using go test's benchmarks support and I'm
>>> particularly interested in understanding the benchmark timer functions.
>>> I've been getting results that I found surprising and I was wondering if
>>> anyone could explain what's going on here.
>>>
>>> The code below has three benchmarks that each invoke a single function
>>> (foo). The implementation of foo isn't important, it's just there to
>>> consume some time:
>>> - foo is called once per iteration in Benchmark1.
>>> - It's called twice per iteration in Benchmark2 so I'd expect
>>> Benchmark2's duration to be nominally twice that of Benchmark1.
>>> - It's also called twice per iteration in Benchmark3 but the first call
>>> is wrapped in b.StopTimer and b.startTimer calls. Because of this I'd have
>>> expected Benchmark3 to be about the same duration as Benchmark1
>>>
>>> Apologies for the length of the example but I didn't think it fair to
>>> ask the question and leave anything out.
>>>
>>> package demo_test
>>>
>>> import (
>>> "strconv"
>>> "testing"
>>> )
>>>
>>> var Foo1 []string
>>> var Foo2 []string
>>> var Count int = 32767
>>>
>>> func Benchmark1(b *testing.B) {
>>> for i := 0; i < b.N; i++{
>>> Foo1 = foo(Count)
>>> }
>>> }
>>>
>>> func Benchmark2(b *testing.B) {
>>> for i := 0; i < b.N; i++{
>>> Foo1 = foo(Count)
>>> Foo2 = foo(Count)
>>> }
>>> }
>>>
>>> func Benchmark3(b *testing.B) {
>>> for i := 0; i < b.N; i++{
>>> b.StopTimer()
>>> Foo1 = foo(Count)
>>> b.StartTimer()
>>> Foo2 = foo(Count)
>>> }
>>> }
>>>
>>> func foo(count int) []string{
>>> testData := []string{}
>>> for i:= 0; i < count; i++ {
>>> testData = append(testData, strconv.Itoa(i))
>>> }
>>>
>>> return testData
>>> }
>>>
>>>
>>> When the benchmarks are run the results are as follows:
>>>
>>> Benchmark1-4 351 3345215 ns/op
>>> Benchmark2-4 166 7206582 ns/op
>>> Benchmark3-4 334 3457907 ns/op
>>> PASS
>>> ok bar.com/benchmarks 6.881s
>>>
>>> OK benchmark3 is a little slower than Benchmark1 but that's not what's
>>> bothering me. It's this: if I now change Count to something much smaller
>>> the results are a surprise, at least to me. Here are the results when Count
>>> = 8:
>>>
>>> Benchmark1-4 2706196 442 ns/op
>>> Benchmark2-4 1357482 873 ns/op
>>> Benchmark3-4 840729 1387 ns/op
>>> PASS
>>> ok bar.com/benchmarks 23.547s
>>>
>>> The ratio of timings for Benchmark1 and Benchmark2 are roughly in line
>>> with expectations but I was surprised to see that the timings for
>>> Benchmark3 are now larger than those for Benchmark2.
>>>
>>> Can anyone explain this?
>>>
>>> TIA
>>> Orson
>>>
>>
--
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+unsubscr...@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/golang-nuts/e1a379d2-aeb8-49be-bd86-15c1495967e3%40googlegroups.com.
