Re: [go-nuts] Re: Bencharking issue with b.StartTimer and b.StopTimer. Was: Benchmark using b.StopTimer and b.StartTimer has unexpected behaviour - to me at least
Just an FYI - this is by no means Go related. These problems and techniques are
very common when doing HPC micro benchmarking.
> On Mar 24, 2020, at 4:10 PM, Orson Cart wrote:
>
>
>> On Tuesday, 24 March 2020 21:00:38 UTC, Sean Liao wrote:
>> setup upfront shouldn't be a problem
>> b.N is constant throughout the function lifetime, the entire function is
>> called multiple times during benchmarking
>
> Thank you! I'd missed that. That makes things so much more straightforward
> for me.
>
>
>>
>>> On Tuesday, March 24, 2020 at 9:56:19 PM UTC+1, Orson Cart wrote:
On Tuesday, 24 March 2020 20:47:07 UTC, Robert Engels wrote:
One way to handle this is to generate all of the data up front in an array
and then just index into the array based on the run.
>>>
>>> Yeah, I had thought of that before posting but then I'd have to decide on a
>>> value for b.N. I was trying to roll with the idea of the framework
>>> establishing a value. To be honest if it wasn't for the fact that I was
>>> just curious as to why it wasn't working I'd just have settled for an array
>>> with a fixed b.N.
>>>
>>> All part of my golang learning experience
>>>
>>>
>> On Mar 24, 2020, at 3:42 PM, Orson Cart wrote:
>>
>
>
>
>> On Tuesday, 24 March 2020 20:27:39 UTC, Adrian Ratnapala wrote:
>> ...
>> 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.
>
> Thanks for the input and I think that you are probably correct. It would
> be nice if the docs said that though.
>
> The code that I'm profiling wasn't written by me. It's fast but it
> modifies its input data so it needs new data on each iteration. The
> implementation is non-trivial and it might be a maintenance headache.
> I've been asked to benchmark it along with less complicated
> implementations. It was whilst trying to set up per-iteration test data
> that I came across this issue.
>
>
>
>
>
>
>
>
>>
>> On Wed, 25 Mar 2020 at 06:51, 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:
>> >
>> > 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 100 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
Re: [go-nuts] Re: Bencharking issue with b.StartTimer and b.StopTimer. Was: Benchmark using b.StopTimer and b.StartTimer has unexpected behaviour - to me at least
On Tuesday, 24 March 2020 21:00:38 UTC, Sean Liao wrote:
>
> setup upfront shouldn't be a problem
> b.N is constant throughout the function lifetime, the entire function is
> called multiple times during benchmarking
>
Thank you! I'd missed that. That makes things so much more straightforward
for me.
>
> On Tuesday, March 24, 2020 at 9:56:19 PM UTC+1, Orson Cart wrote:
>>
>> On Tuesday, 24 March 2020 20:47:07 UTC, Robert Engels wrote:
>>>
>>> One way to handle this is to generate all of the data up front in an
>>> array and then just index into the array based on the run.
>>>
>>
>> Yeah, I had thought of that before posting but then I'd have to decide on
>> a value for b.N. I was trying to roll with the idea of the framework
>> establishing a value. To be honest if it wasn't for the fact that I was
>> just curious as to why it wasn't working I'd just have settled for an array
>> with a fixed b.N.
>>
>> All part of my golang learning experience
>>
>>
>>
>>>
>>> On Mar 24, 2020, at 3:42 PM, Orson Cart wrote:
>>>
>>>
>>>
>>>
>>> On Tuesday, 24 March 2020 20:27:39 UTC, Adrian Ratnapala wrote:
...
>>>
>>> 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.
>>>
>>> Thanks for the input and I think that you are probably correct. It would
>>> be nice if the docs said that though.
>>>
>>> The code that I'm profiling wasn't written by me. It's fast but it
>>> modifies its input data so it needs new data on each iteration. The
>>> implementation is non-trivial and it might be a maintenance headache. I've
>>> been asked to benchmark it along with less complicated implementations. It
>>> was whilst trying to set up per-iteration test data that I came across this
>>> issue.
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
On Wed, 25 Mar 2020 at 06:51, 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:
>
> 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 100 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
Re: [go-nuts] Re: Bencharking issue with b.StartTimer and b.StopTimer. Was: Benchmark using b.StopTimer and b.StartTimer has unexpected behaviour - to me at least
setup upfront shouldn't be a problem
b.N is constant throughout the function lifetime, the entire function is
called multiple times during benchmarking
On Tuesday, March 24, 2020 at 9:56:19 PM UTC+1, Orson Cart wrote:
>
> On Tuesday, 24 March 2020 20:47:07 UTC, Robert Engels wrote:
>>
>> One way to handle this is to generate all of the data up front in an
>> array and then just index into the array based on the run.
>>
>
> Yeah, I had thought of that before posting but then I'd have to decide on
> a value for b.N. I was trying to roll with the idea of the framework
> establishing a value. To be honest if it wasn't for the fact that I was
> just curious as to why it wasn't working I'd just have settled for an array
> with a fixed b.N.
>
> All part of my golang learning experience
>
>
>
>>
>> On Mar 24, 2020, at 3:42 PM, Orson Cart wrote:
>>
>>
>>
>>
>> On Tuesday, 24 March 2020 20:27:39 UTC, Adrian Ratnapala wrote:
>>>
>>> ...
>>
>> 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.
>>>
>>
>> Thanks for the input and I think that you are probably correct. It would
>> be nice if the docs said that though.
>>
>> The code that I'm profiling wasn't written by me. It's fast but it
>> modifies its input data so it needs new data on each iteration. The
>> implementation is non-trivial and it might be a maintenance headache. I've
>> been asked to benchmark it along with less complicated implementations. It
>> was whilst trying to set up per-iteration test data that I came across this
>> issue.
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>>
>>> On Wed, 25 Mar 2020 at 06:51, 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:
>>> >
>>> > 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 100 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)
>>> >> }
Re: [go-nuts] Re: Bencharking issue with b.StartTimer and b.StopTimer. Was: Benchmark using b.StopTimer and b.StartTimer has unexpected behaviour - to me at least
On Tuesday, 24 March 2020 20:47:07 UTC, Robert Engels wrote:
>
> One way to handle this is to generate all of the data up front in an array
> and then just index into the array based on the run.
>
Yeah, I had thought of that before posting but then I'd have to decide on a
value for b.N. I was trying to roll with the idea of the framework
establishing a value. To be honest if it wasn't for the fact that I was
just curious as to why it wasn't working I'd just have settled for an array
with a fixed b.N.
All part of my golang learning experience
>
> On Mar 24, 2020, at 3:42 PM, Orson Cart > wrote:
>
>
>
>
> On Tuesday, 24 March 2020 20:27:39 UTC, Adrian Ratnapala wrote:
>>
>> ...
>
> 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.
>>
>
> Thanks for the input and I think that you are probably correct. It would
> be nice if the docs said that though.
>
> The code that I'm profiling wasn't written by me. It's fast but it
> modifies its input data so it needs new data on each iteration. The
> implementation is non-trivial and it might be a maintenance headache. I've
> been asked to benchmark it along with less complicated implementations. It
> was whilst trying to set up per-iteration test data that I came across this
> issue.
>
>
>
>
>
>
>
>
>
>>
>> On Wed, 25 Mar 2020 at 06:51, 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:
>> >
>> > 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 100 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
Re: [go-nuts] Re: Bencharking issue with b.StartTimer and b.StopTimer. Was: Benchmark using b.StopTimer and b.StartTimer has unexpected behaviour - to me at least
One way to handle this is to generate all of the data up front in an array and
then just index into the array based on the run.
> On Mar 24, 2020, at 3:42 PM, Orson Cart wrote:
>
>
>
>
>> On Tuesday, 24 March 2020 20:27:39 UTC, Adrian Ratnapala wrote:
>> ...
>> 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.
>
> Thanks for the input and I think that you are probably correct. It would be
> nice if the docs said that though.
>
> The code that I'm profiling wasn't written by me. It's fast but it modifies
> its input data so it needs new data on each iteration. The implementation is
> non-trivial and it might be a maintenance headache. I've been asked to
> benchmark it along with less complicated implementations. It was whilst
> trying to set up per-iteration test data that I came across this issue.
>
>
>
>
>
>
>
>
>>
>> On Wed, 25 Mar 2020 at 06:51, 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:
>> >
>> > 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 100 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:
>> >>
>>
Re: [go-nuts] Re: Bencharking issue with b.StartTimer and b.StopTimer. Was: Benchmark using b.StopTimer and b.StartTimer has unexpected behaviour - to me at least
On Tuesday, 24 March 2020 20:27:39 UTC, Adrian Ratnapala wrote:
>
> ...
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.
>
Thanks for the input and I think that you are probably correct. It would be
nice if the docs said that though.
The code that I'm profiling wasn't written by me. It's fast but it modifies
its input data so it needs new data on each iteration. The implementation
is non-trivial and it might be a maintenance headache. I've been asked to
benchmark it along with less complicated implementations. It was whilst
trying to set up per-iteration test data that I came across this issue.
>
> On Wed, 25 Mar 2020 at 06:51, 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:
> >
> > 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 100 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 t
Re: [go-nuts] Re: Bencharking issue with b.StartTimer and b.StopTimer. Was: Benchmark using b.StopTimer and b.StartTimer has unexpected behaviour - to me at least
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 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 100 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 rece
