atlas_test.go

package serialization

import (
	"testing"
	"time"

	"github.com/polydawn/refmt/cbor"
	"github.com/polydawn/refmt/obj/atlas"
)

var cborAtlas atlas.Atlas

//var atlasEntries = []*atlas.AtlasEntry{cidAtlasEntry, bigIntAtlasEntry}
var atlasEntries = make([]*atlas.AtlasEntry, 0)

func init() {
	cborAtlas = atlas.MustBuild()
	RegisterCborType(testEncodeStruct{})
}

// RegisterCborType allows to register a custom cbor type
func RegisterCborType(i interface{}) {
	var entry *atlas.AtlasEntry
	if ae, ok := i.(*atlas.AtlasEntry); ok {
		entry = ae
	} else {
		entry = atlas.BuildEntry(i).StructMap().Autogenerate().Complete()
	}
	atlasEntries = append(atlasEntries, entry)
	cborAtlas = atlas.MustBuild(atlasEntries...)
}

type testEncodeStruct struct {
	Id     string
	Number int
}

func TestParallelWrap(t *testing.T) {

	times := 10000

	obj := &testEncodeStruct{Id: "test", Number: 100}

	responses := make(chan time.Duration, times)

	launchStart := time.Now()
	for i := 0; i < times; i++ {
		go func() {
			var m interface{}
			now := time.Now()
			data, err := cbor.MarshalAtlased(obj, cborAtlas)
			if err != nil {
				panic("error marshaling")
			}

			cbor.UnmarshalAtlased(data, &m, cborAtlas)

			end := time.Now().Sub(now)
			responses <- end
		}()
	}
	t.Logf("launch fanout took: %v", time.Now().Sub(launchStart))

	respSlice := make([]time.Duration, times)

	for i := 0; i < times; i++ {
		respSlice[i] = <-responses
	}
	t.Logf("max was: %v", max(respSlice))
	t.Fail()
}

func max(ints []time.Duration) time.Duration {
	max := time.Duration(0)
	for i := 0; i < len(ints); i++ {
		if ints[i] > max {
			max = ints[i]
		}
	}
	return max
}

I changed the gist to:

• use time.Duration instead of ints -- I dunno, it just printed prettier
• print the time spent in the for-loop that's launching goroutines. The go is "nonblocking" but it's still doing some work
• dropped testify -- I just don't use that library and didn't feel like fetching it

And here's what I get:

    foobar_test.go:62: launch fanout took: 60.042002ms
    foobar_test.go:69: max was: 65.715747ms

Of course, it's quite a bit random: on another run, I get:

    foobar_test.go:62: launch fanout took: 42.806798ms
    foobar_test.go:69: max was: 78.046302ms

One thing's clear: we're absolutely in the scale of microbenchmarking where we're effectively measuring the variability of the go runtime scheduler and channel system. Just launching the goroutines takes between 50% and 92% of the overall time reported by the slowest worker goroutine.

Benchmarking is hard. Parallel benchmarking sextuply so.

While I work on doing a better repro... here's my results

My 2.3Ghz 2013 MBP gives me:

serialization_test.go:162: launch fanout took: 63.776362ms
serialization_test.go:169: max was: 152.20056ms

serialization_test.go:162: launch fanout took: 77.443229ms
serialization_test.go:169: max was: 155.842248ms

serialization_test.go:162: launch fanout took: 64.010625ms
serialization_test.go:169: max was: 153.041077ms