Between foo() exiting and the hardware timer being read, there is
* The call to StopTimer()
* A conditoinal branch
* A call to time.Since
* Another conditional
* A call to either Now() or runtimenano()
Now calls might get inlined, and the branches get predicted, but I
doubt the overhead of all that is zero and, it can be significant
compared to a very fast `foo()` function. Also, after Start/Stop
timer is called, there's a call to runtime.ReadMemStats() which does
nontrivial stuff and could thrash the caches, slowing down the actual
benchmark code.
The docs for StopTimer say:
> StopTimer stops timing a test. This can be used to pause the timer while
> performing complex initialization that you don't want to measure.
So that sounds like the use-case is to call Stop-, StartTimer once
before you enter the main loop of the benchmark. They not efficient
enough for a tight inner loop.
On Wed, 25 Mar 2020 at 06:51, Jake Montgomery <jake6...@gmail.com> wrote:
>
> Strange. I hope someone has a real answer for you.
>
> In the meantime, you can simplify your example to demonstrate the issue:
>
> 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/feda7e38-5d1f-43cf-b0cd-98db0a94d3c9%40googlegroups.com.
--
Adrian Ratnapala
--
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/CAN%2BHj7jEvkOBejV6bZbBmQEcapKafUvBAJKmAhoVGg%2BC7PwEEg%40mail.gmail.com.
