From c7b2c7cfa3cf25da3c71db794ceecb1ce4e970ee Mon Sep 17 00:00:00 2001 From: Ivan Dlugos Date: Wed, 5 Jul 2023 20:04:33 +0200 Subject: [PATCH] update profiler benchmarks --- profiler.go | 3 +- profiler_test.go | 123 +++++++++++++++++++++++++++++++++------- traces_profiler_test.go | 2 +- 3 files changed, 104 insertions(+), 24 deletions(-) diff --git a/profiler.go b/profiler.go index 2b0c599a7..8ea200900 100644 --- a/profiler.go +++ b/profiler.go @@ -311,8 +311,7 @@ func (p *profileRecorder) processRecords(elapsedNs uint64, stacksBuffer []byte) for i := 0; i < length; i++ { var stack = traces.Item(i) - var stackIndex = p.addStackTrace(stack) - bucket.stackIDs[i] = stackIndex + bucket.stackIDs[i] = p.addStackTrace(stack) bucket.goIDs[i] = stack.GoID() } diff --git a/profiler_test.go b/profiler_test.go index 5ed31feb7..640b683b3 100644 --- a/profiler_test.go +++ b/profiler_test.go @@ -2,6 +2,7 @@ package sentry import ( "fmt" + "math/rand" "os" "runtime" "strings" @@ -16,9 +17,10 @@ import ( // Test ticker that ticks on demand instead of relying on go runtime timing. type profilerTestTicker struct { - t *testing.T - tick chan time.Time - ticked chan struct{} + logger func(args ...any) + sleepBeforeTick time.Duration + tick chan time.Time + ticked chan struct{} } func (t *profilerTestTicker) TickSource() <-chan time.Time { @@ -34,22 +36,23 @@ func (t *profilerTestTicker) Stop() {} // Sleeps before a tick to emulate a reasonable frequency of ticks, or they may all come at the same relative time. // Then, sends a tick and waits for the profiler to process it. func (t *profilerTestTicker) Tick() bool { - time.Sleep(time.Millisecond) + time.Sleep(t.sleepBeforeTick) t.tick <- time.Now() select { case <-t.ticked: return true case <-time.After(1 * time.Second): - t.t.Log("Timed out waiting for Ticked() to be called.") + t.logger("Timed out waiting for Ticked() to be called.") return false } } -func setupProfilerTestTicker(t *testing.T) *profilerTestTicker { +func setupProfilerTestTicker(logger func(args ...any)) *profilerTestTicker { ticker := &profilerTestTicker{ - t: t, - tick: make(chan time.Time, 1), - ticked: make(chan struct{}), + logger: logger, + sleepBeforeTick: time.Millisecond, + tick: make(chan time.Time, 1), + ticked: make(chan struct{}), } profilerTickerFactory = func(d time.Duration) profilerTicker { return ticker } return ticker @@ -84,7 +87,7 @@ func TestProfilerCollection(t *testing.T) { var require = require.New(t) var goID = getCurrentGoID() - ticker := setupProfilerTestTicker(t) + ticker := setupProfilerTestTicker(t.Log) defer restoreProfilerTicker() start := time.Now() @@ -112,7 +115,7 @@ func TestProfilerCollection(t *testing.T) { func TestProfilerStackTrace(t *testing.T) { var require = require.New(t) - ticker := setupProfilerTestTicker(t) + ticker := setupProfilerTestTicker(t.Log) defer restoreProfilerTicker() start := time.Now() @@ -149,7 +152,7 @@ testing (*T).Run`)) func TestProfilerCollectsOnStart(t *testing.T) { var require = require.New(t) - setupProfilerTestTicker(t) + setupProfilerTestTicker(t.Log) defer restoreProfilerTicker() start := time.Now() @@ -161,7 +164,7 @@ func TestProfilerCollectsOnStart(t *testing.T) { func TestProfilerPanicDuringStartup(t *testing.T) { var require = require.New(t) - _ = setupProfilerTestTicker(t) + _ = setupProfilerTestTicker(t.Log) defer restoreProfilerTicker() atomic.StoreInt64(&testProfilerPanic, -1) @@ -186,7 +189,7 @@ func TestProfilerPanicOnTick(t *testing.T) { var require = require.New(t) - ticker := setupProfilerTestTicker(t) + ticker := setupProfilerTestTicker(t.Log) defer restoreProfilerTicker() // Panic after the first sample is collected. @@ -482,19 +485,19 @@ func TestProfilerTimeSleep(t *testing.T) { require.LessOrEqual(t, elapsed.Microseconds(), profilerSamplingRate.Microseconds()*int64(count+3)) } -// Benchmark results (run without executing which mess up results) +// Benchmark results (run without executing test which mess up results) // $ go test -run=^$ -bench "BenchmarkProfiler*" // // goos: windows // goarch: amd64 // pkg: github.com/getsentry/sentry-go // cpu: 12th Gen Intel(R) Core(TM) i7-12700K -// BenchmarkProfilerStartStop-20 38008 31072 ns/op 20980 B/op 108 allocs/op -// BenchmarkProfilerOnTick-20 65700 18065 ns/op 260 B/op 4 allocs/op -// BenchmarkProfilerCollect-20 67063 16907 ns/op 0 B/op 0 allocs/op -// BenchmarkProfilerProcess-20 2296788 512.9 ns/op 268 B/op 4 allocs/op -// BenchmarkProfilerOverheadBaseline-20 192 6250525 ns/op -// BenchmarkProfilerOverheadWithProfiler-20 187 6249490 ns/op +// BenchmarkProfilerStartStop/Wait-20 12313 100383 ns/op 130459 B/op 3163 allocs/op +// BenchmarkProfilerStartStop/NoWait-20 8964 118605 ns/op 130783 B/op 3163 allocs/op +// BenchmarkProfilerOnTick-20 61993 18999 ns/op 1088 B/op 10 allocs/op +// BenchmarkProfilerCollect-20 61149 18824 ns/op 0 B/op 0 allocs/op +// BenchmarkProfilerProcess-20 872079 1195 ns/op 1040 B/op 10 allocs/op +// BenchmarkProfilerGetSlice-20 31327 34156 ns/op 79050 B/op 19 allocs/op func BenchmarkProfilerStartStop(b *testing.B) { var bench = func(name string, wait bool) { @@ -538,6 +541,84 @@ func BenchmarkProfilerProcess(b *testing.B) { } } +var profilerSliceBenchmarkData = struct { + profiler *profileRecorder + spans []struct { + start time.Time + end time.Time + } +}{ + spans: make([]struct { + start time.Time + end time.Time + }, 100), +} + +func setupProfilerSliceBenchmark(b *testing.B) { + ticker := setupProfilerTestTicker(b.Log) + ticker.sleepBeforeTick = time.Microsecond + + start := time.Now() + profiler := startProfiling(start).(*profileRecorder) + + // Fill in the profiler circular buffer first + for i := 0; i < profiler.samplesBucketsHead.Len(); i++ { + if !ticker.Tick() { + b.Fatal("Tick() failed") + } + } + + if profiler.samplesBucketsHead.Next().Value == nil { + b.Fatal("Profiler circular buffer is not filled completely") + } + + end := time.Now() + if end.Compare(start) <= 0 { + b.Fatal("Unexpected end time") + } + + // Prepare a set of spans we will be collecting. + random := rand.New(rand.NewSource(42)) + collected := 0 + for i := 0; i < len(profilerSliceBenchmarkData.spans); i++ { + spanStart := start.Add(time.Duration(random.Int63n(end.Sub(start).Nanoseconds()))) + spanEnd := spanStart.Add(time.Duration(random.Int63n(end.Sub(spanStart).Nanoseconds()))) + + profilerSliceBenchmarkData.spans[i].start = spanStart + profilerSliceBenchmarkData.spans[i].end = spanEnd + + slice := profiler.GetSlice(spanStart, spanEnd) + if slice != nil { + collected += len(slice.trace.Samples) + b.Logf("Picked span: %d ms - %d ms with %d samples.\n", spanStart.Sub(start).Milliseconds(), spanEnd.Sub(start).Milliseconds(), len(slice.trace.Samples)) + } + } + + if collected <= 0 { + b.Fatal("Profiler failed to collect data") + } + + b.Logf("Preparation took %d ms. Prepared %d samples in %d spans.\n", end.Sub(start).Milliseconds(), collected, len(profilerSliceBenchmarkData.spans)) + + defer restoreProfilerTicker() + defer profiler.Stop(true) + + profilerSliceBenchmarkData.profiler = profiler +} + +func BenchmarkProfilerGetSlice(b *testing.B) { + if profilerSliceBenchmarkData.profiler == nil { + setupProfilerSliceBenchmark(b) + } + + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + span := profilerSliceBenchmarkData.spans[i%len(profilerSliceBenchmarkData.spans)] + _ = profilerSliceBenchmarkData.profiler.GetSlice(span.start, span.end) + } +} + func profilerBenchmark(t *testing.T, b *testing.B, withProfiling bool, arg int) { var p profiler if withProfiling { diff --git a/traces_profiler_test.go b/traces_profiler_test.go index 260fb1982..1a080bfe2 100644 --- a/traces_profiler_test.go +++ b/traces_profiler_test.go @@ -9,7 +9,7 @@ import ( ) func testTraceProfiling(t *testing.T, rate float64) (*Span, *Event) { - ticker := setupProfilerTestTicker(t) + ticker := setupProfilerTestTicker(t.Log) defer restoreProfilerTicker() transport := &TransportMock{}