fix frames order in profiler stacktrace

internal/traceparser/README.md

@@ -5,9 +5,11 @@ goos: windows
 goarch: amd64
 pkg: github.com/getsentry/sentry-go/internal/trace
 cpu: 12th Gen Intel(R) Core(TM) i7-12700K
-BenchmarkEqualBytes-20          42332671                25.99 ns/op
-BenchmarkStringEqual-20         70265427                17.02 ns/op
-BenchmarkEqualPrefix-20         42128026                30.14 ns/op
-BenchmarkFullParse-20             738534              1501 ns/op        1358.56 MB/s        1024 B/op          6 allocs/op
-BenchmarkSplitOnly-20            2298318               524.6 ns/op      3886.65 MB/s         128 B/op          1 allocs/op
+BenchmarkEqualBytes-20                  44323621                26.08 ns/op
+BenchmarkStringEqual-20                 60980257                18.27 ns/op
+BenchmarkEqualPrefix-20                 41369181                31.12 ns/op
+BenchmarkFullParse-20                     702012              1507 ns/op        1353.42 MB/s        1024 B/op          6 allocs/op
+BenchmarkFramesIterator-20               1229971               969.3 ns/op           896 B/op          5 allocs/op
+BenchmarkFramesReversedIterator-20       1271061               944.5 ns/op           896 B/op          5 allocs/op
+BenchmarkSplitOnly-20                    2250800               534.0 ns/op      3818.23 MB/s         128 B/op          1 allocs/op
 ```

internal/traceparser/parser.go

@@ -77,11 +77,55 @@ func (t *Trace) UniqueIdentifier() []byte {
 	return t.data
 }
 
+func (t *Trace) Frames() FrameIterator {
+	var lines = bytes.Split(t.data, lineSeparator)
+	return FrameIterator{lines: lines, i: 0, len: len(lines)}
+}
+
 func (t *Trace) FramesReversed() ReverseFrameIterator {
 	var lines = bytes.Split(t.data, lineSeparator)
 	return ReverseFrameIterator{lines: lines, i: len(lines)}
 }
 
+const framesElided = "...additional frames elided..."
+
+// FrameIterator iterates over stack frames.
+type FrameIterator struct {
+	lines [][]byte
+	i     int
+	len   int
+}
+
+// Next returns the next frame, or nil if there are none.
+func (it *FrameIterator) Next() Frame {
+	return Frame{it.popLine(), it.popLine()}
+}
+
+func (it *FrameIterator) popLine() []byte {
+	switch {
+	case it.i >= it.len:
+		return nil
+	case string(it.lines[it.i]) == framesElided:
+		it.i++
+		return it.popLine()
+	default:
+		it.i++
+		return it.lines[it.i-1]
+	}
+}
+
+// HasNext return true if there are values to be read.
+func (it *FrameIterator) HasNext() bool {
+	return it.i < it.len
+}
+
+// LengthUpperBound returns the maximum number of elements this stacks may contain.
+// The actual number may be lower because of elided frames. As such, the returned value
+// cannot be used to iterate over the frames but may be used to reserve capacity.
+func (it *FrameIterator) LengthUpperBound() int {
+	return it.len / 2
+}
+
 // ReverseFrameIterator iterates over stack frames in reverse order.
 type ReverseFrameIterator struct {
 	lines [][]byte
@@ -94,8 +138,6 @@ func (it *ReverseFrameIterator) Next() Frame {
 	return Frame{it.popLine(), line2}
 }
 
-const framesElided = "...additional frames elided..."
-
 func (it *ReverseFrameIterator) popLine() []byte {
 	it.i--
 	switch {
@@ -113,7 +155,7 @@ func (it *ReverseFrameIterator) HasNext() bool {
 	return it.i > 1
 }
 
-// LengthUpperBound returns the maximum number of elemnt this stacks may contain.
+// LengthUpperBound returns the maximum number of elements this stacks may contain.
 // The actual number may be lower because of elided frames. As such, the returned value
 // cannot be used to iterate over the frames but may be used to reserve capacity.
 func (it *ReverseFrameIterator) LengthUpperBound() int {

internal/traceparser/parser_test.go

@@ -126,6 +126,89 @@ created by time.goFunc
 func TestFrames(t *testing.T) {
 	var require = require.New(t)
 
+	var output = ""
+	var traces = Parse(tracetext)
+	for i := 0; i < traces.Length(); i++ {
+		var trace = traces.Item(i)
+		var framesIter = trace.Frames()
+		output += fmt.Sprintf("Trace %d: goroutine %d with at most %d frames\n", i, trace.GoID(), framesIter.LengthUpperBound())
+
+		for framesIter.HasNext() {
+			var frame = framesIter.Next()
+			output += fmt.Sprintf("  Func = %s\n", frame.Func())
+			file, line := frame.File()
+			output += fmt.Sprintf("  File = %s\n", file)
+			output += fmt.Sprintf("  Line = %d\n", line)
+		}
+	}
+
+	var expected = strings.Split(strings.TrimLeft(`
+Trace 0: goroutine 18 with at most 2 frames
+  Func = testing.(*M).startAlarm.func1
+  File = C:/Users/name/scoop/apps/go/current/src/testing/testing.go
+  Line = 2241
+  Func = time.goFunc
+  File = C:/Users/name/scoop/apps/go/current/src/time/sleep.go
+  Line = 176
+Trace 1: goroutine 1 with at most 6 frames
+  Func = testing.(*T).Run
+  File = C:/Users/name/scoop/apps/go/current/src/testing/testing.go
+  Line = 1630
+  Func = testing.runTests.func1
+  File = C:/Users/name/scoop/apps/go/current/src/testing/testing.go
+  Line = 2036
+  Func = testing.tRunner
+  File = C:/Users/name/scoop/apps/go/current/src/testing/testing.go
+  Line = 1576
+  Func = testing.runTests
+  File = C:/Users/name/scoop/apps/go/current/src/testing/testing.go
+  Line = 2034
+  Func = testing.(*M).Run
+  File = C:/Users/name/scoop/apps/go/current/src/testing/testing.go
+  Line = 1906
+  Func = main.main
+  File = _testmain.go
+  Line = 465
+Trace 2: goroutine 6 with at most 4 frames
+  Func = github.com/getsentry/sentry-go.startProfiling.func3
+  File = c:/dev/sentry-go/profiler.go
+  Line = 46
+  Func = github.com/getsentry/sentry-go.TestStart
+  File = c:/dev/sentry-go/profiler_test.go
+  Line = 13
+  Func = testing.tRunner
+  File = C:/Users/name/scoop/apps/go/current/src/testing/testing.go
+  Line = 1576
+  Func = testing.(*T).Run
+  File = C:/Users/name/scoop/apps/go/current/src/testing/testing.go
+  Line = 1629
+Trace 3: goroutine 7 with at most 4 frames
+  Func = runtime.Stack
+  File = C:/Users/name/scoop/apps/go/current/src/runtime/mprof.go
+  Line = 1193
+  Func = github.com/getsentry/sentry-go.(*profileRecorder).Collect
+  File = c:/dev/sentry-go/profiler.go
+  Line = 73
+  Func = github.com/getsentry/sentry-go.startProfiling.func2
+  File = c:/dev/sentry-go/profiler.go
+  Line = 38
+  Func = github.com/getsentry/sentry-go.startProfiling
+  File = c:/dev/sentry-go/profiler.go
+  Line = 31
+Trace 4: goroutine 19 with at most 2 frames
+  Func = github.com/getsentry/sentry-go.startProfiling.func1
+  File = c:/dev/sentry-go/profiler.go
+  Line = 29
+  Func = time.goFunc
+  File = C:/Users/name/scoop/apps/go/current/src/time/sleep.go
+  Line = 176
+`, "\n"), "\n")
+	require.Equal(expected, strings.Split(output, "\n"))
+}
+
+func TestFramesReversed(t *testing.T) {
+	var require = require.New(t)
+
 	var output = ""
 	var traces = Parse(tracetext)
 	for i := 0; i < traces.Length(); i++ {
@@ -266,6 +349,42 @@ func BenchmarkFullParse(b *testing.B) {
 	}
 }
 
+func BenchmarkFramesIterator(b *testing.B) {
+	b.ReportAllocs()
+	var traces = Parse(tracetext)
+	b.ResetTimer()
+	for i := 0; i < b.N; i++ {
+		for i := traces.Length() - 1; i >= 0; i-- {
+			var trace = traces.Item(i)
+			var iter = trace.Frames()
+			_ = iter.LengthUpperBound()
+			for iter.HasNext() {
+				var frame = iter.Next()
+				_ = frame.Func()
+				_, _ = frame.File()
+			}
+		}
+	}
+}
+
+func BenchmarkFramesReversedIterator(b *testing.B) {
+	b.ReportAllocs()
+	var traces = Parse(tracetext)
+	b.ResetTimer()
+	for i := 0; i < b.N; i++ {
+		for i := traces.Length() - 1; i >= 0; i-- {
+			var trace = traces.Item(i)
+			var iter = trace.FramesReversed()
+			_ = iter.LengthUpperBound()
+			for iter.HasNext() {
+				var frame = iter.Next()
+				_ = frame.Func()
+				_, _ = frame.File()
+			}
+		}
+	}
+}
+
 func BenchmarkSplitOnly(b *testing.B) {
 	b.SetBytes(int64(len(tracetext)))
 	b.ReportAllocs()

profiler.go

@@ -18,10 +18,11 @@ func startProfiling(startTime time.Time) (stopFunc func() *profilerResult) {
 	resultChannel := make(chan *profilerResult, 2)
 	stopSignal := make(chan struct{}, 2)
 
-	go profilerGoroutine(startTime, resultChannel, stopSignal)
-
+	// Note: must come before starting the profiler to be correct
 	var goID = getCurrentGoID()
 
+	go profilerGoroutine(startTime, resultChannel, stopSignal)
+
 	return func() *profilerResult {
 		stopSignal <- struct{}{}
 		var result = <-resultChannel
@@ -220,7 +221,7 @@ func (p *profileRecorder) addStackTrace(capturedStack traceparser.Trace) int {
 
 	stackIndex, exists := p.stackIndexes[string(key)]
 	if !exists {
-		iter := capturedStack.FramesReversed()
+		iter := capturedStack.Frames()
 		stack := make(profileStack, 0, iter.LengthUpperBound())
 		for iter.HasNext() {
 			var frame = iter.Next()

profiler_test.go

@@ -1,9 +1,11 @@
 package sentry
 
 import (
+	"fmt"
 	"os"
 	"runtime"
 	"strconv"
+	"strings"
 	"sync/atomic"
 	"testing"
 	"time"
@@ -40,19 +42,24 @@ func restoreProfilerTicker() {
 func TestProfilerCollection(t *testing.T) {
 	if !isCI() {
 		t.Run("RealTicker", func(t *testing.T) {
+			var require = require.New(t)
+			var goID = getCurrentGoID()
+
 			start := time.Now()
 			stopFn := startProfiling(start)
 			doWorkFor(35 * time.Millisecond)
 			result := stopFn()
 			elapsed := time.Since(start)
-			require.NotNil(t, result)
-			require.Greater(t, result.callerGoID, uint64(0))
+			require.NotNil(result)
+			require.Greater(result.callerGoID, uint64(0))
+			require.Equal(goID, result.callerGoID)
 			validateProfile(t, result.trace, elapsed)
 		})
 	}
 
 	t.Run("CustomTicker", func(t *testing.T) {
 		var require = require.New(t)
+		var goID = getCurrentGoID()
 
 		ticker := setupProfilerTestTicker()
 		defer restoreProfilerTicker()
@@ -64,10 +71,48 @@ func TestProfilerCollection(t *testing.T) {
 		elapsed := time.Since(start)
 		require.NotNil(result)
 		require.Greater(result.callerGoID, uint64(0))
+		require.Equal(goID, result.callerGoID)
 		validateProfile(t, result.trace, elapsed)
 	})
 }
 
+// Check the order of frames for a known stack trace (this Goroutine's one).
+func TestProfilerStackTrace(t *testing.T) {
+	var require = require.New(t)
+
+	ticker := setupProfilerTestTicker()
+	defer restoreProfilerTicker()
+
+	stopFn := startProfiling(time.Now())
+	ticker.Tick()
+	result := stopFn()
+	require.NotNil(result)
+
+	var actual = ""
+	for _, sample := range result.trace.Samples {
+		if sample.ThreadID == result.callerGoID {
+			t.Logf("Found a sample for the calling goroutine ID: %d", result.callerGoID)
+			var stack = result.trace.Stacks[sample.StackID]
+			for _, frameIndex := range stack {
+				var frame = result.trace.Frames[frameIndex]
+				actual += fmt.Sprintf("%s %s\n", frame.Module, frame.Function)
+			}
+			break
+		}
+	}
+	require.NotZero(len(actual))
+	actual = actual[:len(actual)-1] // remove trailing newline
+	t.Log(actual)
+
+	var expected = []string{
+		"time Sleep",
+		"github.com/getsentry/sentry-go (*profilerTestTicker).Tick",
+		"github.com/getsentry/sentry-go TestProfilerStackTrace",
+		"testing tRunner",
+		"testing (*T).Run",
+	}
+	require.Equal(expected, strings.Split(actual, "\n"))
+}
 func TestProfilerCollectsOnStart(t *testing.T) {
 	start := time.Now()
 	result := startProfiling(start)()