diff --git a/CHANGELOG.md b/CHANGELOG.md index ee99ccaf9..00fb6cd83 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,6 +1,10 @@ # Changelog -## Unreleased +## Unrelesed + +### Features + +- Initial alpha support for profiling [#626](https://github.com/getsentry/sentry-go/pull/626) ### Bug fixes diff --git a/_examples/profiling/main.go b/_examples/profiling/main.go new file mode 100644 index 000000000..c1dc69e1a --- /dev/null +++ b/_examples/profiling/main.go @@ -0,0 +1,80 @@ +// go run main.go +// +// To actually report events to Sentry, set the DSN either by editing the +// appropriate line below or setting the environment variable SENTRY_DSN to +// match the DSN of your Sentry project. +package main + +import ( + "context" + "fmt" + "log" + "runtime" + "sync" + "time" + + "github.com/getsentry/sentry-go" +) + +func main() { + err := sentry.Init(sentry.ClientOptions{ + // Either set your DSN here or set the SENTRY_DSN environment variable. + Dsn: "", + // Enable printing of SDK debug messages. + // Useful when getting started or trying to figure something out. + Debug: true, + EnableTracing: true, + TracesSampleRate: 1.0, + ProfilesSampleRate: 1.0, + }) + + // Flush buffered events before the program terminates. + // Set the timeout to the maximum duration the program can afford to wait. + defer sentry.Flush(2 * time.Second) + + if err != nil { + log.Fatalf("sentry.Init: %s", err) + } + ctx := context.Background() + tx := sentry.StartTransaction(ctx, "top") + + fmt.Println("Finding prime numbers") + var wg sync.WaitGroup + wg.Add(10) + for i := 0; i < 10; i++ { + go func(num int) { + span := tx.StartChild(fmt.Sprintf("Goroutine %d", num)) + defer span.Finish() + for i := 0; i < num; i++ { + _ = findPrimeNumber(50000) + runtime.Gosched() // we need to manually yield this busy loop + } + fmt.Printf("routine %d done\n", num) + wg.Done() + }(i) + } + wg.Wait() + fmt.Println("all") + tx.Finish() +} + +func findPrimeNumber(n int) int { + count := 0 + a := 2 + for count < n { + b := 2 + prime := true // to check if found a prime + for b*b <= a { + if a%b == 0 { + prime = false + break + } + b++ + } + if prime { + count++ + } + a++ + } + return a - 1 +} diff --git a/client.go b/client.go index c20159568..e4a28d45d 100644 --- a/client.go +++ b/client.go @@ -130,6 +130,9 @@ type ClientOptions struct { TracesSampleRate float64 // Used to customize the sampling of traces, overrides TracesSampleRate. TracesSampler TracesSampler + // The sample rate for profiling traces in the range [0.0, 1.0]. + // This is relative to TracesSampleRate - it is a ratio of profiled traces out of all sampled traces. + ProfilesSampleRate float64 // List of regexp strings that will be used to match against event's message // and if applicable, caught errors type and value. // If the match is found, then a whole event will be dropped. @@ -371,6 +374,7 @@ func (client *Client) AddEventProcessor(processor EventProcessor) { } // Options return ClientOptions for the current Client. +// TODO don't access this internally to avoid creating a copy each time. func (client Client) Options() ClientOptions { return client.options } @@ -573,6 +577,7 @@ func (client *Client) processEvent(event *Event, hint *EventHint, scope EventMod func (client *Client) prepareEvent(event *Event, hint *EventHint, scope EventModifier) *Event { if event.EventID == "" { + // TODO set EventID when the event is created, same as in other SDKs. It's necessary for profileTransaction.ID. event.EventID = EventID(uuid()) } @@ -640,6 +645,10 @@ func (client *Client) prepareEvent(event *Event, hint *EventHint, scope EventMod } } + if event.sdkMetaData.transactionProfile != nil { + event.sdkMetaData.transactionProfile.UpdateFromEvent(event) + } + return event } diff --git a/example_transportwithhooks_test.go b/example_transportwithhooks_test.go index c9828e12d..1318a3807 100644 --- a/example_transportwithhooks_test.go +++ b/example_transportwithhooks_test.go @@ -60,6 +60,4 @@ func Example_transportWithHooks() { defer sentry.Flush(2 * time.Second) sentry.CaptureMessage("test") - - // Output: } diff --git a/interfaces.go b/interfaces.go index 0be0d1005..0292308ea 100644 --- a/interfaces.go +++ b/interfaces.go @@ -20,6 +20,8 @@ const transactionType = "transaction" // eventType is the type of an error event. const eventType = "event" +const profileType = "profile" + // Level marks the severity of the event. type Level string @@ -237,7 +239,8 @@ type Exception struct { // SDKMetaData is a struct to stash data which is needed at some point in the SDK's event processing pipeline // but which shouldn't get send to Sentry. type SDKMetaData struct { - dsc DynamicSamplingContext + dsc DynamicSamplingContext + transactionProfile *profileInfo } // Contains information about how the name of the transaction was determined. diff --git a/internal/traceparser/README.md b/internal/traceparser/README.md new file mode 100644 index 000000000..78964587b --- /dev/null +++ b/internal/traceparser/README.md @@ -0,0 +1,15 @@ +## Benchmark results + +``` +goos: windows +goarch: amd64 +pkg: github.com/getsentry/sentry-go/internal/trace +cpu: 12th Gen Intel(R) Core(TM) i7-12700K +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 +``` diff --git a/internal/traceparser/parser.go b/internal/traceparser/parser.go new file mode 100644 index 000000000..f42f28ccf --- /dev/null +++ b/internal/traceparser/parser.go @@ -0,0 +1,210 @@ +package traceparser + +import ( + "bytes" + "strconv" +) + +var blockSeparator = []byte("\n\n") +var lineSeparator = []byte("\n") + +// Parses multi-stacktrace text dump produced by runtime.Stack([]byte, all=true). +// The parser prioritizes performance but requires the input to be well-formed in order to return correct data. +// See https://github.com/golang/go/blob/go1.20.4/src/runtime/mprof.go#L1191 +func Parse(data []byte) TraceCollection { + var it = TraceCollection{} + if len(data) > 0 { + it.blocks = bytes.Split(data, blockSeparator) + } + return it +} + +type TraceCollection struct { + blocks [][]byte +} + +func (it TraceCollection) Length() int { + return len(it.blocks) +} + +// Returns the stacktrace item at the given index. +func (it *TraceCollection) Item(i int) Trace { + // The first item may have a leading data separator and the last one may have a trailing one. + // Note: Trim() doesn't make a copy for single-character cutset under 0x80. It will just slice the original. + var data []byte + switch { + case i == 0: + data = bytes.TrimLeft(it.blocks[i], "\n") + case i == len(it.blocks)-1: + data = bytes.TrimRight(it.blocks[i], "\n") + default: + data = it.blocks[i] + } + + var splitAt = bytes.IndexByte(data, '\n') + if splitAt < 0 { + return Trace{header: data} + } + + return Trace{ + header: data[:splitAt], + data: data[splitAt+1:], + } +} + +// Trace represents a single stacktrace block, identified by a Goroutine ID and a sequence of Frames. +type Trace struct { + header []byte + data []byte +} + +var goroutinePrefix = []byte("goroutine ") + +// GoID parses the Goroutine ID from the header. +func (t *Trace) GoID() (id uint64) { + if bytes.HasPrefix(t.header, goroutinePrefix) { + var line = t.header[len(goroutinePrefix):] + var splitAt = bytes.IndexByte(line, ' ') + if splitAt >= 0 { + id, _ = strconv.ParseUint(string(line[:splitAt]), 10, 64) + } + } + return id +} + +// UniqueIdentifier can be used as a map key to identify the trace. +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 + i int +} + +// Next returns the next frame, or nil if there are none. +func (it *ReverseFrameIterator) Next() Frame { + var line2 = it.popLine() + return Frame{it.popLine(), line2} +} + +func (it *ReverseFrameIterator) popLine() []byte { + it.i-- + switch { + case it.i < 0: + return nil + case string(it.lines[it.i]) == framesElided: + return it.popLine() + default: + return it.lines[it.i] + } +} + +// HasNext return true if there are values to be read. +func (it *ReverseFrameIterator) HasNext() bool { + return it.i > 1 +} + +// 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 { + return len(it.lines) / 2 +} + +type Frame struct { + line1 []byte + line2 []byte +} + +// UniqueIdentifier can be used as a map key to identify the frame. +func (f *Frame) UniqueIdentifier() []byte { + // line2 contains file path, line number and program-counter offset from the beginning of a function + // e.g. C:/Users/name/scoop/apps/go/current/src/testing/testing.go:1906 +0x63a + return f.line2 +} + +var createdByPrefix = []byte("created by ") + +func (f *Frame) Func() []byte { + if bytes.HasPrefix(f.line1, createdByPrefix) { + return f.line1[len(createdByPrefix):] + } + + var end = bytes.LastIndexByte(f.line1, '(') + if end >= 0 { + return f.line1[:end] + } + + return f.line1 +} + +func (f *Frame) File() (path []byte, lineNumber int) { + var line = f.line2 + if len(line) > 0 && line[0] == '\t' { + line = line[1:] + } + + var splitAt = bytes.IndexByte(line, ' ') + if splitAt >= 0 { + line = line[:splitAt] + } + + splitAt = bytes.LastIndexByte(line, ':') + if splitAt < 0 { + return line, 0 + } + + lineNumber, _ = strconv.Atoi(string(line[splitAt+1:])) + return line[:splitAt], lineNumber +} diff --git a/internal/traceparser/parser_test.go b/internal/traceparser/parser_test.go new file mode 100644 index 000000000..d43cda69f --- /dev/null +++ b/internal/traceparser/parser_test.go @@ -0,0 +1,400 @@ +package traceparser + +import ( + "bytes" + "fmt" + "strings" + "testing" + + "github.com/stretchr/testify/require" +) + +func TestParseEmpty(t *testing.T) { + var require = require.New(t) + + require.Zero(Parse(nil).Length()) + require.Zero(Parse([]byte{}).Length()) +} + +var tracetext = []byte(` +goroutine 18 [running]: +testing.(*M).startAlarm.func1() + C:/Users/name/scoop/apps/go/current/src/testing/testing.go:2241 +0x3c5 +created by time.goFunc + C:/Users/name/scoop/apps/go/current/src/time/sleep.go:176 +0x32 + +goroutine 1 [chan receive]: +testing.(*T).Run(0xc00006f6c0, {0x672288?, 0x180fd3?}, 0x6b5f98) + C:/Users/name/scoop/apps/go/current/src/testing/testing.go:1630 +0x405 +testing.runTests.func1(0xa36e00?) + C:/Users/name/scoop/apps/go/current/src/testing/testing.go:2036 +0x45 +testing.tRunner(0xc00006f6c0, 0xc0000b3c88) + C:/Users/name/scoop/apps/go/current/src/testing/testing.go:1576 +0x10b +testing.runTests(0xc000035ea0?, {0xa31240, 0xcd, 0xcd}, {0xc0000befa0?, 0x102df4ae6c418?, 0xa363a0?}) + C:/Users/name/scoop/apps/go/current/src/testing/testing.go:2034 +0x489 +testing.(*M).Run(0xc000035ea0) + C:/Users/name/scoop/apps/go/current/src/testing/testing.go:1906 +0x63a +main.main() + _testmain.go:465 +0x1aa + +goroutine 6 [chan send]: +github.com/getsentry/sentry-go.startProfiling.func3() + c:/dev/sentry-go/profiler.go:46 +0x2b +github.com/getsentry/sentry-go.TestStart(0x0?) + c:/dev/sentry-go/profiler_test.go:13 +0x3e +testing.tRunner(0xc00006f860, 0x6b5f98) + C:/Users/name/scoop/apps/go/current/src/testing/testing.go:1576 +0x10b +created by testing.(*T).Run + C:/Users/name/scoop/apps/go/current/src/testing/testing.go:1629 +0x3ea + +goroutine 7 [stopping the world]: +runtime.Stack({0xc000200000, 0x100000, 0x100000}, 0x1) + C:/Users/name/scoop/apps/go/current/src/runtime/mprof.go:1193 +0x4d +github.com/getsentry/sentry-go.(*profileRecorder).Collect(0xc00008a820) + c:/dev/sentry-go/profiler.go:73 +0x3b +github.com/getsentry/sentry-go.startProfiling.func2() + c:/dev/sentry-go/profiler.go:38 +0xb1 +created by github.com/getsentry/sentry-go.startProfiling + c:/dev/sentry-go/profiler.go:31 +0x36c + +goroutine 19 [chan send]: +github.com/getsentry/sentry-go.startProfiling.func1() + c:/dev/sentry-go/profiler.go:29 +0x25 +...additional frames elided... +created by time.goFunc + C:/Users/name/scoop/apps/go/current/src/time/sleep.go:176 +0x32 +`) + +func TestParse(t *testing.T) { + var require = require.New(t) + + var traces = Parse(tracetext) + var i = 0 + var checkTrace = func(id int, stack string) { + var trace = traces.Item(i) + require.NotNil(trace) + require.Equal(uint64(id), trace.GoID()) + require.Equal(stack, string(trace.UniqueIdentifier())) + i++ + } + + checkTrace(18, `testing.(*M).startAlarm.func1() + C:/Users/name/scoop/apps/go/current/src/testing/testing.go:2241 +0x3c5 +created by time.goFunc + C:/Users/name/scoop/apps/go/current/src/time/sleep.go:176 +0x32`) + + checkTrace(1, `testing.(*T).Run(0xc00006f6c0, {0x672288?, 0x180fd3?}, 0x6b5f98) + C:/Users/name/scoop/apps/go/current/src/testing/testing.go:1630 +0x405 +testing.runTests.func1(0xa36e00?) + C:/Users/name/scoop/apps/go/current/src/testing/testing.go:2036 +0x45 +testing.tRunner(0xc00006f6c0, 0xc0000b3c88) + C:/Users/name/scoop/apps/go/current/src/testing/testing.go:1576 +0x10b +testing.runTests(0xc000035ea0?, {0xa31240, 0xcd, 0xcd}, {0xc0000befa0?, 0x102df4ae6c418?, 0xa363a0?}) + C:/Users/name/scoop/apps/go/current/src/testing/testing.go:2034 +0x489 +testing.(*M).Run(0xc000035ea0) + C:/Users/name/scoop/apps/go/current/src/testing/testing.go:1906 +0x63a +main.main() + _testmain.go:465 +0x1aa`) + + checkTrace(6, `github.com/getsentry/sentry-go.startProfiling.func3() + c:/dev/sentry-go/profiler.go:46 +0x2b +github.com/getsentry/sentry-go.TestStart(0x0?) + c:/dev/sentry-go/profiler_test.go:13 +0x3e +testing.tRunner(0xc00006f860, 0x6b5f98) + C:/Users/name/scoop/apps/go/current/src/testing/testing.go:1576 +0x10b +created by testing.(*T).Run + C:/Users/name/scoop/apps/go/current/src/testing/testing.go:1629 +0x3ea`) + + checkTrace(7, `runtime.Stack({0xc000200000, 0x100000, 0x100000}, 0x1) + C:/Users/name/scoop/apps/go/current/src/runtime/mprof.go:1193 +0x4d +github.com/getsentry/sentry-go.(*profileRecorder).Collect(0xc00008a820) + c:/dev/sentry-go/profiler.go:73 +0x3b +github.com/getsentry/sentry-go.startProfiling.func2() + c:/dev/sentry-go/profiler.go:38 +0xb1 +created by github.com/getsentry/sentry-go.startProfiling + c:/dev/sentry-go/profiler.go:31 +0x36c`) + + checkTrace(19, `github.com/getsentry/sentry-go.startProfiling.func1() + c:/dev/sentry-go/profiler.go:29 +0x25 +...additional frames elided... +created by time.goFunc + C:/Users/name/scoop/apps/go/current/src/time/sleep.go:176 +0x32`) + + require.Equal(traces.Length(), i) +} + +//nolint:dupl +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")) +} + +//nolint:dupl +func TestFramesReversed(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.FramesReversed() + 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 = time.goFunc + File = C:/Users/name/scoop/apps/go/current/src/time/sleep.go + Line = 176 + Func = testing.(*M).startAlarm.func1 + File = C:/Users/name/scoop/apps/go/current/src/testing/testing.go + Line = 2241 +Trace 1: goroutine 1 with at most 6 frames + Func = main.main + File = _testmain.go + Line = 465 + Func = testing.(*M).Run + File = C:/Users/name/scoop/apps/go/current/src/testing/testing.go + Line = 1906 + Func = testing.runTests + File = C:/Users/name/scoop/apps/go/current/src/testing/testing.go + Line = 2034 + Func = testing.tRunner + File = C:/Users/name/scoop/apps/go/current/src/testing/testing.go + Line = 1576 + Func = testing.runTests.func1 + File = C:/Users/name/scoop/apps/go/current/src/testing/testing.go + Line = 2036 + Func = testing.(*T).Run + File = C:/Users/name/scoop/apps/go/current/src/testing/testing.go + Line = 1630 +Trace 2: goroutine 6 with at most 4 frames + Func = testing.(*T).Run + File = C:/Users/name/scoop/apps/go/current/src/testing/testing.go + Line = 1629 + Func = testing.tRunner + File = C:/Users/name/scoop/apps/go/current/src/testing/testing.go + Line = 1576 + Func = github.com/getsentry/sentry-go.TestStart + File = c:/dev/sentry-go/profiler_test.go + Line = 13 + Func = github.com/getsentry/sentry-go.startProfiling.func3 + File = c:/dev/sentry-go/profiler.go + Line = 46 +Trace 3: goroutine 7 with at most 4 frames + Func = github.com/getsentry/sentry-go.startProfiling + File = c:/dev/sentry-go/profiler.go + Line = 31 + Func = github.com/getsentry/sentry-go.startProfiling.func2 + File = c:/dev/sentry-go/profiler.go + Line = 38 + Func = github.com/getsentry/sentry-go.(*profileRecorder).Collect + File = c:/dev/sentry-go/profiler.go + Line = 73 + Func = runtime.Stack + File = C:/Users/name/scoop/apps/go/current/src/runtime/mprof.go + Line = 1193 +Trace 4: goroutine 19 with at most 2 frames + Func = time.goFunc + File = C:/Users/name/scoop/apps/go/current/src/time/sleep.go + Line = 176 + Func = github.com/getsentry/sentry-go.startProfiling.func1 + File = c:/dev/sentry-go/profiler.go + Line = 29 +`, "\n"), "\n") + require.Equal(expected, strings.Split(output, "\n")) +} + +func BenchmarkEqualBytes(b *testing.B) { + lines := bytes.Split(tracetext, lineSeparator) + var framesElided = []byte(framesElided) + b.ResetTimer() + for i := 0; i < b.N; i++ { + for n := 0; n < len(lines); n++ { + if bytes.Equal(lines[n], framesElided) { + break + } + } + } +} + +// Benchmark results: this is the best performing implementation. +func BenchmarkStringEqual(b *testing.B) { + lines := bytes.Split(tracetext, lineSeparator) + b.ResetTimer() + for i := 0; i < b.N; i++ { + for n := 0; n < len(lines); n++ { + if string(lines[n]) == framesElided { + break + } + } + } +} + +func BenchmarkEqualPrefix(b *testing.B) { + lines := bytes.Split(tracetext, lineSeparator) + var framesElided = []byte(framesElided) + var ln = len(framesElided) + b.ResetTimer() + for i := 0; i < b.N; i++ { + for n := 0; n < len(lines); n++ { + if len(lines[n]) == ln && bytes.HasPrefix(lines[n], framesElided) { + break + } + } + } +} + +func BenchmarkFullParse(b *testing.B) { + b.SetBytes(int64(len(tracetext))) + b.ReportAllocs() + for i := 0; i < b.N; i++ { + var traces = Parse(tracetext) + for i := traces.Length() - 1; i >= 0; i-- { + var trace = traces.Item(i) + _ = trace.GoID() + + var iter = trace.FramesReversed() + _ = iter.LengthUpperBound() + for iter.HasNext() { + var frame = iter.Next() + _ = frame.Func() + _, _ = frame.File() + } + } + } +} + +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() + for i := 0; i < b.N; i++ { + var traces = Parse(tracetext) + for i := traces.Length() - 1; i >= 0; i-- { + var trace = traces.Item(i) + _ = trace.UniqueIdentifier() + } + } +} diff --git a/profile_sample.go b/profile_sample.go new file mode 100644 index 000000000..a820fddbb --- /dev/null +++ b/profile_sample.go @@ -0,0 +1,74 @@ +package sentry + +// Based on https://github.com/getsentry/vroom/blob/d11c26063e802d66b9a592c4010261746ca3dfa4/internal/sample/sample.go + +import ( + "time" +) + +type ( + profileDevice struct { + Architecture string `json:"architecture"` + Classification string `json:"classification"` + Locale string `json:"locale"` + Manufacturer string `json:"manufacturer"` + Model string `json:"model"` + } + + profileOS struct { + BuildNumber string `json:"build_number"` + Name string `json:"name"` + Version string `json:"version"` + } + + profileRuntime struct { + Name string `json:"name"` + Version string `json:"version"` + } + + profileSample struct { + ElapsedSinceStartNS uint64 `json:"elapsed_since_start_ns"` + QueueAddress string `json:"queue_address,omitempty"` + StackID int `json:"stack_id"` + ThreadID uint64 `json:"thread_id"` + } + + profileThreadMetadata struct { + Name string `json:"name,omitempty"` + Priority int `json:"priority,omitempty"` + } + + profileStack []int + + profileTrace struct { + Frames []*Frame `json:"frames"` + Samples []*profileSample `json:"samples"` + Stacks []profileStack `json:"stacks"` + ThreadMetadata map[string]profileThreadMetadata `json:"thread_metadata"` + } + + profileInfo struct { + DebugMeta *DebugMeta `json:"debug_meta,omitempty"` + Device profileDevice `json:"device"` + Environment string `json:"environment,omitempty"` + EventID string `json:"event_id"` + OS profileOS `json:"os"` + Platform string `json:"platform"` + Release string `json:"release"` + Dist string `json:"dist"` + Runtime profileRuntime `json:"runtime"` + Timestamp time.Time `json:"timestamp"` + Trace *profileTrace `json:"profile"` + Transaction profileTransaction `json:"transaction"` + Version string `json:"version"` + } + + // see https://github.com/getsentry/vroom/blob/a91e39416723ec44fc54010257020eeaf9a77cbd/internal/transaction/transaction.go + profileTransaction struct { + ActiveThreadID uint64 `json:"active_thread_id"` + DurationNS uint64 `json:"duration_ns,omitempty"` + ID EventID `json:"id"` + Name string `json:"name"` + TraceID string `json:"trace_id"` + } +) diff --git a/profiler.go b/profiler.go new file mode 100644 index 000000000..6c77b4df4 --- /dev/null +++ b/profiler.go @@ -0,0 +1,277 @@ +package sentry + +import ( + "runtime" + "strconv" + "sync/atomic" + "time" + + "github.com/getsentry/sentry-go/internal/traceparser" +) + +// Start collecting profile data and returns a function that stops profiling, producing a Trace. +// The returned stop function May return nil or an incomplete trace in case of a panic. +func startProfiling(startTime time.Time) (stopFunc func() *profilerResult) { + onProfilerStart() + + // buffered channels to handle the recover() case without blocking + resultChannel := make(chan *profilerResult, 2) + stopSignal := make(chan struct{}, 2) + + go profilerGoroutine(startTime, resultChannel, stopSignal) + + var goID = getCurrentGoID() + + return func() *profilerResult { + stopSignal <- struct{}{} + var result = <-resultChannel + if result != nil { + result.callerGoID = goID + } + return result + } +} + +// This allows us to test whether panic during profiling are handled correctly and don't block execution. +// If the number is lower than 0, profilerGoroutine() will panic immedately. +// If the number is higher than 0, profiler.onTick() will panic after the given number of samples collected. +var testProfilerPanic int64 + +func profilerGoroutine(startTime time.Time, result chan<- *profilerResult, stopSignal chan struct{}) { + // We shouldn't panic but let's be super safe. + defer func() { + _ = recover() + + // Make sure we don't block the caller of stopFn() even if we panic. + result <- nil + + atomic.StoreInt64(&testProfilerPanic, 0) + }() + + // Stop after 30 seconds unless stopped manually. + timeout := time.AfterFunc(30*time.Second, func() { stopSignal <- struct{}{} }) + defer timeout.Stop() + + var localTestProfilerPanic = atomic.LoadInt64(&testProfilerPanic) + if localTestProfilerPanic < 0 { + panic("This is an expected panic in profilerGoroutine() during tests") + } + + profiler := newProfiler(startTime) + profiler.testProfilerPanic = localTestProfilerPanic + + // Collect the first sample immediately. + profiler.onTick() + + // Periodically collect stacks, starting after profilerSamplingRate has passed. + collectTicker := profilerTickerFactory(profilerSamplingRate) + defer collectTicker.Stop() + var tickerChannel = collectTicker.Channel() + + defer func() { + result <- &profilerResult{0, profiler.trace} + }() + + for { + select { + case <-tickerChannel: + profiler.onTick() + case <-stopSignal: + return + } + } +} + +type profilerResult struct { + callerGoID uint64 + trace *profileTrace +} + +func getCurrentGoID() uint64 { + // We shouldn't panic but let's be super safe. + defer func() { + _ = recover() + }() + + // Buffer to read the stack trace into. We should be good with a small buffer because we only need the first line. + var stacksBuffer = make([]byte, 100) + var n = runtime.Stack(stacksBuffer, false) + if n > 0 { + var traces = traceparser.Parse(stacksBuffer[0:n]) + if traces.Length() > 0 { + var trace = traces.Item(0) + return trace.GoID() + } + } + return 0 +} + +func newProfiler(startTime time.Time) *profileRecorder { + // Pre-allocate the profile trace for the currently active number of routines & 100 ms worth of samples. + // Other coefficients are just guesses of what might be a good starting point to avoid allocs on short runs. + numRoutines := runtime.NumGoroutine() + trace := &profileTrace{ + Frames: make([]*Frame, 0, 32), + Samples: make([]*profileSample, 0, numRoutines*10), // 100 ms @ 101 Hz + Stacks: make([]profileStack, 0, 8), + ThreadMetadata: make(map[string]profileThreadMetadata, numRoutines), + } + + return &profileRecorder{ + startTime: startTime, + trace: trace, + stackIndexes: make(map[string]int, cap(trace.Stacks)), + frameIndexes: make(map[string]int, cap(trace.Frames)), + // A buffer of 2 KiB per stack looks like a good starting point (empirically determined). + stacksBuffer: make([]byte, numRoutines*2048), + } +} + +const profilerSamplingRate = time.Second / 101 // 101 Hz; not 100 Hz because of the lockstep sampling (https://stackoverflow.com/a/45471031/1181370) +const stackBufferMaxGrowth = 512 * 1024 +const stackBufferLimit = 10 * 1024 * 1024 + +type profileRecorder struct { + startTime time.Time + trace *profileTrace + testProfilerPanic int64 + + // Buffer to read current stacks - will grow automatically up to stackBufferLimit. + stacksBuffer []byte + + // Map from runtime.StackRecord.Stack0 to an index trace.Stacks. + stackIndexes map[string]int + + // Map from runtime.Frame.PC to an index trace.Frames. + frameIndexes map[string]int +} + +func (p *profileRecorder) onTick() { + elapsedNs := time.Since(p.startTime).Nanoseconds() + + if p.testProfilerPanic > 0 && int64(len(p.trace.Samples)) > p.testProfilerPanic { + panic("This is an expected panic in Profiler.OnTick() during tests") + } + + records := p.collectRecords() + p.processRecords(uint64(elapsedNs), records) + + // Free up some memory if we don't need such a large buffer anymore. + if len(p.stacksBuffer) > len(records)*3 { + p.stacksBuffer = make([]byte, len(records)*3) + } +} + +func (p *profileRecorder) collectRecords() []byte { + for { + // Capture stacks for all existing goroutines. + // Note: runtime.GoroutineProfile() would be better but we can't use it at the moment because + // it doesn't give us `gid` for each routine, see https://github.com/golang/go/issues/59663 + n := runtime.Stack(p.stacksBuffer, true) + + // If we couldn't read everything, increase the buffer and try again. + if n >= len(p.stacksBuffer) && n < stackBufferLimit { + var newSize = n * 2 + if newSize > n+stackBufferMaxGrowth { + newSize = n + stackBufferMaxGrowth + } + if newSize > stackBufferLimit { + newSize = stackBufferLimit + } + p.stacksBuffer = make([]byte, newSize) + } else { + return p.stacksBuffer[0:n] + } + } +} + +func (p *profileRecorder) processRecords(elapsedNs uint64, stacksBuffer []byte) { + var traces = traceparser.Parse(stacksBuffer) + for i := traces.Length() - 1; i >= 0; i-- { + var stack = traces.Item(i) + threadIndex := p.addThread(stack.GoID()) + stackIndex := p.addStackTrace(stack) + if stackIndex < 0 { + return + } + + p.trace.Samples = append(p.trace.Samples, &profileSample{ + ElapsedSinceStartNS: elapsedNs, + StackID: stackIndex, + ThreadID: threadIndex, + }) + } +} + +func (p *profileRecorder) addThread(id uint64) uint64 { + index := strconv.FormatUint(id, 10) + if _, exists := p.trace.ThreadMetadata[index]; !exists { + p.trace.ThreadMetadata[index] = profileThreadMetadata{ + Name: "Goroutine " + index, + } + } + return id +} + +func (p *profileRecorder) addStackTrace(capturedStack traceparser.Trace) int { + // NOTE: Don't convert to string yet, it's expensive and compiler can avoid it when + // indexing into a map (only needs a copy when adding a new key to the map). + var key = capturedStack.UniqueIdentifier() + + stackIndex, exists := p.stackIndexes[string(key)] + if !exists { + iter := capturedStack.Frames() + stack := make(profileStack, 0, iter.LengthUpperBound()) + for iter.HasNext() { + var frame = iter.Next() + + if frameIndex := p.addFrame(frame); frameIndex >= 0 { + stack = append(stack, frameIndex) + } + } + stackIndex = len(p.trace.Stacks) + p.trace.Stacks = append(p.trace.Stacks, stack) + p.stackIndexes[string(key)] = stackIndex + } + + return stackIndex +} + +func (p *profileRecorder) addFrame(capturedFrame traceparser.Frame) int { + // NOTE: Don't convert to string yet, it's expensive and compiler can avoid it when + // indexing into a map (only needs a copy when adding a new key to the map). + var key = capturedFrame.UniqueIdentifier() + + frameIndex, exists := p.frameIndexes[string(key)] + if !exists { + module, function := splitQualifiedFunctionName(string(capturedFrame.Func())) + file, line := capturedFrame.File() + frame := newFrame(module, function, string(file), line) + frameIndex = len(p.trace.Frames) + p.trace.Frames = append(p.trace.Frames, &frame) + p.frameIndexes[string(key)] = frameIndex + } + return frameIndex +} + +// A Ticker holds a channel that delivers “ticks” of a clock at intervals. +type profilerTicker interface { + Stop() + Channel() <-chan time.Time +} + +type timeTicker struct { + *time.Ticker +} + +func (t *timeTicker) Channel() <-chan time.Time { + return t.C +} + +func profilerTickerFactoryDefault(d time.Duration) profilerTicker { + return &timeTicker{time.NewTicker(d)} +} + +// We allow overriding the ticker for tests. CI is terribly flaky +// because the time.Ticker doesn't guarantee regular ticks - they may come (a lot) later than the given interval. +var profilerTickerFactory = profilerTickerFactoryDefault diff --git a/profiler_other.go b/profiler_other.go new file mode 100644 index 000000000..fbb79b0c6 --- /dev/null +++ b/profiler_other.go @@ -0,0 +1,5 @@ +//go:build !windows + +package sentry + +func onProfilerStart() {} diff --git a/profiler_test.go b/profiler_test.go new file mode 100644 index 000000000..95d356121 --- /dev/null +++ b/profiler_test.go @@ -0,0 +1,440 @@ +package sentry + +import ( + "fmt" + "os" + "runtime" + "strconv" + "strings" + "sync/atomic" + "testing" + "time" + + "github.com/stretchr/testify/require" +) + +// Test ticker that ticks on demand instead of relying on go runtime timing. +type profilerTestTicker struct { + c chan time.Time +} + +func (t *profilerTestTicker) Channel() <-chan time.Time { + return t.c +} + +func (t *profilerTestTicker) Stop() {} + +func (t *profilerTestTicker) Tick() { + t.c <- time.Now() + time.Sleep(time.Millisecond) // Allow the goroutine to pick up the tick from the channel. +} + +func setupProfilerTestTicker() *profilerTestTicker { + ticker := &profilerTestTicker{c: make(chan time.Time, 1)} + profilerTickerFactory = func(d time.Duration) profilerTicker { return ticker } + return ticker +} + +func restoreProfilerTicker() { + profilerTickerFactory = profilerTickerFactoryDefault +} + +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(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() + + start := time.Now() + stopFn := startProfiling(start) + ticker.Tick() + result := stopFn() + 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 (i.e. this test case). +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) + + // Note: we can't check the exact stack trace because the profiler runs its own goroutine + // And this test goroutine may be interrupted at multiple points. + require.True(strings.HasSuffix(actual, ` +github.com/getsentry/sentry-go TestProfilerStackTrace +testing tRunner +testing (*T).Run`)) +} + +func TestProfilerCollectsOnStart(t *testing.T) { + start := time.Now() + result := startProfiling(start)() + require.NotNil(t, result) + validateProfile(t, result.trace, time.Since(start)) +} + +func TestProfilerPanicDuringStartup(t *testing.T) { + var require = require.New(t) + + atomic.StoreInt64(&testProfilerPanic, -1) + + stopFn := startProfiling(time.Now()) + // wait until the profiler has panicked + for i := 0; i < 100 && atomic.LoadInt64(&testProfilerPanic) != 0; i++ { + doWorkFor(10 * time.Millisecond) + } + result := stopFn() + + require.Zero(atomic.LoadInt64(&testProfilerPanic)) + require.Nil(result) +} + +func TestProfilerPanicOnTick(t *testing.T) { + var require = require.New(t) + + ticker := setupProfilerTestTicker() + defer restoreProfilerTicker() + + // Panic after the first sample is collected. + atomic.StoreInt64(&testProfilerPanic, 1) + + start := time.Now() + stopFn := startProfiling(start) + ticker.Tick() + result := stopFn() + elapsed := time.Since(start) + + require.Zero(atomic.LoadInt64(&testProfilerPanic)) + require.NotNil(result) + validateProfile(t, result.trace, elapsed) +} + +func TestProfilerPanicOnTickDirect(t *testing.T) { + var require = require.New(t) + + profiler := newProfiler(time.Now()) + profiler.testProfilerPanic = 1 + + // first tick won't panic + profiler.onTick() + var lenSamples = len(profiler.trace.Samples) + require.Greater(lenSamples, 0) + + // This is normally handled by the profiler goroutine and stops the profiler. + require.Panics(profiler.onTick) + require.Equal(lenSamples, len(profiler.trace.Samples)) + + profiler.testProfilerPanic = 0 + + profiler.onTick() + require.NotEmpty(profiler.trace.Samples) + require.Less(lenSamples, len(profiler.trace.Samples)) +} + +func doWorkFor(duration time.Duration) { + start := time.Now() + for time.Since(start) < duration { + _ = findPrimeNumber(1000) + runtime.Gosched() + } +} + +//nolint:unparam +func findPrimeNumber(n int) int { + count := 0 + a := 2 + for count < n { + b := 2 + prime := true // to check if found a prime + for b*b <= a { + if a%b == 0 { + prime = false + break + } + b++ + } + if prime { + count++ + } + a++ + } + return a - 1 +} + +func validateProfile(t *testing.T, trace *profileTrace, duration time.Duration) { + var require = require.New(t) + require.NotNil(trace) + require.NotEmpty(trace.Samples) + require.NotEmpty(trace.Stacks) + require.NotEmpty(trace.Frames) + require.NotEmpty(trace.ThreadMetadata) + + for _, sample := range trace.Samples { + require.GreaterOrEqual(sample.ElapsedSinceStartNS, uint64(0)) + require.GreaterOrEqual(uint64(duration.Nanoseconds()), sample.ElapsedSinceStartNS) + require.GreaterOrEqual(sample.StackID, 0) + require.Less(sample.StackID, len(trace.Stacks)) + require.Contains(trace.ThreadMetadata, strconv.Itoa(int(sample.ThreadID))) + } + + for _, thread := range trace.ThreadMetadata { + require.NotEmpty(thread.Name) + } + + for _, frame := range trace.Frames { + require.NotEmpty(frame.Function) + require.Greater(len(frame.AbsPath)+len(frame.Filename), 0) + require.Greater(frame.Lineno, 0) + } +} + +func TestProfilerSamplingRate(t *testing.T) { + if isCI() { + t.Skip("Skipping on CI because the machines are too overloaded to provide consistent ticker resolution.") + } + if testing.Short() { + t.Skip("Skipping in short mode.") + } + + var require = require.New(t) + + stopFn := startProfiling(time.Now()) + doWorkFor(500 * time.Millisecond) + result := stopFn() + + require.NotEmpty(result.trace.Samples) + var samplesByThread = map[uint64]uint64{} + var outliersByThread = map[uint64]uint64{} + var outliers = 0 + for _, sample := range result.trace.Samples { + count := samplesByThread[sample.ThreadID] + + var lowerBound = count * uint64(profilerSamplingRate.Nanoseconds()) + var upperBound = (count + 1 + outliersByThread[sample.ThreadID]) * uint64(profilerSamplingRate.Nanoseconds()) + + t.Logf("Routine %2d, sample %d (%d) should be between %d and %d", sample.ThreadID, count, sample.ElapsedSinceStartNS, lowerBound, upperBound) + + // We can check the lower bound explicitly, but the upper bound is problematic as some samples may get delayed. + // Therefore, we collect the number of outliers and check if it's reasonably low. + require.GreaterOrEqual(sample.ElapsedSinceStartNS, lowerBound) + if sample.ElapsedSinceStartNS > upperBound { + // We also increase the count by one to shift the followup samples too. + outliersByThread[sample.ThreadID]++ + if int(outliersByThread[sample.ThreadID]) > outliers { + outliers = int(outliersByThread[sample.ThreadID]) + } + } + + samplesByThread[sample.ThreadID] = count + 1 + } + + require.Less(outliers, len(result.trace.Samples)/10) +} + +func TestProfilerStackBufferGrowth(t *testing.T) { + var require = require.New(t) + profiler := newProfiler(time.Now()) + + _ = profiler.collectRecords() + + profiler.stacksBuffer = make([]byte, 1) + require.Equal(1, len(profiler.stacksBuffer)) + var bytesWithAutoAlloc = profiler.collectRecords() + var lenAfterAutoAlloc = len(profiler.stacksBuffer) + require.Greater(lenAfterAutoAlloc, 1) + require.Greater(lenAfterAutoAlloc, len(bytesWithAutoAlloc)) + + _ = profiler.collectRecords() + require.Equal(lenAfterAutoAlloc, len(profiler.stacksBuffer)) +} + +func testTick(t *testing.T, count, i int, prevTick time.Time) time.Time { + var sinceLastTick = time.Since(prevTick).Microseconds() + t.Logf("tick %2d/%d after %d μs", i+1, count, sinceLastTick) + return time.Now() +} + +func isCI() bool { + return os.Getenv("CI") != "" +} + +// This test measures the accuracy of time.NewTicker() on the current system. +func TestProfilerTimeTicker(t *testing.T) { + if isCI() { + t.Skip("Skipping on CI because the machines are too overloaded to provide consistent ticker resolution.") + } + + onProfilerStart() // This fixes Windows ticker resolution. + + t.Logf("We're expecting a tick once every %d μs", profilerSamplingRate.Microseconds()) + + var startTime = time.Now() + var ticker = time.NewTicker(profilerSamplingRate) + defer ticker.Stop() + + // wait until 10 ticks have passed + var count = 10 + var prevTick = time.Now() + for i := 0; i < count; i++ { + <-ticker.C + prevTick = testTick(t, count, i, prevTick) + } + + var elapsed = time.Since(startTime) + require.LessOrEqual(t, elapsed.Microseconds(), profilerSamplingRate.Microseconds()*int64(count+3)) +} + +// This test measures the accuracy of time.Sleep() on the current system. +func TestProfilerTimeSleep(t *testing.T) { + t.Skip("This test isn't necessary at the moment because we don't use time.Sleep() in the profiler.") + + onProfilerStart() // This fixes Windows ticker resolution. + + t.Logf("We're expecting a tick once every %d μs", profilerSamplingRate.Microseconds()) + + var startTime = time.Now() + + // wait until 10 ticks have passed + var count = 10 + var prevTick = time.Now() + var next = time.Now() + for i := 0; i < count; i++ { + next = next.Add(profilerSamplingRate) + time.Sleep(time.Until(next)) + prevTick = testTick(t, count, i, prevTick) + } + + var elapsed = time.Since(startTime) + require.LessOrEqual(t, elapsed.Microseconds(), profilerSamplingRate.Microseconds()*int64(count+3)) +} + +// Benchmark results (run without executing 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 + +func BenchmarkProfilerStartStop(b *testing.B) { + b.ReportAllocs() + for i := 0; i < b.N; i++ { + stopFn := startProfiling(time.Now()) + _ = stopFn() + } +} + +func BenchmarkProfilerOnTick(b *testing.B) { + profiler := newProfiler(time.Now()) + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + profiler.onTick() + } +} + +func BenchmarkProfilerCollect(b *testing.B) { + profiler := newProfiler(time.Now()) + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + _ = profiler.collectRecords() + } +} + +func BenchmarkProfilerProcess(b *testing.B) { + profiler := newProfiler(time.Now()) + records := profiler.collectRecords() + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + profiler.processRecords(uint64(i), records) + } +} + +func profilerBenchmark(b *testing.B, withProfiling bool) { + var stopFn func() *profilerResult + if withProfiling { + stopFn = startProfiling(time.Now()) + } + b.ResetTimer() + for i := 0; i < b.N; i++ { + _ = findPrimeNumber(10000) + } + b.StopTimer() + if withProfiling { + stopFn() + } +} + +func TestProfilerOverhead(t *testing.T) { + if testing.Short() { + t.Skip("Skipping overhead benchmark in short mode.") + } + if isCI() { + t.Skip("Skipping on CI because the machines are too overloaded to run the test properly - they show between 3 and 30 %% overhead....") + } + + var base = testing.Benchmark(func(b *testing.B) { profilerBenchmark(b, false) }) + var other = testing.Benchmark(func(b *testing.B) { profilerBenchmark(b, true) }) + + t.Logf("Without profiling: %v\n", base.String()) + t.Logf("With profiling: %v\n", other.String()) + + var overhead = float64(other.NsPerOp())/float64(base.NsPerOp())*100 - 100 + var maxOverhead = 5.0 + t.Logf("Profiling overhead: %f percent\n", overhead) + require.Less(t, overhead, maxOverhead) +} diff --git a/profiler_windows.go b/profiler_windows.go new file mode 100644 index 000000000..fccb425db --- /dev/null +++ b/profiler_windows.go @@ -0,0 +1,24 @@ +package sentry + +import ( + "sync" + "syscall" +) + +// This works around the ticker resolution on Windows being ~15ms by default. +// See https://github.com/golang/go/issues/44343 +func setTimeTickerResolution() { + var winmmDLL = syscall.NewLazyDLL("winmm.dll") + if winmmDLL != nil { + var timeBeginPeriod = winmmDLL.NewProc("timeBeginPeriod") + if timeBeginPeriod != nil { + timeBeginPeriod.Call(uintptr(1)) + } + } +} + +var runOnce sync.Once + +func onProfilerStart() { + runOnce.Do(setTimeTickerResolution) +} diff --git a/stacktrace.go b/stacktrace.go index 81afbf3cf..4c288ab72 100644 --- a/stacktrace.go +++ b/stacktrace.go @@ -2,7 +2,6 @@ package sentry import ( "go/build" - "path/filepath" "reflect" "runtime" "strings" @@ -32,8 +31,8 @@ func NewStacktrace() *Stacktrace { return nil } - frames := extractFrames(pcs[:n]) - frames = filterFrames(frames) + runtimeFrames := extractFrames(pcs[:n]) + frames := createFrames(runtimeFrames) stacktrace := Stacktrace{ Frames: frames, @@ -62,8 +61,8 @@ func ExtractStacktrace(err error) *Stacktrace { return nil } - frames := extractFrames(pcs) - frames = filterFrames(frames) + runtimeFrames := extractFrames(pcs) + frames := createFrames(runtimeFrames) stacktrace := Stacktrace{ Frames: frames, @@ -192,50 +191,63 @@ type Frame struct { // NewFrame assembles a stacktrace frame out of runtime.Frame. func NewFrame(f runtime.Frame) Frame { - var abspath, relpath string - // NOTE: f.File paths historically use forward slash as path separator even - // on Windows, though this is not yet documented, see - // https://golang.org/issues/3335. In any case, filepath.IsAbs can work with - // paths with either slash or backslash on Windows. + function := f.Function + var pkg string + + if function != "" { + pkg, function = splitQualifiedFunctionName(function) + } + + return newFrame(pkg, function, f.File, f.Line) +} + +// Like filepath.IsAbs() but doesn't care what platform you run this on. +// I.e. it also recognizies `/path/to/file` when run on Windows. +func isAbsPath(path string) bool { + if len(path) == 0 { + return false + } + + // If the volume name starts with a double slash, this is an absolute path. + if len(path) >= 1 && (path[0] == '/' || path[0] == '\\') { + return true + } + + // Windows absolute path, see https://learn.microsoft.com/en-us/dotnet/standard/io/file-path-formats + if len(path) >= 3 && path[1] == ':' && (path[2] == '/' || path[2] == '\\') { + return true + } + + return false +} + +func newFrame(module string, function string, file string, line int) Frame { + frame := Frame{ + Lineno: line, + Module: module, + Function: function, + } + switch { - case f.File == "": - relpath = unknown - // Leave abspath as the empty string to be omitted when serializing - // event as JSON. - abspath = "" - case filepath.IsAbs(f.File): - abspath = f.File + case len(file) == 0: + frame.Filename = unknown + // Leave abspath as the empty string to be omitted when serializing event as JSON. + case isAbsPath(file): + frame.AbsPath = file // TODO: in the general case, it is not trivial to come up with a // "project relative" path with the data we have in run time. // We shall not use filepath.Base because it creates ambiguous paths and // affects the "Suspect Commits" feature. // For now, leave relpath empty to be omitted when serializing the event // as JSON. Improve this later. - relpath = "" default: // f.File is a relative path. This may happen when the binary is built // with the -trimpath flag. - relpath = f.File + frame.Filename = file // Omit abspath when serializing the event as JSON. - abspath = "" } - function := f.Function - var pkg string - - if function != "" { - pkg, function = splitQualifiedFunctionName(function) - } - - frame := Frame{ - AbsPath: abspath, - Filename: relpath, - Lineno: f.Line, - Module: pkg, - Function: function, - } - - frame.InApp = isInAppFrame(frame) + setInAppFrame(&frame) return frame } @@ -245,24 +257,27 @@ func NewFrame(f runtime.Frame) Frame { // runtime.Frame.Function values. func splitQualifiedFunctionName(name string) (pkg string, fun string) { pkg = packageName(name) - fun = strings.TrimPrefix(name, pkg+".") + if len(pkg) > 0 { + fun = name[len(pkg)+1:] + } return } -func extractFrames(pcs []uintptr) []Frame { - var frames = make([]Frame, 0, len(pcs)) +func extractFrames(pcs []uintptr) []runtime.Frame { + var frames = make([]runtime.Frame, 0, len(pcs)) callersFrames := runtime.CallersFrames(pcs) for { callerFrame, more := callersFrames.Next() - frames = append(frames, NewFrame(callerFrame)) + frames = append(frames, callerFrame) if !more { break } } + // TODO don't append and reverse, put in the right place from the start. // reverse for i, j := 0, len(frames)-1; i < j; i, j = i+1, j-1 { frames[i], frames[j] = frames[j], frames[i] @@ -271,41 +286,60 @@ func extractFrames(pcs []uintptr) []Frame { return frames } -// filterFrames filters out stack frames that are not meant to be reported to -// Sentry. Those are frames internal to the SDK or Go. -func filterFrames(frames []Frame) []Frame { +// createFrames creates Frame objects while filtering out frames that are not +// meant to be reported to Sentry, those are frames internal to the SDK or Go. +func createFrames(frames []runtime.Frame) []Frame { if len(frames) == 0 { return nil } - // reuse - filteredFrames := frames[:0] + result := make([]Frame, 0, len(frames)) for _, frame := range frames { - // Skip Go internal frames. - if frame.Module == "runtime" || frame.Module == "testing" { - continue + function := frame.Function + var pkg string + if function != "" { + pkg, function = splitQualifiedFunctionName(function) } - // Skip Sentry internal frames, except for frames in _test packages (for - // testing). - if strings.HasPrefix(frame.Module, "github.com/getsentry/sentry-go") && - !strings.HasSuffix(frame.Module, "_test") { - continue + + if !shouldSkipFrame(pkg) { + result = append(result, newFrame(pkg, function, frame.File, frame.Line)) } - filteredFrames = append(filteredFrames, frame) } - return filteredFrames + return result } -func isInAppFrame(frame Frame) bool { - if strings.HasPrefix(frame.AbsPath, build.Default.GOROOT) || +// TODO ID: why do we want to do this? +// I'm not aware of other SDKs skipping all Sentry frames, regardless of their position in the stactrace. +// For example, in the .NET SDK, only the first frames are skipped until the call to the SDK. +// As is, this will also hide any intermediate frames in the stack and make debugging issues harder. +func shouldSkipFrame(module string) bool { + // Skip Go internal frames. + if module == "runtime" || module == "testing" { + return true + } + + // Skip Sentry internal frames, except for frames in _test packages (for testing). + if strings.HasPrefix(module, "github.com/getsentry/sentry-go") && + !strings.HasSuffix(module, "_test") { + return true + } + + return false +} + +// On Windows, GOROOT has backslashes, but we want forward slashes. +var goRoot = strings.ReplaceAll(build.Default.GOROOT, "\\", "/") + +func setInAppFrame(frame *Frame) { + if strings.HasPrefix(frame.AbsPath, goRoot) || strings.Contains(frame.Module, "vendor") || strings.Contains(frame.Module, "third_party") { - return false + frame.InApp = false + } else { + frame.InApp = true } - - return true } func callerFunctionName() string { diff --git a/stacktrace_test.go b/stacktrace_test.go index cb6f4f687..96d682801 100644 --- a/stacktrace_test.go +++ b/stacktrace_test.go @@ -3,6 +3,7 @@ package sentry import ( "encoding/json" "errors" + "runtime" "testing" "github.com/google/go-cmp/cmp" @@ -69,9 +70,9 @@ func TestSplitQualifiedFunctionName(t *testing.T) { } // nolint: scopelint // false positive https://github.com/kyoh86/scopelint/issues/4 -func TestFilterFrames(t *testing.T) { +func TestCreateFrames(t *testing.T) { tests := []struct { - in []Frame + in []runtime.Frame out []Frame }{ // sanity check @@ -79,36 +80,26 @@ func TestFilterFrames(t *testing.T) { // filter out go internals and SDK internals; "sentry-go_test" is // considered outside of the SDK and thus included (useful for testing) { - in: []Frame{ + in: []runtime.Frame{ { - Function: "goexit", - Module: "runtime", - AbsPath: "/goroot/src/runtime/asm_amd64.s", - InApp: false, + Function: "runtime.goexit", + File: "/goroot/src/runtime/asm_amd64.s", }, { - Function: "tRunner", - Module: "testing", - AbsPath: "/goroot/src/testing/testing.go", - InApp: false, + Function: "testing.tRunner", + File: "/goroot/src/testing/testing.go", }, { - Function: "TestNewStacktrace.func1", - Module: "github.com/getsentry/sentry-go_test", - AbsPath: "/somewhere/sentry/sentry-go/stacktrace_external_test.go", - InApp: true, + Function: "github.com/getsentry/sentry-go_test.TestNewStacktrace.func1", + File: "/somewhere/sentry/sentry-go/stacktrace_external_test.go", }, { - Function: "StacktraceTestHelper.NewStacktrace", - Module: "github.com/getsentry/sentry-go", - AbsPath: "/somewhere/sentry/sentry-go/stacktrace_test.go", - InApp: true, + Function: "github.com/getsentry/sentry-go.StacktraceTestHelper.NewStacktrace", + File: "/somewhere/sentry/sentry-go/stacktrace_test.go", }, { - Function: "NewStacktrace", - Module: "github.com/getsentry/sentry-go", - AbsPath: "/somewhere/sentry/sentry-go/stacktrace.go", - InApp: true, + Function: "github.com/getsentry/sentry-go.NewStacktrace", + File: "/somewhere/sentry/sentry-go/stacktrace.go", }, }, out: []Frame{ @@ -122,24 +113,18 @@ func TestFilterFrames(t *testing.T) { }, // filter out integrations; SDK subpackages { - in: []Frame{ + in: []runtime.Frame{ { - Function: "Example.Integration", - Module: "github.com/getsentry/sentry-go/http/integration", - AbsPath: "/somewhere/sentry/sentry-go/http/integration/integration.go", - InApp: true, + Function: "github.com/getsentry/sentry-go/http/integration.Example.Integration", + File: "/somewhere/sentry/sentry-go/http/integration/integration.go", }, { - Function: "(*Handler).Handle", - Module: "github.com/getsentry/sentry-go/http", - AbsPath: "/somewhere/sentry/sentry-go/http/sentryhttp.go", - InApp: true, + Function: "github.com/getsentry/sentry-go/http.(*Handler).Handle", + File: "/somewhere/sentry/sentry-go/http/sentryhttp.go", }, { - Function: "main", - Module: "main", - AbsPath: "/somewhere/example.com/pkg/main.go", - InApp: true, + Function: "main.main", + File: "/somewhere/example.com/pkg/main.go", }, }, out: []Frame{ @@ -154,7 +139,7 @@ func TestFilterFrames(t *testing.T) { } for _, tt := range tests { t.Run("", func(t *testing.T) { - got := filterFrames(tt.in) + got := createFrames(tt.in) if diff := cmp.Diff(tt.out, got); diff != "" { t.Errorf("filterFrames() mismatch (-want +got):\n%s", diff) } diff --git a/traces_profiler.go b/traces_profiler.go new file mode 100644 index 000000000..a983262ca --- /dev/null +++ b/traces_profiler.go @@ -0,0 +1,80 @@ +package sentry + +// Checks whether the transaction should be profiled (according to ProfilesSampleRate) +// and starts a profiler if so. +func (span *Span) sampleTransactionProfile() { + var sampleRate = span.clientOptions().ProfilesSampleRate + switch { + case sampleRate < 0.0 || sampleRate > 1.0: + Logger.Printf("Skipping transaction profiling: ProfilesSampleRate out of range [0.0, 1.0]: %f", sampleRate) + case sampleRate == 0.0 || rng.Float64() >= sampleRate: + Logger.Printf("Skipping transaction profiling: ProfilesSampleRate is: %f", sampleRate) + default: + span.profiler = &_transactionProfiler{ + stopFunc: startProfiling(span.StartTime), + } + } +} + +type transactionProfiler interface { + Finish(span *Span) *profileInfo +} + +type _transactionProfiler struct { + stopFunc func() *profilerResult +} + +func (tp *_transactionProfiler) Finish(span *Span) *profileInfo { + result := tp.stopFunc() + if result == nil || result.trace == nil { + return nil + } + + info := &profileInfo{ + Version: "1", + EventID: uuid(), + // See https://github.com/getsentry/sentry-go/pull/626#discussion_r1204870340 for explanation why we use the Transaction time. + Timestamp: span.StartTime, + Trace: result.trace, + Transaction: profileTransaction{ + DurationNS: uint64(span.EndTime.Sub(span.StartTime).Nanoseconds()), + Name: span.Name, + TraceID: span.TraceID.String(), + }, + } + if len(info.Transaction.Name) == 0 { + // Name is required by Relay so use the operation name if the span name is empty. + info.Transaction.Name = span.Op + } + if result.callerGoID > 0 { + info.Transaction.ActiveThreadID = result.callerGoID + } + return info +} + +func (info *profileInfo) UpdateFromEvent(event *Event) { + info.Environment = event.Environment + info.Platform = event.Platform + info.Release = event.Release + info.Dist = event.Dist + info.Transaction.ID = event.EventID + + if runtimeContext, ok := event.Contexts["runtime"]; ok { + if value, ok := runtimeContext["name"]; !ok { + info.Runtime.Name = value.(string) + } + if value, ok := runtimeContext["version"]; !ok { + info.Runtime.Version = value.(string) + } + } + if osContext, ok := event.Contexts["os"]; ok { + if value, ok := osContext["name"]; !ok { + info.OS.Name = value.(string) + } + } + if deviceContext, ok := event.Contexts["device"]; ok { + if value, ok := deviceContext["arch"]; !ok { + info.Device.Architecture = value.(string) + } + } +} diff --git a/traces_profiler_test.go b/traces_profiler_test.go new file mode 100644 index 000000000..2996a4146 --- /dev/null +++ b/traces_profiler_test.go @@ -0,0 +1,56 @@ +package sentry + +import ( + "testing" + "time" + + "github.com/stretchr/testify/require" +) + +func testTraceProfiling(t *testing.T, rate float64) (*Span, *Event) { + ticker := setupProfilerTestTicker() + defer restoreProfilerTicker() + + transport := &TransportMock{} + ctx := NewTestContext(ClientOptions{ + Transport: transport, + EnableTracing: true, + TracesSampleRate: 1.0, + ProfilesSampleRate: rate, + Environment: "env", + Release: "rel", + Dist: "dist", + }) + span := StartSpan(ctx, "top") + ticker.Tick() + span.Finish() + + require.Equal(t, 1, len(transport.events)) + return span, transport.events[0] +} + +func TestTraceProfiling(t *testing.T) { + var require = require.New(t) + var timeBeforeStarting = time.Now() + span, event := testTraceProfiling(t, 1.0) + require.Equal(transactionType, event.Type) + require.NotNil(event.sdkMetaData.transactionProfile) + var profileInfo = event.sdkMetaData.transactionProfile + require.Equal("go", profileInfo.Platform) + require.Equal(event.Environment, profileInfo.Environment) + require.Equal(event.Release, profileInfo.Release) + require.Equal(event.Dist, profileInfo.Dist) + require.GreaterOrEqual(profileInfo.Timestamp, timeBeforeStarting) + require.LessOrEqual(profileInfo.Timestamp, time.Now()) + require.Equal(event.EventID, profileInfo.Transaction.ID) + require.Greater(profileInfo.Transaction.ActiveThreadID, uint64(0)) + require.Equal(span.TraceID.String(), profileInfo.Transaction.TraceID) + validateProfile(t, profileInfo.Trace, span.EndTime.Sub(span.StartTime)) +} + +func TestTraceProfilingDisabled(t *testing.T) { + var require = require.New(t) + _, event := testTraceProfiling(t, 0) + require.Equal(transactionType, event.Type) + require.Nil(event.sdkMetaData.transactionProfile) +} diff --git a/tracing.go b/tracing.go index 41d7a4316..32aea821b 100644 --- a/tracing.go +++ b/tracing.go @@ -58,6 +58,8 @@ type Span struct { //nolint: maligned // prefer readability over optimal memory recorder *spanRecorder // span context, can only be set on transactions contexts map[string]Context + // profiler instance if attached, nil otherwise. + profiler transactionProfiler } // TraceParentContext describes the context of a (remote) parent span. @@ -178,9 +180,16 @@ func StartSpan(ctx context.Context, operation string, options ...SpanOption) *Sp } span.recorder.record(&span) + hub := hubFromContext(ctx) + // Update scope so that all events include a trace context, allowing // Sentry to correlate errors to transactions/spans. - hubFromContext(ctx).Scope().SetContext("trace", span.traceContext().Map()) + hub.Scope().SetContext("trace", span.traceContext().Map()) + + // Start profiling only if it's a sampled root transaction. + if span.IsTransaction() && span.Sampled.Bool() { + span.sampleTransactionProfile() + } return &span } @@ -191,9 +200,16 @@ func (s *Span) Finish() { // TODO(tracing): maybe make Finish run at most once, such that // (incorrectly) calling it twice never double sends to Sentry. + // For the timing to be correct, the profiler must be stopped before s.EndTime. + var profile *profileInfo + if s.profiler != nil { + profile = s.profiler.Finish(s) + } + if s.EndTime.IsZero() { s.EndTime = monotonicTimeSince(s.StartTime) } + if !s.Sampled.Bool() { return } @@ -202,6 +218,8 @@ func (s *Span) Finish() { return } + event.sdkMetaData.transactionProfile = profile + // TODO(tracing): add breadcrumbs // (see https://github.com/getsentry/sentry-python/blob/f6f3525f8812f609/sentry_sdk/tracing.py#L372) @@ -397,14 +415,16 @@ func (s *Span) MarshalJSON() ([]byte, error) { }) } -func (s *Span) sample() Sampled { - hub := hubFromContext(s.ctx) - var clientOptions ClientOptions - client := hub.Client() +func (s *Span) clientOptions() *ClientOptions { + client := hubFromContext(s.ctx).Client() if client != nil { - clientOptions = hub.Client().Options() + return &client.options } + return &ClientOptions{} +} +func (s *Span) sample() Sampled { + clientOptions := s.clientOptions() // https://develop.sentry.dev/sdk/performance/#sampling // #1 tracing is not enabled. if !clientOptions.EnableTracing { diff --git a/transport.go b/transport.go index a6abf1d32..d8bdf2a74 100644 --- a/transport.go +++ b/transport.go @@ -94,6 +94,22 @@ func getRequestBodyFromEvent(event *Event) []byte { return nil } +func encodeEnvelopeItem(enc *json.Encoder, itemType string, body json.RawMessage) error { + // Item header + err := enc.Encode(struct { + Type string `json:"type"` + Length int `json:"length"` + }{ + Type: itemType, + Length: len(body), + }) + if err == nil { + // payload + err = enc.Encode(body) + } + return err +} + func envelopeFromBody(event *Event, dsn *Dsn, sentAt time.Time, body json.RawMessage) (*bytes.Buffer, error) { var b bytes.Buffer enc := json.NewEncoder(&b) @@ -127,29 +143,25 @@ func envelopeFromBody(event *Event, dsn *Dsn, sentAt time.Time, body json.RawMes return nil, err } - var itemType string - switch event.Type { - case transactionType: - itemType = transactionType - default: - itemType = eventType + if event.Type == transactionType { + err = encodeEnvelopeItem(enc, transactionType, body) + } else { + err = encodeEnvelopeItem(enc, eventType, body) } - - // Item header - err = enc.Encode(struct { - Type string `json:"type"` - Length int `json:"length"` - }{ - Type: itemType, - Length: len(body), - }) if err != nil { return nil, err } - // payload - err = enc.Encode(body) - if err != nil { - return nil, err + + // Profile data + if event.sdkMetaData.transactionProfile != nil { + body, err = json.Marshal(event.sdkMetaData.transactionProfile) + if err != nil { + return nil, err + } + err = encodeEnvelopeItem(enc, profileType, body) + if err != nil { + return nil, err + } } return &b, nil diff --git a/transport_test.go b/transport_test.go index 2085f73fc..e20f69dbb 100644 --- a/transport_test.go +++ b/transport_test.go @@ -132,26 +132,32 @@ func TestGetRequestBodyFromEventCompletelyInvalid(t *testing.T) { } } -func TestEnvelopeFromErrorBody(t *testing.T) { - const eventID = "b81c5be4d31e48959103a1f878a1efcb" +func newTestEvent(eventType string) *Event { event := NewEvent() event.Type = eventType - event.EventID = eventID + event.EventID = "b81c5be4d31e48959103a1f878a1efcb" event.Sdk = SdkInfo{ Name: "sentry.go", Version: "0.0.1", } + return event +} +func newTestDSN(t *testing.T) *Dsn { dsn, err := NewDsn("http://public@example.com/sentry/1") if err != nil { t.Fatal(err) } + return dsn +} +func TestEnvelopeFromErrorBody(t *testing.T) { + event := newTestEvent(eventType) sentAt := time.Unix(0, 0).UTC() body := json.RawMessage(`{"type":"event","fields":"omitted"}`) - b, err := envelopeFromBody(event, dsn, sentAt, body) + b, err := envelopeFromBody(event, newTestDSN(t), sentAt, body) if err != nil { t.Fatal(err) } @@ -166,25 +172,63 @@ func TestEnvelopeFromErrorBody(t *testing.T) { } func TestEnvelopeFromTransactionBody(t *testing.T) { - const eventID = "b81c5be4d31e48959103a1f878a1efcb" - event := NewEvent() - event.Type = transactionType - event.EventID = eventID - event.Sdk = SdkInfo{ - Name: "sentry.go", - Version: "0.0.1", - } + event := newTestEvent(transactionType) + sentAt := time.Unix(0, 0).UTC() - dsn, err := NewDsn("http://public@example.com/sentry/1") + body := json.RawMessage(`{"type":"transaction","fields":"omitted"}`) + + b, err := envelopeFromBody(event, newTestDSN(t), sentAt, body) if err != nil { t.Fatal(err) } + got := b.String() + want := `{"event_id":"b81c5be4d31e48959103a1f878a1efcb","sent_at":"1970-01-01T00:00:00Z","dsn":"http://public@example.com/sentry/1","sdk":{"name":"sentry.go","version":"0.0.1"}} +{"type":"transaction","length":41} +{"type":"transaction","fields":"omitted"} +` + if diff := cmp.Diff(want, got); diff != "" { + t.Errorf("Envelope mismatch (-want +got):\n%s", diff) + } +} +func TestEnvelopeFromTransactionWithProfile(t *testing.T) { + event := newTestEvent(transactionType) + event.sdkMetaData.transactionProfile = &profileInfo{ + Trace: &profileTrace{ + Frames: []*Frame{ + { + Function: "func", + Module: "module", + Filename: "file.go", + Lineno: 42, + Colno: 24, + }, + }, + Samples: []*profileSample{ + { + ElapsedSinceStartNS: 10, + StackID: 2, + ThreadID: 3, + }, + }, + Stacks: []profileStack{{0}}, + ThreadMetadata: map[string]profileThreadMetadata{ + "1": {Name: "GO 1"}, + }, + }, + Transaction: profileTransaction{ + ActiveThreadID: 1, + DurationNS: 2, + ID: "3", + Name: "tx-name", + TraceID: "trace-id", + }, + } sentAt := time.Unix(0, 0).UTC() body := json.RawMessage(`{"type":"transaction","fields":"omitted"}`) - b, err := envelopeFromBody(event, dsn, sentAt, body) + b, err := envelopeFromBody(event, newTestDSN(t), sentAt, body) if err != nil { t.Fatal(err) } @@ -192,6 +236,8 @@ func TestEnvelopeFromTransactionBody(t *testing.T) { want := `{"event_id":"b81c5be4d31e48959103a1f878a1efcb","sent_at":"1970-01-01T00:00:00Z","dsn":"http://public@example.com/sentry/1","sdk":{"name":"sentry.go","version":"0.0.1"}} {"type":"transaction","length":41} {"type":"transaction","fields":"omitted"} +{"type":"profile","length":618} +{"device":{"architecture":"","classification":"","locale":"","manufacturer":"","model":""},"event_id":"","os":{"build_number":"","name":"","version":""},"platform":"","release":"","dist":"","runtime":{"name":"","version":""},"timestamp":"0001-01-01T00:00:00Z","profile":{"frames":[{"function":"func","module":"module","filename":"file.go","lineno":42,"colno":24,"in_app":false}],"samples":[{"elapsed_since_start_ns":10,"stack_id":2,"thread_id":3}],"stacks":[[0]],"thread_metadata":{"1":{"name":"GO 1"}}},"transaction":{"active_thread_id":1,"duration_ns":2,"id":"3","name":"tx-name","trace_id":"trace-id"},"version":""} ` if diff := cmp.Diff(want, got); diff != "" { t.Errorf("Envelope mismatch (-want +got):\n%s", diff)