Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add a folded stacks output format #669

Closed
wants to merge 2 commits into from
Closed

Add a folded stacks output format #669

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
9288912
Rename some golden tests
mhansen Nov 8, 2021
dfdad6d
Add a folded stacks output format
mhansen Nov 8, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions doc/README.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -171,6 +171,8 @@ pprof text reports show the location hierarchy in text format.
* **-peek= _regex_:** Print the location entry with all its predecessors and
successors, without trimming any entries.
* **-traces:** Prints each sample with a location per line.
* **-folded:** Prints each sample in [Brendan Gregg's Folded Stacks
format](https://queue.acm.org/detail.cfm?id=2927301#:~:text=The%20folded%20stack%2Dtrace%20format,trace%2C%20followed%20by%20a%20semicolon.).

## Graphical reports

Expand Down
1 change: 1 addition & 0 deletions internal/driver/commands.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -93,6 +93,7 @@ var pprofCommands = commands{
"top": {report.Text, nil, nil, false, "Outputs top entries in text form", reportHelp("top", true, true)},
"traces": {report.Traces, nil, nil, false, "Outputs all profile samples in text form", ""},
"tree": {report.Tree, nil, nil, false, "Outputs a text rendering of call graph", reportHelp("tree", true, true)},
"folded": {report.Folded, nil, nil, false, "Outputs entries in folded stack form", reportHelp("folded", false, true)},

// Save binary formats to a file
"callgrind": {report.Callgrind, nil, awayFromTTY("callgraph.out"), false, "Outputs a graph in callgrind format", reportHelp("callgrind", false, true)},
Expand Down
52 changes: 52 additions & 0 deletions internal/report/report.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -48,6 +48,7 @@ const (
Traces
Tree
WebList
Folded
)

// Options are the formatting and filtering options used to generate a
Expand Down Expand Up @@ -94,6 +95,8 @@ func Generate(w io.Writer, rpt *Report, obj plugin.ObjTool) error {
return printDOT(w, rpt)
case Tree:
return printTree(w, rpt)
case Folded:
return printFolded(w, rpt)
case Text:
return printText(w, rpt)
case Traces:
Expand Down Expand Up @@ -828,6 +831,55 @@ func printText(w io.Writer, rpt *Report) error {
return nil
}

// printFolded prints a profile in Brendan Gregg's Folded Stacks format.
func printFolded(w io.Writer, rpt *Report) error {
prof := rpt.prof
o := rpt.options

_, locations := graph.CreateNodes(prof, &graph.Options{})
for _, sample := range prof.Sample {
var stack []*graph.NodeInfo
for _, loc := range sample.Location {
nodes := locations[loc.ID]
for _, n := range nodes {
stack = append(stack, &n.Info)
}
}

if len(stack) == 0 {
continue
}

var d, v int64
v = o.SampleValue(sample.Value)
if o.SampleMeanDivisor != nil {
d = o.SampleMeanDivisor(sample.Value)
}
if d != 0 {
v = v / d
}
// Print call stack.
for i := range stack {
// Folded stack convention: start with root frame, end
// with leaves.
s := stack[len(stack)-i-1]
if i > 0 {
fmt.Fprint(w, ";")
}
// TODO: should we print more than just s.Name?
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, I think this needs more discussion. There is an implicit interplay with the granularity. See below. I would expect that we utilize that - i.e. use PrintableName() or NameComponents() directly defining how they should join. This is in particular important because graph.CreateNodes() respects the granularity and so if we don't encode all components in the string, then something like "-folded -filefunctions" may produce duplicate elements.

$ pprof -top -nodecount=5 -symbolize=none internal/report/testdata/sample.cpu
File: sample.bin
Type: cpu
Time: Sep 29, 2017 at 1:57pm (PDT)
Duration: 2s, Total samples = 1760ms (87.91%)
Showing nodes accounting for 1640ms, 93.18% of 1760ms total
Showing top 5 nodes out of 14
      flat  flat%   sum%        cum   cum%
    1280ms 72.73% 72.73%     1370ms 77.84%  runtime.mapiternext
     150ms  8.52% 81.25%     1760ms   100%  main.busyLoop
     110ms  6.25% 87.50%      110ms  6.25%  math.Abs (inline)
      60ms  3.41% 90.91%       70ms  3.98%  runtime.evacuate
      40ms  2.27% 93.18%       40ms  2.27%  runtime.add (inline)
$ pprof -top -nodecount=5 -symbolize=none -filefunctions internal/report/testdata/sample.cpu
File: sample.bin
Type: cpu
Time: Sep 29, 2017 at 1:57pm (PDT)
Duration: 2s, Total samples = 1760ms (87.91%)
Showing nodes accounting for 1640ms, 93.18% of 1760ms total
Showing top 5 nodes out of 14
      flat  flat%   sum%        cum   cum%
    1280ms 72.73% 72.73%     1370ms 77.84%  runtime.mapiternext /usr/lib/google-golang/src/runtime/hashmap.go
     150ms  8.52% 81.25%     1760ms   100%  main.busyLoop internal/report/testdata/sample/sample.go
     110ms  6.25% 87.50%      110ms  6.25%  math.Abs /usr/lib/google-golang/src/math/abs.go (inline)
      60ms  3.41% 90.91%       70ms  3.98%  runtime.evacuate /usr/lib/google-golang/src/runtime/hashmap.go
      40ms  2.27% 93.18%       40ms  2.27%  runtime.add /usr/lib/google-golang/src/runtime/stubs.go (inline)
$ pprof -top -nodecount=5 -symbolize=none -files internal/report/testdata/sample.cpu
File: sample.bin
Type: cpu
Time: Sep 29, 2017 at 1:57pm (PDT)
Duration: 2s, Total samples = 1760ms (87.91%)
Showing nodes accounting for 1740ms, 98.86% of 1760ms total
Showing top 5 nodes out of 8
      flat  flat%   sum%        cum   cum%
    1400ms 79.55% 79.55%     1450ms 82.39%  /usr/lib/google-golang/src/runtime/hashmap.go
     150ms  8.52% 88.07%     1760ms   100%  internal/report/testdata/sample/sample.go
     110ms  6.25% 94.32%      110ms  6.25%  /usr/lib/google-golang/src/math/abs.go (inline)
      40ms  2.27% 96.59%      130ms  7.39%  /usr/lib/google-golang/src/runtime/hashmap_fast.go
      40ms  2.27% 98.86%       40ms  2.27%  /usr/lib/google-golang/src/runtime/stubs.go (inline)
$ pprof -top -nodecount=5 -symbolize=none -addresses internal/report/testdata/sample.cpu
File: sample.bin
Type: cpu
Time: Sep 29, 2017 at 1:57pm (PDT)
Duration: 2s, Total samples = 1760ms (87.91%)
Showing nodes accounting for 350ms, 19.89% of 1760ms total
Showing top 5 nodes out of 96
      flat  flat%   sum%        cum   cum%
     100ms  5.68%  5.68%      100ms  5.68%  00000000004b4463 math.Abs /usr/lib/google-golang/src/math/abs.go:16
      70ms  3.98%  9.66%       70ms  3.98%  00000000004095d0 runtime.mapiternext /usr/lib/google-golang/src/runtime/hashmap.go:823
      70ms  3.98% 13.64%       70ms  3.98%  00000000004096a2 runtime.mapiternext /usr/lib/google-golang/src/runtime/hashmap.go:856
      60ms  3.41% 17.05%       60ms  3.41%  000000000040957a runtime.mapiternext /usr/lib/google-golang/src/runtime/hashmap.go:819
      50ms  2.84% 19.89%       50ms  2.84%  00000000004095b6 runtime.mapiternext /usr/lib/google-golang/src/runtime/hashmap.go:822

// NodeInfo.PrintableName() has a lot more.

// Remove semicolons and newlines.
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Add a note on why?

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Err, didn't mean to click "Add single comment", I'll have more comments!

name := strings.ReplaceAll(s.Name, ";", "")
name = strings.ReplaceAll(name, "\n", "")
fmt.Fprint(w, name)
}
// We just want a raw number, so don't use rpt.formatValue().
fmt.Fprintf(w, " %d\n", v)
}
return nil
}

// printTraces prints all traces from a profile.
func printTraces(w io.Writer, rpt *Report) error {
fmt.Fprintln(w, strings.Join(ProfileLabels(rpt), "\n"))
Expand Down
50 changes: 45 additions & 5 deletions internal/report/report_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -33,9 +33,12 @@ type testcase struct {
want string
}

func TestSource(t *testing.T) {
func TestTextReports(t *testing.T) {
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could we have a separate test for the folded report? I find such combined meta-tests somewhat complicated... If this is to share setup / teardown code then maybe we can share it by other means?

const path = "testdata/"

sampleValue0 := func(v []int64) int64 {
return v[0]
}
sampleValue1 := func(v []int64) int64 {
return v[1]
}
Expand All @@ -53,7 +56,7 @@ func TestSource(t *testing.T) {
SampleUnit: testProfile.SampleType[1].Unit,
},
),
want: path + "source.rpt",
want: path + "report.source",
},
{
rpt: New(
Expand All @@ -68,7 +71,44 @@ func TestSource(t *testing.T) {
SampleUnit: testProfile.SampleType[1].Unit,
},
),
want: path + "source.dot",
want: path + "report.dot",
},
{
rpt: New(
testProfile.Copy(),
&Options{
OutputFormat: Folded,

SampleValue: sampleValue1,
SampleUnit: testProfile.SampleType[1].Unit,
},
),
want: path + "report.folded",
},
{
rpt: New(
testProfile.Copy(),
&Options{
OutputFormat: Folded,

SampleValue: sampleValue0,
SampleUnit: testProfile.SampleType[0].Unit,
},
),
want: path + "report0.folded",
},
{
rpt: New(
testProfile.Copy(),
&Options{
OutputFormat: Folded,

SampleValue: sampleValue1,
SampleUnit: testProfile.SampleType[1].Unit,
SampleMeanDivisor: sampleValue0,
},
),
want: path + "report_mean.folded",
},
} {
var b bytes.Buffer
Expand Down Expand Up @@ -169,7 +209,7 @@ var testF = []*profile.Function{
},
{
ID: 3,
Name: "bar",
Name: "b;ar",
Filename: "testdata/source1",
},
{
Expand Down Expand Up @@ -259,7 +299,7 @@ var testProfile = &profile.Profile{
},
{
Location: []*profile.Location{testL[4], testL[3], testL[0]},
Value: []int64{1, 10000},
Value: []int64{2, 10000},
},
},
Location: testL,
Expand Down
10 changes: 5 additions & 5 deletions internal/report/testdata/source.dot → internal/report/testdata/report.dot
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,13 +5,13 @@ N1 [label="tee\nsource2:8\n10000 (90.00%)" id="node1" fontsize=24 shape=box tool
N2 [label="main\nsource1:2\n1 (0.009%)\nof 11111 (100%)" id="node2" fontsize=9 shape=box tooltip="main testdata/source1:2 (11111)" color="#b20000" fillcolor="#edd5d5"]
N3 [label="tee\nsource2:2\n1000 (9.00%)\nof 11000 (99.00%)" id="node3" fontsize=14 shape=box tooltip="tee testdata/source2:2 (11000)" color="#b20000" fillcolor="#edd5d5"]
N4 [label="tee\nsource2:8\n100 (0.9%)" id="node4" fontsize=10 shape=box tooltip="tee testdata/source2:8 (100)" color="#b2b0aa" fillcolor="#edecec"]
N5 [label="bar\nsource1:10\n10 (0.09%)" id="node5" fontsize=9 shape=box tooltip="bar testdata/source1:10 (10)" color="#b2b2b1" fillcolor="#ededed"]
N6 [label="bar\nsource1:10\n0 of 100 (0.9%)" id="node6" fontsize=8 shape=box tooltip="bar testdata/source1:10 (100)" color="#b2b0aa" fillcolor="#edecec"]
N5 [label="b;ar\nsource1:10\n10 (0.09%)" id="node5" fontsize=9 shape=box tooltip="b;ar testdata/source1:10 (10)" color="#b2b2b1" fillcolor="#ededed"]
N6 [label="b;ar\nsource1:10\n0 of 100 (0.9%)" id="node6" fontsize=8 shape=box tooltip="b;ar testdata/source1:10 (100)" color="#b2b0aa" fillcolor="#edecec"]
N7 [label="foo\nsource1:4\n0 of 10 (0.09%)" id="node7" fontsize=8 shape=box tooltip="foo testdata/source1:4 (10)" color="#b2b2b1" fillcolor="#ededed"]
N2 -> N3 [label=" 11000" weight=100 penwidth=5 color="#b20000" tooltip="main testdata/source1:2 -> tee testdata/source2:2 (11000)" labeltooltip="main testdata/source1:2 -> tee testdata/source2:2 (11000)"]
N3 -> N1 [label=" 10000" weight=91 penwidth=5 color="#b20500" tooltip="tee testdata/source2:2 -> tee testdata/source2:8 (10000)" labeltooltip="tee testdata/source2:2 -> tee testdata/source2:8 (10000)"]
N6 -> N4 [label=" 100" color="#b2b0aa" tooltip="bar testdata/source1:10 -> tee testdata/source2:8 (100)" labeltooltip="bar testdata/source1:10 -> tee testdata/source2:8 (100)"]
N2 -> N6 [label=" 100" color="#b2b0aa" tooltip="main testdata/source1:2 -> bar testdata/source1:10 (100)" labeltooltip="main testdata/source1:2 -> bar testdata/source1:10 (100)"]
N7 -> N5 [label=" 10" color="#b2b2b1" tooltip="foo testdata/source1:4 -> bar testdata/source1:10 (10)" labeltooltip="foo testdata/source1:4 -> bar testdata/source1:10 (10)"]
N6 -> N4 [label=" 100" color="#b2b0aa" tooltip="b;ar testdata/source1:10 -> tee testdata/source2:8 (100)" labeltooltip="b;ar testdata/source1:10 -> tee testdata/source2:8 (100)"]
N2 -> N6 [label=" 100" color="#b2b0aa" tooltip="main testdata/source1:2 -> b;ar testdata/source1:10 (100)" labeltooltip="main testdata/source1:2 -> b;ar testdata/source1:10 (100)"]
N7 -> N5 [label=" 10" color="#b2b2b1" tooltip="foo testdata/source1:4 -> b;ar testdata/source1:10 (10)" labeltooltip="foo testdata/source1:4 -> b;ar testdata/source1:10 (10)"]
N2 -> N7 [label=" 10" color="#b2b2b1" tooltip="main testdata/source1:2 -> foo testdata/source1:4 (10)" labeltooltip="main testdata/source1:2 -> foo testdata/source1:4 (10)"]
}
5 changes: 5 additions & 0 deletions internal/report/testdata/report.folded
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,5 @@
main 1
main;foo;bar 10
main;bar;tee 100
main;tee 1000
main;tee;tee 10000
2 changes: 1 addition & 1 deletion internal/report/testdata/source.rpt → internal/report/testdata/report.source
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
Total: 11111
ROUTINE ======================== bar in testdata/source1
ROUTINE ======================== b;ar in testdata/source1
10 110 (flat, cum) 0.99% of Total
. . 5:source1 line 5;
. . 6:source1 line 6;
Expand Down
5 changes: 5 additions & 0 deletions internal/report/testdata/report0.folded
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,5 @@
main 1
main;foo;bar 1
main;bar;tee 1
main;tee 1
main;tee;tee 2
5 changes: 5 additions & 0 deletions internal/report/testdata/report_mean.folded
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,5 @@
main 1
main;foo;bar 10
main;bar;tee 100
main;tee 1000
main;tee;tee 5000