Merge pull request #3 from pyroscope-io/managed-code-filtering

Add sampling option to ignore time spent in native code

Author: kolesnikovae

examples/tracing/README.md

@@ -1,8 +1,7 @@
 # Collect Tracing
 
 The example demonstrates how the package may be used to collect and process `NetTrace` stream data using Diagnostics IPC:
-the program processes events produced with **Microsoft-DotNETCore-SampleProfiler** provider and creates a sampled profile,
-rendered as a call tree.
+the program processes events produced with **Microsoft-DotNETCore-SampleProfiler** provider and creates a sampled profile.
 
 1. Run dotnet application.
 2. Find its PID, e.g.:

nettrace/nettrace_test.go

@@ -15,20 +15,38 @@ import (
 )
 
 func TestNetTraceDecoding(t *testing.T) {
-	t.Run(".Net 5.0 SampleProfiler Web app", func(t *testing.T) {
-		requireEqual(t,
-			"testdata/dotnet-5.0-SampleProfiler-webapp.golden.nettrace",
-			"testdata/dotnet-5.0-SampleProfiler-webapp.txt")
-	})
+	t.Run(".Net 5.0 SampleProfiler", func(t *testing.T) {
+		t.Run("Web app", func(t *testing.T) {
+			t.Run("Managed code only", func(t *testing.T) {
+				requireEqual(t,
+					"testdata/dotnet-5.0-SampleProfiler-webapp.golden.nettrace",
+					"testdata/dotnet-5.0-SampleProfiler-webapp-managed-only.txt",
+					profiler.WithManagedCodeOnly())
+			})
+			t.Run("Managed and native code", func(t *testing.T) {
+				requireEqual(t,
+					"testdata/dotnet-5.0-SampleProfiler-webapp.golden.nettrace",
+					"testdata/dotnet-5.0-SampleProfiler-webapp.txt")
+			})
+		})
 
-	t.Run(".Net 5.0 SampleProfiler Simple single thread app", func(t *testing.T) {
-		requireEqual(t,
-			"testdata/dotnet-5.0-SampleProfiler-single-thread.golden.nettrace",
-			"testdata/dotnet-5.0-SampleProfiler-single-thread.txt")
+		t.Run("Simple single thread app", func(t *testing.T) {
+			t.Run("Managed code only", func(t *testing.T) {
+				requireEqual(t,
+					"testdata/dotnet-5.0-SampleProfiler-single-thread.golden.nettrace",
+					"testdata/dotnet-5.0-SampleProfiler-single-thread-managed-only.txt",
+					profiler.WithManagedCodeOnly())
+			})
+			t.Run("Managed and native code", func(t *testing.T) {
+				requireEqual(t,
+					"testdata/dotnet-5.0-SampleProfiler-single-thread.golden.nettrace",
+					"testdata/dotnet-5.0-SampleProfiler-single-thread.txt")
+			})
+		})
 	})
 }
 
-func requireEqual(t *testing.T, sample, expected string) {
+func requireEqual(t *testing.T, sample, expected string, options ...profiler.Option) {
 	t.Helper()
 
 	s, err := os.Open(sample)
@@ -40,7 +58,7 @@ func requireEqual(t *testing.T, sample, expected string) {
 	trace, err := stream.Open()
 	requireNoError(t, err)
 
-	p := profiler.NewSampleProfiler(trace)
+	p := profiler.NewSampleProfiler(trace, options...)
 	stream.EventHandler = p.EventHandler
 	stream.MetadataHandler = p.MetadataHandler
 	stream.StackBlockHandler = p.StackBlockHandler

nettrace/profiler/profiler.go

@@ -10,6 +10,8 @@ import (
 	"github.com/pyroscope-io/dotnetdiag/nettrace"
 )
 
+// SampleProfiler processes event stream from Microsoft-DotNETCore-SampleProfiler
+// provider and calculates time for every call stack.
 type SampleProfiler struct {
 	trace *nettrace.Trace
 	sym   *symbols
@@ -20,16 +22,23 @@ type SampleProfiler struct {
 
 	events  events
 	samples []sample
+
+	managedOnly bool
 }
 
-type sample struct {
-	stack []uint64
-	val   int64
+type Option func(*SampleProfiler)
+
+// WithManagedCodeOnly prescribes SampleProfiler to ignore the time that
+// was spent in native (unmanaged) code.
+func WithManagedCodeOnly() Option {
+	return func(p *SampleProfiler) {
+		p.managedOnly = true
+	}
 }
 
-type FrameInfo struct {
-	SampledTime time.Duration
-	Name        string
+type sample struct {
+	stack []uint64
+	value int64
 }
 
 type event struct {
@@ -74,14 +83,18 @@ const (
 	sampleTypeManaged
 )
 
-func NewSampleProfiler(trace *nettrace.Trace) *SampleProfiler {
-	return &SampleProfiler{
+func NewSampleProfiler(trace *nettrace.Trace, options ...Option) *SampleProfiler {
+	p := &SampleProfiler{
 		trace:   trace,
 		sym:     newSymbols(),
 		md:      make(map[int32]*nettrace.Metadata),
 		threads: make(map[int64]*thread),
 		stacks:  make(map[int32][]uint64),
 	}
+	for _, option := range options {
+		option(p)
+	}
+	return p
 }
 
 func (s *SampleProfiler) Samples() map[string]time.Duration {
@@ -91,7 +104,7 @@ func (s *SampleProfiler) Samples() map[string]time.Duration {
 		for i := range x.stack {
 			name[i] = s.sym.resolve(x.stack[i])
 		}
-		samples[strings.Join(name, ";")] += time.Duration(x.val * -1)
+		samples[strings.Join(name, ";")] += time.Duration(x.value * -1)
 	}
 	return samples
 }
@@ -137,10 +150,10 @@ func (s *SampleProfiler) SequencePointBlockHandler(*nettrace.SequencePointBlock)
 		s.thread(x.threadID).addSample(x.typ, x.relativeTime, x.stackID)
 	}
 	for _, t := range s.threads {
-		for k, v := range t.samples {
+		for stackID, value := range t.samples {
 			s.samples = append(s.samples, sample{
-				stack: s.stacks[k],
-				val:   v,
+				stack: s.stacks[stackID],
+				value: value,
 			})
 		}
 		t.samples = make(map[int32]int64)
@@ -169,7 +182,10 @@ func (s *SampleProfiler) thread(tid int64) *thread {
 	if ok {
 		return t
 	}
-	t = &thread{samples: make(map[int32]int64)}
+	t = &thread{
+		samples:     make(map[int32]int64),
+		managedOnly: s.managedOnly,
+	}
 	s.threads[tid] = t
 	return t
 }

nettrace/profiler/thread.go

@@ -1,10 +1,10 @@
 package profiler
 
 type thread struct {
-	lastBlockTime int64
-	lastCPUTime   int64
-	// StackID -> sampled time
-	samples map[int32]int64
+	lastExternalTime int64
+	lastManagedTime  int64
+	samples          map[int32]int64
+	managedOnly      bool
 }
 
 type threadState int
@@ -13,16 +13,16 @@ const (
 	_ threadState = iota - 1
 
 	uninitialized
-	running
-	blocked
+	managed
+	external
 )
 
 func (t *thread) state() threadState {
 	switch {
-	case t.lastBlockTime < 0:
-		return running
-	case t.lastBlockTime > 0:
-		return blocked
+	case t.lastExternalTime < 0:
+		return managed
+	case t.lastExternalTime > 0:
+		return external
 	default:
 		return uninitialized
 	}
@@ -36,35 +36,35 @@ func (t *thread) addSample(sampleType clrThreadSampleType, relativeTime int64, s
 	case sampleTypeManaged:
 		switch t.state() {
 		case uninitialized:
-			t.putCPUSample(stackID, relativeTime)
-			t.lastBlockTime = -1
-		case running:
-			t.putCPUSample(stackID, relativeTime)
-		case blocked:
-			t.putBlockSample(stackID, relativeTime)
-			t.lastBlockTime = -relativeTime
+			t.managedSample(stackID, relativeTime)
+			t.lastExternalTime = -1
+		case managed:
+			t.managedSample(stackID, relativeTime)
+		case external:
+			t.externalSample(stackID, relativeTime)
+			t.lastExternalTime = -relativeTime
 		}
-		t.lastCPUTime = relativeTime
+		t.lastManagedTime = relativeTime
 
 	case sampleTypeExternal:
 		switch t.state() {
-		case blocked, uninitialized:
-			t.putBlockSample(stackID, relativeTime)
-		case running:
-			t.putCPUSample(stackID, relativeTime)
+		case external, uninitialized:
+			t.externalSample(stackID, relativeTime)
+		case managed:
+			t.managedSample(stackID, relativeTime)
 		}
-		t.lastBlockTime = relativeTime
+		t.lastExternalTime = relativeTime
 	}
 }
 
-func (t *thread) putCPUSample(stackID int32, rt int64) {
-	if t.lastCPUTime > 0 {
-		t.samples[stackID] += t.lastCPUTime - rt
+func (t *thread) managedSample(stackID int32, rt int64) {
+	if t.lastManagedTime > 0 {
+		t.samples[stackID] += t.lastManagedTime - rt
 	}
 }
 
-func (t *thread) putBlockSample(stackID int32, rt int64) {
-	if t.lastBlockTime > 0 {
-		t.samples[stackID] += t.lastBlockTime - rt
+func (t *thread) externalSample(stackID int32, rt int64) {
+	if t.lastExternalTime > 0 && !t.managedOnly {
+		t.samples[stackID] += t.lastExternalTime - rt
 	}
 }

nettrace/testdata/dotnet-5.0-SampleProfiler-single-thread-managed-only.txt

@@ -0,0 +1,4 @@
+mvc-hello-world!Example.Program.Main(class System.String[]);mvc-hello-world!Example.Program.Fast() 11217349
+mvc-hello-world!Example.Program.Main(class System.String[]);mvc-hello-world!Example.Program.Fast();mvc-hello-world!Example.Program.Work(int32) 1638356862
+mvc-hello-world!Example.Program.Main(class System.String[]);mvc-hello-world!Example.Program.Slow() 11253402
+mvc-hello-world!Example.Program.Main(class System.String[]);mvc-hello-world!Example.Program.Slow();mvc-hello-world!Example.Program.Work(int32) 6505198057