diff --git a/fgprof.go b/fgprof.go index a79d2a3..18f7d6f 100644 --- a/fgprof.go +++ b/fgprof.go @@ -4,10 +4,26 @@ package fgprof import ( + "fmt" "io" "runtime" + "sort" "strings" "time" + + "github.com/google/pprof/profile" +) + +// Format decides how the output is rendered to the user. +type Format string + +const ( + // FormatFolded is used by Brendan Gregg's FlameGraph utility, see + // https://github.com/brendangregg/FlameGraph#2-fold-stacks. + FormatFolded Format = "folded" + // FormatPprof is used by Google's pprof utility, see + // https://github.com/google/pprof/blob/master/proto/README.md. + FormatPprof Format = "pprof" ) // Start begins profiling the goroutines of the program and returns a function @@ -23,7 +39,7 @@ func Start(w io.Writer, format Format) func() error { stopCh := make(chan struct{}) prof := &profiler{} - stackCounts := stackCounter{} + profile := newWallclockProfile() go func() { defer ticker.Stop() @@ -32,7 +48,7 @@ func Start(w io.Writer, format Format) func() error { select { case <-ticker.C: stacks := prof.GoroutineProfile() - stackCounts.Update(stacks) + profile.Add(stacks) case <-stopCh: return } @@ -42,14 +58,8 @@ func Start(w io.Writer, format Format) func() error { return func() error { stopCh <- struct{}{} endTime := time.Now() - return writeFormat( - w, - stackCounts.HumanMap(prof.SelfFrame()), - format, - hz, - startTime, - endTime, - ) + profile.Ignore(prof.SelfFrames()...) + return profile.Export(w, format, hz, startTime, endTime) } } @@ -95,58 +105,203 @@ func (p *profiler) GoroutineProfile() []runtime.StackRecord { } } -func (p *profiler) SelfFrame() *runtime.Frame { - return p.selfFrame +// SelfFrames returns frames that belong to the profiler so that we can ignore +// them when exporting the final profile. +func (p *profiler) SelfFrames() []*runtime.Frame { + if p.selfFrame != nil { + return []*runtime.Frame{p.selfFrame} + } + return nil } -type stringStackCounter map[string]int +func newWallclockProfile() *wallclockProfile { + return &wallclockProfile{stacks: map[[32]uintptr]*wallclockStack{}} +} -func (s stringStackCounter) Update(p []runtime.StackRecord) { - for _, pp := range p { - frames := runtime.CallersFrames(pp.Stack()) +// wallclockProfile holds a wallclock profile that can be exported in different +// formats. +type wallclockProfile struct { + stacks map[[32]uintptr]*wallclockStack + ignore []*runtime.Frame +} - var stack []string - for { - frame, more := frames.Next() - stack = append([]string{frame.Function}, stack...) - if !more { - break +// wallclockStack holds the symbolized frames of a stack trace and the number +// of times it has been seen. +type wallclockStack struct { + frames []*runtime.Frame + count int +} + +// Ignore sets a list of frames that should be ignored when exporting the +// profile. +func (p *wallclockProfile) Ignore(frames ...*runtime.Frame) { + p.ignore = frames +} + +// Add adds the given stack traces to the profile. +func (p *wallclockProfile) Add(stackRecords []runtime.StackRecord) { + for _, stackRecord := range stackRecords { + if _, ok := p.stacks[stackRecord.Stack0]; !ok { + ws := &wallclockStack{} + // symbolize pcs into frames + frames := runtime.CallersFrames(stackRecord.Stack()) + for { + frame, more := frames.Next() + ws.frames = append(ws.frames, &frame) + if !more { + break + } } + p.stacks[stackRecord.Stack0] = ws } - key := strings.Join(stack, ";") - s[key]++ + p.stacks[stackRecord.Stack0].count++ } } -type stackCounter map[[32]uintptr]int +func (p *wallclockProfile) Export(w io.Writer, f Format, hz int, startTime, endTime time.Time) error { + switch f { + case FormatFolded: + return p.exportFolded(w) + case FormatPprof: + return p.exportPprof(hz, startTime, endTime).Write(w) + default: + return fmt.Errorf("unknown format: %q", f) + } +} -func (s stackCounter) Update(p []runtime.StackRecord) { - for _, pp := range p { - s[pp.Stack0]++ +// exportStacks returns the stacks in this profile except those that have been +// set to Ignore(). +func (p *wallclockProfile) exportStacks() []*wallclockStack { + stacks := make([]*wallclockStack, 0, len(p.stacks)) +nextStack: + for _, ws := range p.stacks { + for _, f := range ws.frames { + for _, igf := range p.ignore { + if f.Entry == igf.Entry { + continue nextStack + } + } + } + stacks = append(stacks, ws) } + return stacks } -// @TODO(fg) create a better interface that avoids the pprof output having to -// split the stacks using the `;` separator. -func (s stackCounter) HumanMap(exclude *runtime.Frame) map[string]int { - m := map[string]int{} +func (p *wallclockProfile) exportFolded(w io.Writer) error { + var lines []string + stacks := p.exportStacks() + for _, ws := range stacks { + var foldedStack []string + for _, f := range ws.frames { + foldedStack = append(foldedStack, f.Function) + } + line := fmt.Sprintf("%s %d", strings.Join(foldedStack, ";"), ws.count) + lines = append(lines, line) + } + sort.Strings(lines) + _, err := io.WriteString(w, strings.Join(lines, "\n")+"\n") + return err +} + +func (p *wallclockProfile) exportPprof(hz int, startTime, endTime time.Time) *profile.Profile { + prof := &profile.Profile{} + m := &profile.Mapping{ID: 1, HasFunctions: true} + prof.Period = int64(1e9 / hz) // Number of nanoseconds between samples. + prof.TimeNanos = startTime.UnixNano() + prof.DurationNanos = int64(endTime.Sub(startTime)) + prof.Mapping = []*profile.Mapping{m} + prof.SampleType = []*profile.ValueType{ + { + Type: "samples", + Unit: "count", + }, + { + Type: "time", + Unit: "nanoseconds", + }, + } + prof.PeriodType = &profile.ValueType{ + Type: "wallclock", + Unit: "nanoseconds", + } + + type functionKey struct { + Name string + Filename string + } + funcIdx := map[functionKey]*profile.Function{} + + type locationKey struct { + Function functionKey + Line int + } + locationIdx := map[locationKey]*profile.Location{} + for _, ws := range p.exportStacks() { + sample := &profile.Sample{ + Value: []int64{ + int64(ws.count), + int64(1000 * 1000 * 1000 / hz * ws.count), + }, + } + + for _, frame := range ws.frames { + fnKey := functionKey{Name: frame.Function, Filename: frame.File} + function, ok := funcIdx[fnKey] + if !ok { + function = &profile.Function{ + ID: uint64(len(prof.Function)) + 1, + Name: frame.Function, + SystemName: frame.Function, + Filename: frame.File, + } + funcIdx[fnKey] = function + prof.Function = append(prof.Function, function) + } + + locKey := locationKey{Function: fnKey, Line: frame.Line} + location, ok := locationIdx[locKey] + if !ok { + location = &profile.Location{ + ID: uint64(len(prof.Location)) + 1, + Mapping: m, + Line: []profile.Line{{ + Function: function, + Line: int64(frame.Line), + }}, + } + locationIdx[locKey] = location + prof.Location = append(prof.Location, location) + } + sample.Location = append(sample.Location, location) + } + prof.Sample = append(prof.Sample, sample) + } + return prof +} + +type symbolizedStacks map[[32]uintptr][]frameCount + +func (w wallclockProfile) Symbolize(exclude *runtime.Frame) symbolizedStacks { + m := make(symbolizedStacks) outer: - for stack0, count := range s { + for stack0, ws := range w.stacks { frames := runtime.CallersFrames((&runtime.StackRecord{Stack0: stack0}).Stack()) - var stack []string for { frame, more := frames.Next() if frame.Entry == exclude.Entry { continue outer } - stack = append([]string{frame.Function}, stack...) + m[stack0] = append(m[stack0], frameCount{Frame: &frame, Count: ws.count}) if !more { break } } - key := strings.Join(stack, ";") - m[key] = count } return m } + +type frameCount struct { + *runtime.Frame + Count int +} diff --git a/fgprof_test.go b/fgprof_test.go index 658ca42..948b99d 100644 --- a/fgprof_test.go +++ b/fgprof_test.go @@ -3,28 +3,110 @@ package fgprof import ( "bytes" "fmt" + "runtime" "strings" "testing" "time" + + "github.com/google/pprof/profile" + "github.com/stretchr/testify/require" ) -// TestStart is a simple smoke test that checks that the profiler doesn't -// produce errors and catches the TestStart function itself. It'd be nice to -// add better testing in the future, but writing test cases for a profiler is -// a little tricky : ). +// TestStart is a smoke test that checks that the profiler produces a profiles +// in different formats with the expected stack frames. func TestStart(t *testing.T) { - out := &bytes.Buffer{} - stop := Start(out, FormatFolded) - time.Sleep(100 * time.Millisecond) - if err := stop(); err != nil { - t.Fatal(err) + tests := []struct { + // Format is the export format being tested + Format Format + // ContainsStack returns true if the given profile contains a frame with the given name + ContainsStack func(t *testing.T, prof *bytes.Buffer, frame string) bool + }{ + { + Format: FormatFolded, + ContainsStack: func(t *testing.T, prof *bytes.Buffer, frame string) bool { + return strings.Contains(prof.String(), frame) + }, + }, + { + Format: FormatPprof, + ContainsStack: func(t *testing.T, prof *bytes.Buffer, frame string) bool { + pprof, err := profile.ParseData(prof.Bytes()) + require.NoError(t, err) + require.NoError(t, pprof.CheckValid()) + for _, s := range pprof.Sample { + for _, loc := range s.Location { + for _, line := range loc.Line { + if strings.Contains(line.Function.Name, frame) { + return true + } + } + } + } + return false + }, + }, } - if !strings.Contains(out.String(), "fgprof.TestStart") { - t.Fatalf("invalid output:\n%s", out) + for _, test := range tests { + t.Run(string(test.Format), func(t *testing.T) { + prof := &bytes.Buffer{} + stop := Start(prof, test.Format) + time.Sleep(100 * time.Millisecond) + if err := stop(); err != nil { + t.Fatal(err) + } + require.True(t, test.ContainsStack(t, prof, "fgprof.TestStart")) + require.False(t, test.ContainsStack(t, prof, "GoroutineProfile")) + }) } } +func Test_toPprof(t *testing.T) { + foo := &runtime.Frame{PC: 1, Function: "foo", File: "foo.go", Line: 23} + bar := &runtime.Frame{PC: 2, Function: "bar", File: "bar.go", Line: 42} + prof := &wallclockProfile{ + stacks: map[[32]uintptr]*wallclockStack{ + {foo.PC}: { + frames: []*runtime.Frame{foo}, + count: 1, + }, + {bar.PC, foo.PC}: { + frames: []*runtime.Frame{bar, foo}, + count: 2, + }, + }, + } + + before := time.Local + defer func() { time.Local = before }() + time.Local = time.UTC + + start := time.Date(2022, 8, 27, 14, 32, 23, 0, time.UTC) + end := start.Add(time.Second) + p := prof.exportPprof(99, start, end) + if err := p.CheckValid(); err != nil { + t.Fatal(err) + } + + want := strings.TrimSpace(` +PeriodType: wallclock nanoseconds +Period: 10101010 +Time: 2022-08-27 14:32:23 +0000 UTC +Duration: 1s +Samples: +samples/count time/nanoseconds + 1 10101010: 1 + 2 20202020: 2 1 +Locations + 1: 0x0 M=1 foo foo.go:23 s=0 + 2: 0x0 M=1 bar bar.go:42 s=0 +Mappings +1: 0x0/0x0/0x0 [FN] +`) + got := strings.TrimSpace(p.String()) + require.Equal(t, got, want) +} + func BenchmarkProfiler(b *testing.B) { prof := &profiler{} for i := 0; i < b.N; i++ { @@ -80,9 +162,9 @@ func BenchmarkProfilerGoroutines(b *testing.B) { func BenchmarkStackCounter(b *testing.B) { prof := &profiler{} stacks := prof.GoroutineProfile() - sc := stackCounter{} + sc := wallclockProfile{} b.ResetTimer() for i := 0; i < b.N; i++ { - sc.Update(stacks) + sc.Add(stacks) } } diff --git a/format.go b/format.go deleted file mode 100644 index 8a81ad7..0000000 --- a/format.go +++ /dev/null @@ -1,114 +0,0 @@ -package fgprof - -import ( - "fmt" - "io" - "sort" - "strings" - "time" - - "github.com/google/pprof/profile" -) - -// Format decides how the output is rendered to the user. -type Format string - -const ( - // FormatFolded is used by Brendan Gregg's FlameGraph utility, see - // https://github.com/brendangregg/FlameGraph#2-fold-stacks. - FormatFolded Format = "folded" - // FormatPprof is used by Google's pprof utility, see - // https://github.com/google/pprof/blob/master/proto/README.md. - FormatPprof Format = "pprof" -) - -func writeFormat(w io.Writer, s map[string]int, f Format, hz int, startTime, endTime time.Time) error { - switch f { - case FormatFolded: - return writeFolded(w, s) - case FormatPprof: - return toPprof(s, hz, startTime, endTime).Write(w) - default: - return fmt.Errorf("unknown format: %q", f) - } -} - -func writeFolded(w io.Writer, s map[string]int) error { - for _, stack := range sortedKeys(s) { - count := s[stack] - if _, err := fmt.Fprintf(w, "%s %d\n", stack, count); err != nil { - return err - } - } - return nil -} - -func toPprof(s map[string]int, hz int, startTime, endTime time.Time) *profile.Profile { - functionID := uint64(1) - locationID := uint64(1) - line := int64(1) - - p := &profile.Profile{} - m := &profile.Mapping{ID: 1, HasFunctions: true} - p.Period = int64(1e9 / hz) // Number of nanoseconds between samples. - p.TimeNanos = startTime.UnixNano() - p.DurationNanos = int64(endTime.Sub(startTime)) - p.Mapping = []*profile.Mapping{m} - p.SampleType = []*profile.ValueType{ - { - Type: "samples", - Unit: "count", - }, - { - Type: "time", - Unit: "nanoseconds", - }, - } - p.PeriodType = &profile.ValueType{ - Type: "wallclock", - Unit: "nanoseconds", - } - - for _, stack := range sortedKeys(s) { - count := s[stack] - sample := &profile.Sample{ - Value: []int64{ - int64(count), - int64(1000 * 1000 * 1000 / hz * count), - }, - } - for _, fnName := range strings.Split(stack, ";") { - function := &profile.Function{ - ID: functionID, - Name: fnName, - } - p.Function = append(p.Function, function) - - location := &profile.Location{ - ID: locationID, - Mapping: m, - Line: []profile.Line{{Function: function}}, - } - p.Location = append(p.Location, location) - sample.Location = append([]*profile.Location{location}, sample.Location...) - - line++ - - locationID++ - functionID++ - } - p.Sample = append(p.Sample, sample) - } - return p -} - -func sortedKeys(s map[string]int) []string { - keys := make([]string, len(s)) - i := 0 - for stack := range s { - keys[i] = stack - i++ - } - sort.Strings(keys) - return keys -} diff --git a/format_test.go b/format_test.go deleted file mode 100644 index f19263e..0000000 --- a/format_test.go +++ /dev/null @@ -1,46 +0,0 @@ -package fgprof - -import ( - "strings" - "testing" - "time" -) - -func Test_toPprof(t *testing.T) { - s := map[string]int{ - "foo;bar": 2, - "foo": 1, - } - - before := time.Local - defer func() { time.Local = before }() - time.Local = time.UTC - - start := time.Date(2022, 8, 27, 14, 32, 23, 0, time.UTC) - end := start.Add(time.Second) - p := toPprof(s, 99, start, end) - if err := p.CheckValid(); err != nil { - t.Fatal(err) - } - - want := strings.TrimSpace(` -PeriodType: wallclock nanoseconds -Period: 10101010 -Time: 2022-08-27 14:32:23 +0000 UTC -Duration: 1s -Samples: -samples/count time/nanoseconds - 1 10101010: 1 - 2 20202020: 3 2 -Locations - 1: 0x0 M=1 foo :0 s=0() - 2: 0x0 M=1 foo :0 s=0() - 3: 0x0 M=1 bar :0 s=0() -Mappings -1: 0x0/0x0/0x0 [FN] -`) - got := strings.TrimSpace(p.String()) - if want != got { - t.Fatalf("got:\n%s\n\nwant:\n%s", got, want) - } -} diff --git a/go.mod b/go.mod index 0e2e84c..ba0a67a 100644 --- a/go.mod +++ b/go.mod @@ -2,4 +2,7 @@ module github.com/felixge/fgprof go 1.14 -require github.com/google/pprof v0.0.0-20211214055906-6f57359322fd +require ( + github.com/google/pprof v0.0.0-20211214055906-6f57359322fd + github.com/stretchr/testify v1.8.0 +) diff --git a/go.sum b/go.sum index 374d31e..ade4ead 100644 --- a/go.sum +++ b/go.sum @@ -1,7 +1,22 @@ github.com/chzyer/logex v1.1.10/go.mod h1:+Ywpsq7O8HXn0nuIou7OrIPyXbp3wmkHB+jjWRnGsAI= github.com/chzyer/readline v0.0.0-20180603132655-2972be24d48e/go.mod h1:nSuG5e5PlCu98SY8svDHJxuZscDgtXS6KTTbou5AhLI= github.com/chzyer/test v0.0.0-20180213035817-a1ea475d72b1/go.mod h1:Q3SI9o4m/ZMnBNeIyt5eFwwo7qiLfzFZmjNmxjkiQlU= +github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= +github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= +github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/google/pprof v0.0.0-20211214055906-6f57359322fd h1:1FjCyPC+syAzJ5/2S8fqdZK1R22vvA0J7JZKcuOIQ7Y= github.com/google/pprof v0.0.0-20211214055906-6f57359322fd/go.mod h1:KgnwoLYCZ8IQu3XUZ8Nc/bM9CCZFOyjUNOSygVozoDg= github.com/ianlancetaylor/demangle v0.0.0-20210905161508-09a460cdf81d/go.mod h1:aYm2/VgdVmcIU8iMfdMvDMsRAQjcfZSKFby6HOFvi/w= +github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= +github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= +github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= +github.com/stretchr/objx v0.4.0/go.mod h1:YvHI0jy2hoMjB+UWwv71VJQ9isScKT/TqJzVSSt89Yw= +github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= +github.com/stretchr/testify v1.8.0 h1:pSgiaMZlXftHpm5L7V1+rVB+AZJydKsMxsQBIJw4PKk= +github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU= golang.org/x/sys v0.0.0-20211007075335-d3039528d8ac/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM= +gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= +gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= +gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA= +gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=