On Tuesday, 24 March 2020 20:16:21 UTC, Jake Montgomery wrote:
>
> 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.
>
Thanks once again. Others on the thread have pointed out more potential
issues. I feel a bit like a carpenter who has to measure a piece of wood
but who only has a rubber rule :D
>
>
> 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/0f718800-042a-4176-b4dd-545e86e0b655%40googlegroups.com.
