Skip to content

Commit

Permalink
fix frames order in profiler stacktrace
Browse files Browse the repository at this point in the history
  • Loading branch information
vaind committed Jun 4, 2023
1 parent 54d52ac commit a7e1a2f
Show file tree
Hide file tree
Showing 5 changed files with 222 additions and 13 deletions.
12 changes: 7 additions & 5 deletions internal/traceparser/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
```
48 changes: 45 additions & 3 deletions internal/traceparser/parser.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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 {
Expand All @@ -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 {
Expand Down
119 changes: 119 additions & 0 deletions internal/traceparser/parser_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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++ {
Expand Down Expand Up @@ -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()
Expand Down
7 changes: 4 additions & 3 deletions profiler.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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()
Expand Down
49 changes: 47 additions & 2 deletions profiler_test.go
Original file line number Diff line number Diff line change
@@ -1,9 +1,11 @@
package sentry

import (
"fmt"
"os"
"runtime"
"strconv"
"strings"
"sync/atomic"
"testing"
"time"
Expand Down Expand Up @@ -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()
Expand All @@ -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)()
Expand Down

0 comments on commit a7e1a2f

Please sign in to comment.