Implements https://github.com/google/pprof/issues/166

Details:

• Basic flame graph implementation under http output.
• Tested with both CPU and Memory profiles.
• Endpoint is /flamegraph, and there's a link in /,
• Opted not to use the directed graph to generate the flame graph since it doesn't have the detailed information required. Parsed the raw samples instead.
• Not doing any filtering in the samples.
• Output is mostly self-contained and could be saved. It should also be easy to add an option to export the html file.
• Making available all sample types in the UI, via a drop-down. e.g.: CPU profile will have samples and cpu.
• Displaying some profile metadata like profile time and duration.
• Converting nanoseconds to seconds. I'm not sure if this is ideal, but same thing is being done in the main view. Happy to revert it if necessary.
• Using a bootstrap layout now, but happy to revert it if you believe it would be better to keep a simple layout without the bootstrap dependency.
• Implements all features mentioned by @brendangregg, except different palettes, which is under development and requires changes in the D3 plugin.
• We are continuously adding more features to the D3 plugin, and those should be easily assimilated by this.

A demo can be found in pprof_flame.html

Happy to make any changes deemed necessary.

TL;DR

Things included in this PR:

• Added a Github Action script draft (macOS, Linux and Windows test).

Follow-up plan:

• Verify the correctness of the draft.

• Remove working {Go, OS, XCode} sections that are covered by this Github Action script from existing CI scripts.

• Add build badge to README.md.

• Enable Github Action as part of PR review process.

Details

Why it is only a draft?

The Github Action script (i.e. ci.yaml) is first introduced in this PR. That means any change made to ci.yaml can be only tested on the forked repo (i.e. it will trigger the Github Action on the forked repo if a commit is pushed to the master branch). This seems to be the intentional behavior as noted here.

Limitations

1. The master branch of Go is not supported by setup-go. There is an open PR that is working on this: https://github.com/actions/setup-go/pull/34, but no progress has been made since March and no ETA.

2. Only the latest macOS is supported: https://help.github.com/en/actions/reference/workflow-syntax-for-github-actions#jobsjob_idruns-on.

3. Limited number of XCode versions are supported: https://github.com/actions/virtual-environments/blob/master/images/macos/macos-10.15-Readme.md#xcode, but this should not be an issue for us as we wouldn't support anything older than XCode 10.3.

Solution

We will keep the tests for {GO, OS, XCode} combination that are not currently supported by Github Action in existing CI scripts. Ideally, we will only need to maintain one CI.

Encountered in https://go-review.googlesource.com/c/go/+/89715, after trying to update the vendored copy to pull https://github.com/google/pprof/pull/298.

https://storage.googleapis.com/go-build-log/b9cbc869/freebsd-amd64-11_1_dbe018c1.log

Relevant bit of output:

Generating report in /tmp/profile_proto401663026
Generating report in /tmp/profile_output286659561
Generating report in /tmp/profile_proto375996468
Generating report in /tmp/profile_output864397315
Generating report in /tmp/profile_proto039962502
Generating report in /tmp/profile_output187100461
Generating report in /tmp/profile_proto409183912
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output785726951
Generating report in /tmp/profile_proto884247066
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output637371569
Generating report in /tmp/profile_proto247173724
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output097694731
Generating report in /tmp/profile_proto492795374
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output034252917
Generating report in /tmp/profile_proto368253776
Generating report in /tmp/profile_output322350703
Generating report in /tmp/profile_proto977961218
Generating report in /tmp/profile_output894972025
Generating report in /tmp/profile_proto420701572
Generating report in /tmp/profile_output650228499
Generating report in /tmp/profile_proto732512086
Hide expression matched no samples
Generating report in /tmp/profile_output521628349
Generating report in /tmp/profile_proto277399288
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output057706487
Generating report in /tmp/profile_proto464104682
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output775549761
Generating report in /tmp/profile_proto674043820
Generating report in /tmp/profile_output590092059
Generating report in /tmp/profile_proto546088894
Generating report in /tmp/profile_output341598725
Generating report in /tmp/profile_proto335752608
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output184212607
Generating report in /tmp/profile_proto241410002
Generating report in /tmp/profile_output195271945
Generating report in /tmp/profile_proto261196500
Generating report in /tmp/profile_output463594531
Generating report in /tmp/profile_proto185480486
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output325258317
Generating report in /tmp/profile_proto806478664
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output207366663
Generating report in /tmp/profile_proto501424570
Ignoring local file /path/to/buildid-contention: build-id mismatch (buildid-contention != abcdef)
Generating report in /tmp/profile_output341586385
Generating report in /tmp/profile_proto104851196
Ignoring local file /path/to/buildid-contention: build-id mismatch (buildid-contention != abcdef)
Generating report in /tmp/profile_output663387691
Generating report in /tmp/profile_proto116933518
Generating report in /tmp/profile_output450033045
Generating report in /tmp/profile_proto727070192
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output899511951
Generating report in /tmp/profile_proto393553058
Generating report in /tmp/profile_output289885081
Generating report in /tmp/profile_proto251520548
TagHide expression matched no samples
Generating report in /tmp/profile_output935486259
Generating report in /tmp/profile_proto094535926
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output083339741
Generating report in /tmp/profile_proto156133272
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output277399063
Generating report in /tmp/profile_proto935120522
Generating report in /tmp/profile_output201512033
Generating report in /tmp/profile_proto273219660
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output809429307
Generating report in /tmp/profile_proto478786910
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output347197221
TagShow expression matched no samples
Generating report in /tmp/profile_proto927775296
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
TagShow expression matched no samples
Generating report in /tmp/profile_output452561567
Generating report in /tmp/profile_proto655736690
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output707493929
Generating report in /tmp/profile_proto176749940
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
tagfocus:Interpreted '1mb:2gb' as range, not regexp
Generating report in /tmp/profile_output117007939
Generating report in /tmp/profile_proto814631622
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
tagfocus:Interpreted '30kb:' as range, not regexp
tagignore:Interpreted '1mb:2mb' as range, not regexp
TagHide expression matched no samples
Generating report in /tmp/profile_output373592941
Generating report in /tmp/profile_proto043137512
Generating report in /tmp/profile_output260846631
Generating report in /tmp/profile_proto961517402
Generating report in /tmp/profile_output118255345
Generating report in /tmp/profile_proto014898588
Generating report in /tmp/profile_output779428427
Generating report in /tmp/profile_proto014254894
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
tagfocus:Interpreted '400kb:' as range, not regexp
Generating report in /tmp/profile_output616030389
Local symbolization failed for cppbench_server_main: stat cppbench_server_main: no such file or directory
Local symbolization failed for libpthread-2.15.so: stat /libpthread-2.15.so: no such file or directory
Some binary filenames not available. Symbolization may be incomplete.
Try setting PPROF_BINARY_PATH to the search path for local binaries.
Local symbolization failed for cppbench_server_main: stat cppbench_server_main: no such file or directory
Local symbolization failed for libpthread-2.15.so: stat /libpthread-2.15.so: no such file or directory
Some binary filenames not available. Symbolization may be incomplete.
Try setting PPROF_BINARY_PATH to the search path for local binaries.
Local symbolization failed for cppbench_server_main: stat cppbench_server_main: no such file or directory
Local symbolization failed for libpthread-2.15.so: stat /libpthread-2.15.so: no such file or directory
Some binary filenames not available. Symbolization may be incomplete.
Try setting PPROF_BINARY_PATH to the search path for local binaries.
2018/01/29 12:10:32 httptest.Server blocked in Close after 5 seconds, waiting for connections:
  *net.TCPConn 0xc420186210 127.0.0.1:51135 in state active
panic: test timed out after 3m0s

goroutine 455 [running]:
testing.(*M).startAlarm.func1()
	/tmp/workdir/go/src/testing/testing.go:1240 +0xfc
created by time.goFunc
	/tmp/workdir/go/src/time/sleep.go:172 +0x44

goroutine 1 [chan receive, 2 minutes]:
testing.(*T).Run(0xc4203f22d0, 0x93756e, 0x10, 0x985408, 0x47a601)
	/tmp/workdir/go/src/testing/testing.go:825 +0x301
testing.runTests.func1(0xc4201ca000)
	/tmp/workdir/go/src/testing/testing.go:1063 +0x64
testing.tRunner(0xc4201ca000, 0xc420063df8)
	/tmp/workdir/go/src/testing/testing.go:777 +0xd0
testing.runTests(0xc420182480, 0xbfbe20, 0x10, 0x10, 0x4115e9)
	/tmp/workdir/go/src/testing/testing.go:1061 +0x2c4
testing.(*M).Run(0xc42018c280, 0x0)
	/tmp/workdir/go/src/testing/testing.go:978 +0x171
main.main()
	_testmain.go:72 +0x151

goroutine 360 [semacquire, 2 minutes]:
sync.runtime_Semacquire(0xc4201965f4)
	/tmp/workdir/go/src/runtime/sema.go:56 +0x39
sync.(*WaitGroup).Wait(0xc4201965e8)
	/tmp/workdir/go/src/sync/waitgroup.go:129 +0x72
net/http/httptest.(*Server).Close(0xc4201965b0)
	/tmp/workdir/go/src/net/http/httptest/server.go:221 +0x208
cmd/vendor/github.com/google/pprof/internal/driver.TestWebInterface(0xc4203f22d0)
	/tmp/workdir/go/src/cmd/vendor/github.com/google/pprof/internal/driver/webui_test.go:128 +0xded
testing.tRunner(0xc4203f22d0, 0x985408)
	/tmp/workdir/go/src/testing/testing.go:777 +0xd0
created by testing.(*T).Run
	/tmp/workdir/go/src/testing/testing.go:824 +0x2e0

goroutine 46 [select, 2 minutes]:
net/http.(*persistConn).writeLoop(0xc420550000)
	/tmp/workdir/go/src/net/http/transport.go:1822 +0x14b
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1238 +0x97f

goroutine 44 [IO wait, 2 minutes]:
internal/poll.runtime_pollWait(0x800c7a688, 0x72, 0xc420052620)
	/tmp/workdir/go/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc42014c018, 0x72, 0xffffffffffffff00, 0x9c46e0, 0xbc55c8)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:85 +0x9b
internal/poll.(*pollDesc).waitRead(0xc42014c018, 0xc4200bc000, 0x400, 0x400)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc42014c000, 0xc4200bc000, 0x400, 0x400, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/internal/poll/fd_unix.go:157 +0x17d
net.(*netFD).Read(0xc42014c000, 0xc4200bc000, 0x400, 0x400, 0x100c420052730, 0x18, 0x28)
	/tmp/workdir/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc4201a0000, 0xc4200bc000, 0x400, 0x400, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/net/net.go:176 +0x6a
crypto/tls.(*block).readFromUntil(0xc420180570, 0x800d0ccd0, 0xc4201a0000, 0x5, 0xc4201a0000, 0xc420344000)
	/tmp/workdir/go/src/crypto/tls/conn.go:493 +0x96
crypto/tls.(*Conn).readRecord(0xc42009e380, 0x986517, 0xc42009e4a0, 0xc420052978)
	/tmp/workdir/go/src/crypto/tls/conn.go:595 +0xe0
crypto/tls.(*Conn).Read(0xc42009e380, 0xc420337000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/crypto/tls/conn.go:1156 +0x100
net/http.(*connReader).Read(0xc420180cc0, 0xc420337000, 0x1000, 0x1000, 0xc42014c000, 0x800c0a000, 0x3)
	/tmp/workdir/go/src/net/http/server.go:764 +0xf8
bufio.(*Reader).fill(0xc4200705a0)
	/tmp/workdir/go/src/bufio/bufio.go:100 +0x11e
bufio.(*Reader).ReadSlice(0xc4200705a0, 0xc420052a0a, 0xc420052ad8, 0x411156, 0x800c76fb0, 0x1, 0xc420052ab8)
	/tmp/workdir/go/src/bufio/bufio.go:341 +0x2c
bufio.(*Reader).ReadLine(0xc4200705a0, 0xc42044c100, 0x100, 0xf8, 0x921700, 0x1, 0x100c420043800)
	/tmp/workdir/go/src/bufio/bufio.go:370 +0x34
net/textproto.(*Reader).readLineSlice(0xc420176300, 0xc42031c401, 0xc420052ba8, 0x411e38, 0x100, 0x921700)
	/tmp/workdir/go/src/net/textproto/reader.go:55 +0x70
net/textproto.(*Reader).ReadLine(0xc420176300, 0xc42044c100, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/net/textproto/reader.go:36 +0x2b
net/http.readRequest(0xc4200705a0, 0x0, 0xc42044c100, 0x0, 0x0)
	/tmp/workdir/go/src/net/http/request.go:929 +0x8c
net/http.(*conn).readRequest(0xc420348000, 0x9c8420, 0xc4202a8240, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/net/http/server.go:944 +0x16f
net/http.(*conn).serve(0xc420348000, 0x9c8420, 0xc4202a8240)
	/tmp/workdir/go/src/net/http/server.go:1768 +0x4dc
created by net/http.(*Server).Serve
	/tmp/workdir/go/src/net/http/server.go:2795 +0x27b

goroutine 453 [IO wait, 2 minutes]:
internal/poll.runtime_pollWait(0x800c79f38, 0x72, 0xc4203e6e58)
	/tmp/workdir/go/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc42014c598, 0x72, 0xffffffffffffff00, 0x9c46e0, 0xbc55c8)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:85 +0x9b
internal/poll.(*pollDesc).waitRead(0xc42014c598, 0xc42016ed00, 0x1, 0x1)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc42014c580, 0xc42016edf1, 0x1, 0x1, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/internal/poll/fd_unix.go:157 +0x17d
net.(*netFD).Read(0xc42014c580, 0xc42016edf1, 0x1, 0x1, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc420186210, 0xc42016edf1, 0x1, 0x1, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/net/net.go:176 +0x6a
net/http.(*connReader).backgroundRead(0xc42016ede0)
	/tmp/workdir/go/src/net/http/server.go:668 +0x5a
created by net/http.(*connReader).startBackgroundRead
	/tmp/workdir/go/src/net/http/server.go:664 +0xce

goroutine 267 [select, 2 minutes]:
net/http.(*persistConn).readLoop(0xc42031e360)
	/tmp/workdir/go/src/net/http/transport.go:1717 +0x743
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1237 +0x95a

goroutine 45 [IO wait, 2 minutes]:
internal/poll.runtime_pollWait(0x800c7a758, 0x72, 0xc420494760)
	/tmp/workdir/go/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc4202f0218, 0x72, 0xffffffffffffff00, 0x9c46e0, 0xbc55c8)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:85 +0x9b
internal/poll.(*pollDesc).waitRead(0xc4202f0218, 0xc4200ce400, 0x400, 0x400)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc4202f0200, 0xc4200ce400, 0x400, 0x400, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/internal/poll/fd_unix.go:157 +0x17d
net.(*netFD).Read(0xc4202f0200, 0xc4200ce400, 0x400, 0x400, 0xc4204948e0, 0xc4204948e8, 0x4115e9)
	/tmp/workdir/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc42000e040, 0xc4200ce400, 0x400, 0x400, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/net/net.go:176 +0x6a
crypto/tls.(*block).readFromUntil(0xc420504360, 0x800d0ccd0, 0xc42000e040, 0x5, 0xc42000e040, 0x411e38)
	/tmp/workdir/go/src/crypto/tls/conn.go:493 +0x96
crypto/tls.(*Conn).readRecord(0xc4201b5500, 0x986517, 0xc4201b5620, 0x456170)
	/tmp/workdir/go/src/crypto/tls/conn.go:595 +0xe0
crypto/tls.(*Conn).Read(0xc4201b5500, 0xc4202e7000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/crypto/tls/conn.go:1156 +0x100
net/http.(*persistConn).Read(0xc420550000, 0xc4202e7000, 0x1000, 0x1000, 0xc420494b98, 0x404985, 0xc4204063c0)
	/tmp/workdir/go/src/net/http/transport.go:1453 +0x136
bufio.(*Reader).fill(0xc420070660)
	/tmp/workdir/go/src/bufio/bufio.go:100 +0x11e
bufio.(*Reader).Peek(0xc420070660, 0x1, 0x0, 0x0, 0x0, 0xc420406300, 0x0)
	/tmp/workdir/go/src/bufio/bufio.go:132 +0x3a
net/http.(*persistConn).readLoop(0xc420550000)
	/tmp/workdir/go/src/net/http/transport.go:1601 +0x185
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1237 +0x95a

goroutine 435 [select, 2 minutes]:
net/http.(*persistConn).readLoop(0xc4201ceb40)
	/tmp/workdir/go/src/net/http/transport.go:1717 +0x743
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1237 +0x95a

goroutine 399 [select, 2 minutes]:
net/http.(*persistConn).readLoop(0xc420550120)
	/tmp/workdir/go/src/net/http/transport.go:1717 +0x743
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1237 +0x95a

goroutine 434 [select, 2 minutes]:
net/http.(*persistConn).writeLoop(0xc4200b90e0)
	/tmp/workdir/go/src/net/http/transport.go:1822 +0x14b
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1238 +0x97f

goroutine 388 [select, 2 minutes]:
net/http.(*persistConn).readLoop(0xc4200b8ea0)
	/tmp/workdir/go/src/net/http/transport.go:1717 +0x743
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1237 +0x95a

goroutine 389 [select, 2 minutes]:
net/http.(*persistConn).writeLoop(0xc4200b8ea0)
	/tmp/workdir/go/src/net/http/transport.go:1822 +0x14b
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1238 +0x97f

goroutine 436 [select, 2 minutes]:
net/http.(*persistConn).writeLoop(0xc4201ceb40)
	/tmp/workdir/go/src/net/http/transport.go:1822 +0x14b
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1238 +0x97f

goroutine 400 [select, 2 minutes]:
net/http.(*persistConn).writeLoop(0xc420550120)
	/tmp/workdir/go/src/net/http/transport.go:1822 +0x14b
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1238 +0x97f

goroutine 268 [select, 2 minutes]:
net/http.(*persistConn).writeLoop(0xc42031e360)
	/tmp/workdir/go/src/net/http/transport.go:1822 +0x14b
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1238 +0x97f

goroutine 401 [select, 2 minutes]:
net/http.(*persistConn).readLoop(0xc4200b90e0)
	/tmp/workdir/go/src/net/http/transport.go:1717 +0x743
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1237 +0x95a

goroutine 405 [IO wait, 2 minutes]:
internal/poll.runtime_pollWait(0x800c79f38, 0x77, 0xc420697328)
	/tmp/workdir/go/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc42014c598, 0x77, 0xffffffffffffff00, 0x9c46e0, 0xbc55c8)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:85 +0x9b
internal/poll.(*pollDesc).waitWrite(0xc42014c598, 0xc420258e00, 0x74f0, 0xa786)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:94 +0x3d
internal/poll.(*FD).Write(0xc42014c580, 0xc420236f8c, 0x2938c, 0x2c622, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/internal/poll/fd_unix.go:264 +0x237
net.(*netFD).Write(0xc42014c580, 0xc420236f8c, 0x2938c, 0x2c622, 0x0, 0x0, 0xbf4090)
	/tmp/workdir/go/src/net/fd_unix.go:220 +0x4f
net.(*conn).Write(0xc420186210, 0xc420236f8c, 0x2938c, 0x2c622, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/net/net.go:188 +0x6a
net/http.checkConnErrorWriter.Write(0xc42019b220, 0xc420236f8c, 0x2938c, 0x2c622, 0x7, 0x0, 0x0)
	/tmp/workdir/go/src/net/http/server.go:3313 +0x56
bufio.(*Writer).Write(0xc42017de40, 0xc420236f8c, 0x2a318, 0x2c622, 0xc420697598, 0x1, 0x1)
	/tmp/workdir/go/src/bufio/bufio.go:605 +0x14d
net/http.(*chunkWriter).Write(0xc42034c3b8, 0xc420236000, 0x2a318, 0x2d5ae, 0xc4206975f0, 0xc420697610, 0xc42034c3c0)
	/tmp/workdir/go/src/net/http/server.go:372 +0xab
bufio.(*Writer).Write(0xc42017c880, 0xc420236000, 0x2a318, 0x2d5ae, 0x8d4a60, 0xc42016eed0, 0x9348da)
	/tmp/workdir/go/src/bufio/bufio.go:605 +0x14d
net/http.(*response).write(0xc42034c380, 0x2a318, 0xc420236000, 0x2a318, 0x2d5ae, 0x0, 0x0, 0xc, 0x933115, 0x9)
	/tmp/workdir/go/src/net/http/server.go:1529 +0x142
net/http.(*response).Write(0xc42034c380, 0xc420236000, 0x2a318, 0x2d5ae, 0x9, 0x90fb40, 0xc4203fa0c0)
	/tmp/workdir/go/src/net/http/server.go:1499 +0x56
cmd/vendor/github.com/google/pprof/internal/driver.(*webInterface).render(0xc420182860, 0x9c7fa0, 0xc42034c380, 0x933e68, 0xb, 0x9339fc, 0xa, 0xc4203447e0, 0x0, 0x0, ...)
	/tmp/workdir/go/src/cmd/vendor/github.com/google/pprof/internal/driver/webui.go:249 +0x45a
cmd/vendor/github.com/google/pprof/internal/driver.(*webInterface).flamegraph(0xc420182860, 0x9c7fa0, 0xc42034c380, 0xc420122d00)
	/tmp/workdir/go/src/cmd/vendor/github.com/google/pprof/internal/driver/flamegraph.go:95 +0xd56
cmd/vendor/github.com/google/pprof/internal/driver.(*webInterface).(cmd/vendor/github.com/google/pprof/internal/driver.flamegraph)-fm(0x9c7fa0, 0xc42034c380, 0xc420122d00)
	/tmp/workdir/go/src/cmd/vendor/github.com/google/pprof/internal/driver/webui.go:124 +0x48
net/http.HandlerFunc.ServeHTTP(0xc42013e830, 0x9c7fa0, 0xc42034c380, 0xc420122d00)
	/tmp/workdir/go/src/net/http/server.go:1947 +0x44
cmd/vendor/github.com/google/pprof/internal/driver.TestWebInterface.func1.1(0x9c7fa0, 0xc42034c380, 0xc420122d00)
	/tmp/workdir/go/src/cmd/vendor/github.com/google/pprof/internal/driver/webui_test.go:48 +0x9c
net/http.HandlerFunc.ServeHTTP(0xc42013e840, 0x9c7fa0, 0xc42034c380, 0xc420122d00)
	/tmp/workdir/go/src/net/http/server.go:1947 +0x44
net/http.serverHandler.ServeHTTP(0xc420095520, 0x9c7fa0, 0xc42034c380, 0xc420122d00)
	/tmp/workdir/go/src/net/http/server.go:2694 +0xbc
net/http.(*conn).serve(0xc42019b220, 0x9c8420, 0xc42017de00)
	/tmp/workdir/go/src/net/http/server.go:1830 +0x651
created by net/http.(*Server).Serve
	/tmp/workdir/go/src/net/http/server.go:2795 +0x27b

goroutine 397 [select, 2 minutes]:
net/http.(*persistConn).readLoop(0xc4201cec60)
	/tmp/workdir/go/src/net/http/transport.go:1717 +0x743
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1237 +0x95a

goroutine 398 [select, 2 minutes]:
net/http.(*persistConn).writeLoop(0xc4201cec60)
	/tmp/workdir/go/src/net/http/transport.go:1822 +0x14b
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1238 +0x97f

goroutine 270 [select, 2 minutes]:
net/http.(*persistConn).readLoop(0xc42031e480)
	/tmp/workdir/go/src/net/http/transport.go:1717 +0x743
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1237 +0x95a

goroutine 271 [select, 2 minutes]:
net/http.(*persistConn).writeLoop(0xc42031e480)
	/tmp/workdir/go/src/net/http/transport.go:1822 +0x14b
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1238 +0x97f

goroutine 273 [select, 2 minutes]:
net/http.(*persistConn).readLoop(0xc42031e5a0)
	/tmp/workdir/go/src/net/http/transport.go:1717 +0x743
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1237 +0x95a

goroutine 418 [select, 2 minutes]:
net/http.(*persistConn).writeLoop(0xc42031e5a0)
	/tmp/workdir/go/src/net/http/transport.go:1822 +0x14b
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1238 +0x97f

goroutine 420 [select, 2 minutes]:
net/http.(*persistConn).readLoop(0xc42031e900)
	/tmp/workdir/go/src/net/http/transport.go:1717 +0x743
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1237 +0x95a

goroutine 421 [select, 2 minutes]:
net/http.(*persistConn).writeLoop(0xc42031e900)
	/tmp/workdir/go/src/net/http/transport.go:1822 +0x14b
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1238 +0x97f

goroutine 423 [select, 2 minutes]:
net/http.(*persistConn).readLoop(0xc42031ea20)
	/tmp/workdir/go/src/net/http/transport.go:1717 +0x743
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1237 +0x95a

goroutine 424 [select, 2 minutes]:
net/http.(*persistConn).writeLoop(0xc42031ea20)
	/tmp/workdir/go/src/net/http/transport.go:1822 +0x14b
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1238 +0x97f
FAIL	cmd/vendor/github.com/google/pprof/internal/driver	180.119s
2018/01/29 12:13:17 Failed: exit status 1

Flame graphs allow you to move in a specific ancestry path from a very compact UI and lets the users to zoom in/out specific paths easily. Flame graphs became one of the defato representation of profiling data in the industry in the recent years, e.g. go-torch is a highly successful tool and often user's entry point to visualize pprof data in Go.

Consider supporting flame graphs in addition to the dot visualization on the new web UI, so we can provide this representation out-of-the-box with minimal setup and external dependencies.

(If you need this feature as well, you can 👍 so the team knows about your interest.)

Fixes #544.

Add support for LLVM nm.

Tesed llvm-nm:

• macOS
  • macOS 10.15.4, Xcode 11.5, Apple LLVM version 11.0.3
• Linux
  • latest
  • 9
  • 8

Tested gnm on macOS.

pprof only uses "-n" option from nm and this option is supported across version and publisher (i.e llvm or GNU). They all pass the unit tests and have interchangeable outputs (i.e. the order of a few entries is different) comparing to nm for our purposes.

Testings on other versions of llvm-nm is omitted since llvm-nm has stable output since the introduction of -n option in https://github.com/llvm/llvm-project/commit/b8672a50c08dcd8b4805f4ca4b33354acc3c127c.

See @MaskRay 's comments below for more context.

Full log: https://storage.googleapis.com/go-build-log/198cc863/openbsd-amd64-62_382c8558.log

Interesting part:

Generating report in /tmp/profile_proto127733951
Generating report in /tmp/profile_output976672530
Generating report in /tmp/profile_proto864760137
Generating report in /tmp/profile_output749897236
Generating report in /tmp/profile_proto674757731
Generating report in /tmp/profile_output998323814
Generating report in /tmp/profile_proto228678285
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output259635848
Generating report in /tmp/profile_proto174538311
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output131752698
Generating report in /tmp/profile_proto182942225
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output948220476
Generating report in /tmp/profile_proto644947563
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output820104910
Generating report in /tmp/profile_proto172666325
Generating report in /tmp/profile_output310512944
Generating report in /tmp/profile_proto416149711
Generating report in /tmp/profile_output955108834
Generating report in /tmp/profile_proto134901721
Generating report in /tmp/profile_output655382884
Generating report in /tmp/profile_proto990546803
Hide expression matched no samples
Generating report in /tmp/profile_output065374262
Generating report in /tmp/profile_proto189982237
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output344876760
Generating report in /tmp/profile_proto098495063
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output391055306
Generating report in /tmp/profile_proto873545889
Generating report in /tmp/profile_output950568844
Generating report in /tmp/profile_proto350487931
Generating report in /tmp/profile_output148036254
Generating report in /tmp/profile_proto238922597
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output361437056
Generating report in /tmp/profile_proto859589343
Generating report in /tmp/profile_output948475570
Generating report in /tmp/profile_proto888026217
Generating report in /tmp/profile_output462067892
Generating report in /tmp/profile_proto216871555
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output432729094
Generating report in /tmp/profile_proto753219501
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output419030824
Generating report in /tmp/profile_proto161255527
Ignoring local file /path/to/buildid-contention: build-id mismatch (buildid-contention != abcdef)
Generating report in /tmp/profile_output262854298
Generating report in /tmp/profile_proto245839153
Ignoring local file /path/to/buildid-contention: build-id mismatch (buildid-contention != abcdef)
Generating report in /tmp/profile_output420925148
Generating report in /tmp/profile_proto344449675
Generating report in /tmp/profile_output334905966
Generating report in /tmp/profile_proto050744565
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output992652240
Generating report in /tmp/profile_proto759083759
Generating report in /tmp/profile_output162414466
Generating report in /tmp/profile_proto365944057
TagHide expression matched no samples
Generating report in /tmp/profile_output107096068
Generating report in /tmp/profile_proto478871443
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output781034966
Generating report in /tmp/profile_proto208459069
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output901856120
Generating report in /tmp/profile_proto196185719
Generating report in /tmp/profile_output094373226
Generating report in /tmp/profile_proto848061889
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output292484140
Generating report in /tmp/profile_proto123168155
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output518198334
TagShow expression matched no samples
Generating report in /tmp/profile_proto943217797
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
TagShow expression matched no samples
Generating report in /tmp/profile_output876305952
Generating report in /tmp/profile_proto694926591
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
Generating report in /tmp/profile_output105629778
Generating report in /tmp/profile_proto552467849
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
tagfocus:Interpreted '1mb:2gb' as range, not regexp
Generating report in /tmp/profile_output486548308
Generating report in /tmp/profile_proto752542883
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
tagfocus:Interpreted '30kb:' as range, not regexp
tagignore:Interpreted '1mb:2mb' as range, not regexp
TagHide expression matched no samples
Generating report in /tmp/profile_output913352614
Generating report in /tmp/profile_proto318557389
Generating report in /tmp/profile_output348401096
Generating report in /tmp/profile_proto892583047
Generating report in /tmp/profile_output133244986
Generating report in /tmp/profile_proto556095569
Generating report in /tmp/profile_output653629820
Generating report in /tmp/profile_proto463020715
Ignoring local file /path/to/buildid: build-id mismatch (buildid != abcdef)
tagfocus:Interpreted '400kb:' as range, not regexp
Generating report in /tmp/profile_output997609486
Local symbolization failed for cppbench_server_main: stat cppbench_server_main: no such file or directory
Local symbolization failed for libpthread-2.15.so: stat /libpthread-2.15.so: no such file or directory
Some binary filenames not available. Symbolization may be incomplete.
Try setting PPROF_BINARY_PATH to the search path for local binaries.
Local symbolization failed for cppbench_server_main: stat cppbench_server_main: no such file or directory
Local symbolization failed for libpthread-2.15.so: stat /libpthread-2.15.so: no such file or directory
Some binary filenames not available. Symbolization may be incomplete.
Try setting PPROF_BINARY_PATH to the search path for local binaries.
Local symbolization failed for cppbench_server_main: stat cppbench_server_main: no such file or directory
Local symbolization failed for libpthread-2.15.so: stat /libpthread-2.15.so: no such file or directory
Some binary filenames not available. Symbolization may be incomplete.
Try setting PPROF_BINARY_PATH to the search path for local binaries.
--- FAIL: TestHttpsInsecure (15.03s)
	proftest.go:114: https+insecure://127.0.0.1:28700/debug/pprof/profile: http fetch: Get https://127.0.0.1:28700/debug/pprof/profile?seconds=10: net/http: timeout awaiting response headers
	fetch_test.go:426: failed to fetch any source profiles
FAIL
FAIL	cmd/vendor/github.com/google/pprof/internal/driver	17.284s

This is with the vendored version in the Go tree, which is 0e0e5b7254e076a62326ab7305ba49e8515f0c91.

Also, the tests are very noisy. Is this intended? You can see that the rest of the standard library tests are all quiet by default, as they should be. Perhaps these logs should be hidden behind testing.Verbose().

In some programming languages, e.g. JuliaLang, function names can contain arbitrary characters. For example, in julia, functions with non-identifier characters are represented via the string macro var"...", which allows constructing identifiers that wouldn't otherwise parse.

These names are handled correctly by pprof in the FlameGraph view, but before this commit, they would produce an invalid dot file.

This fixes the dot graph export for names that contain ".

Review Guidelines

• All of the code changes are in the internal/graph/dotgraph.go file, and consist of escaping a few more callsites that produce text that will go in a string in the .dot file.
• The rest of the files are modifications to the tests:
  1. We added a new test to test string escaping in the newly escaped parts of the .dot file.
  2. We fixed a bunch of windows tests, which were previously validating incorrect escaping of \, and had to be updated once we started correctly escaping "...\..." to "...\\..." on Windows.

Fixes https://github.com/JuliaPerf/PProf.jl/issues/30.

The issue was noticed in #111.

Test server:

package main

import (
  "log"
  "net/http"
  _ "net/http/pprof"
)

func run() {
  for {
  }
}

func main() {
  go func() {
    log.Println(http.ListenAndServe("localhost:6060", nil))
  }()
  run()
}

Running it as go run server.go and profiling as "pprof -symbolize=remote localhost:6060/debug/pprof/profile?seconds=5" produces unknown symbol on OSX with Go 1.8. Doing the same with Go 1.7.5 produces correctly symbolized output.

Looking at "-raw" output for the Go 1.8 vs. 1.7.5 profiles, there is a difference in the mapping section:

Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?seconds=5
Saved profile in /Users/aalexand/pprof/pprof.samples.cpu.011.pb.gz
Type: cpu
Time: Mar 15, 2017 at 1:08pm (PDT)
Duration: 5s, Total samples = 4.29s (85.74%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) raw
PeriodType: cpu nanoseconds
Period: 10000000
Time: 2017-03-15 13:08:32.787861506 -0700 PDT
Duration: 5.00
Samples:
samples/count cpu/nanoseconds
         83  830000000: 1 2 3 4 
          1   10000000: 5 6 7 3 4 
        345 3450000000: 8 9 10 11 
Locations
     1: 0x105adc6 
     2: 0x1037612 
     3: 0x10309cd 
     4: 0x10308a3 
     5: 0x105abc6 
     6: 0x105abf4 
     7: 0x1037726 
     8: 0x1311630 
     9: 0x1311679 
    10: 0x102dad9 
    11: 0x1059af0 
Mappings

with Go 1.8 vs.

Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?seconds=5
Saved profile in /Users/aalexand/pprof/pprof.samples.cpu.012.pb.gz
Type: cpu
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) raw
PeriodType: cpu nanoseconds
Period: 10000000
Samples:
samples/count cpu/nanoseconds
        388 3880000000: 1 2 3 4 
         37  370000000: 5 6 7 8 
Locations
     1: 0x2040 M=1 main.run :0 s=0
     2: 0x2089 M=1 main.main :0 s=0
     3: 0x2ddd3 M=1 runtime.main :0 s=0
     4: 0x5d930 M=1 runtime.goexit :0 s=0
     5: 0x5e8b6 M=1 runtime.usleep :0 s=0
     6: 0x377d1 M=1 runtime.sysmon :0 s=0
     7: 0x30c1d M=1 runtime.mstart1 :0 s=0
     8: 0x30af3 M=1 runtime.mstart :0 s=0
Mappings
1: 0x0/0xffffffffffffffff/0x0   [FN]

with Go 1.7.5.

Doing the same on Linux, produces

Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?seconds=5
Saved profile in /usr/local/google/home/aalexand/pprof/pprof.server.samples.cpu.005.pb.gz
File: server
Type: cpu
Time: Mar 15, 2017 at 1:16pm (PDT)
Duration: 5s, Total samples = 4.99s (99.79%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) raw
PeriodType: cpu nanoseconds
Period: 10000000
Time: 2017-03-15 13:16:34.995513521 -0700 PDT
Duration: 5.00
Samples:
samples/count cpu/nanoseconds
        499 4990000000: 1 2 3 4 
Locations
     1: 0x70fb00 M=1 main.run :0 s=0
     2: 0x70fb49 M=1 main.main :0 s=0
     3: 0x42dab9 M=1 runtime.main :0 s=0
     4: 0x45a4f0 M=1 runtime.goexit :0 s=0
Mappings
1: 0x400000/0x710000/0x0 /tmp/go-build929989772/command-line-arguments/_obj/exe/server  [FN]

and

Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?seconds=5
Saved profile in /usr/local/google/home/aalexand/pprof/pprof.server.samples.cpu.004.pb.gz
File: server
Type: cpu
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) raw
PeriodType: cpu nanoseconds
Period: 10000000
Samples:
samples/count cpu/nanoseconds
        500 5000000000: 1 2 
Locations
     1: 0x401000 M=1 main.run :0 s=0
     2: 0x45ddc0 M=1 runtime.goexit :0 s=0
Mappings
1: 0x400000/0x699000/0x0 /tmp/go-build092539107/command-line-arguments/_obj/exe/server  [FN]

respectively that are both correctly symbolized profiles.

Fixes: #441

1. More helpful error messages and usages are added.
2. All non-bool option now requires an input. That means "call_tree" is valid, but "sample_index" is invalid.

Before:

(pprof) sample_index
(pprof)

(pprof) sample_index 0
unrecognized command: "sample_index"

(pprof) help
    ...
    sample_index     Sample value to report (0-based index or name)
    ...

After:

(pprof) sample_index
please input a value, e.g. sample_index=<val>
(pprof) focus
please input a value, e.g. focus=<val>
(pprof) call_tree
(pprof) 

(pprof) sample_index 0
do you mean: "sample_index=0"?

What version of pprof are you using?

tip from https://github.com/google/pprof

What operating system and processor architecture are you using?

Linux 64bit

I would like to have a way to tell pprof where it can find source files.

Imagine I have some service running on the server and I have a binary that is running there.

I can use pprof like this:

$ pprof -http=:8080 /tmp/lakafka-1.22.0-278 /tmp/prof

Where /tmp/lakafka-1.22.0-278 is a binary built on a build server and /tmp/prof is a profile collected via wget from http://.../debug/pprof/profile.

If I then go to View -> Source I don't see any source code. pprof is looking for the source code in the path from build server, e.g. /home/teamcitycpp/agent09/work/56cbaf90675b10ff/_gopath/src/badoo/lakafka/main.go

But I am not on a build server. I have the same source code at, lets say, /home/marko/lakafka.

I would like to tell pprof to look for the source code at /home/marko/lakafka.

Similar to what dir command does in GDB.

Thank you!

I believe that this repo is the code that powers go tool pprof. If I'm wrong on that count, disregard everything else I say.

I'm using pprof on macOS 10.12.1 with go 1.7.3. I'm constantly using it in interactive mode, and it would be really nice to be able to call back previous commands with the "up" arrow key. Instead, of course, it prints ^[[A, which I assume means that this isn't supported?

I completely understand if this isn't worth the development team's time, but I thought I would suggest it.

Look for debug symbols in all locations GDB does (https://sourceware.org/gdb/onlinedocs/gdb/Separate-Debug-Files.html) , e.g.:

• /usr/lib/debug/.build-id/ab/cdef1234.debug
• /usr/bin/binary.debug
• /usr/bin/.debug/binary.debug
• /usr/lib/debug/usr/bin/binary.debug.

The first option is already there, the other three are added by this commit.

Signed-off-by: Adriaan Schmidt [email protected]

Please answer these questions before submitting your issue. Thanks!

What version of pprof are you using?

If you are using pprof via go tool pprof, what's your go env output? If you run pprof from GitHub, what's the Git revision?

What operating system and processor architecture are you using?

darwin_amd64

What did you do?

pprof -http=:8080

If possible, provide a recipe for reproducing the error. Attaching a profile you are trying to analyze is good.

What did you expect to see?

should display specificial code.

What did you see instead?

Please answer these questions before submitting your issue. Thanks!

What version of pprof are you using?

v0.0.0-20221103000818-d260c55eee4c

What operating system and processor architecture are you using?

linux, amd64

What did you do?

pprof -http=:

What did you expect to see?

there should not have more than one (func, file) pair

What did you see instead?

Motivation

My team at Datadog is using pprof as our data collection format for profiling data (cpu, wall clock, lock contention, allocations, etc.) coming from non-JVM languages (which use JFR). This works very well for us, and we'd like to continue building on pprof. However, there are two use cases we are interested in that are currently difficult to implement efficiently using pprof.

This proposal outlines these use cases as well as potential changes to the profile.proto format that would support them. We believe that these use cases would also be useful to the OSS community. Additionally the proposal should meet the signal correlation requirements of the Profiling Vision OTEP, which might allow pprof to be adopted by OpenTelemtry.

Last, but not least, we hope that this proposal would ease the adoption of these features by the Go runtime, e.g. by adding timestamps to CPU profiles. I already implemented a prototype for this.

Also see: https://github.com/google/pprof/issues/457

UC 1: Thread Timelines (FlameChart)

We would like to break down the self-time of distributed tracing spans using per-thread (or goroutine) flame chart timelines. The data for this would be collected using wall clock sampling, tracing techniques, or a combination of both. This is similar to what fgtrace does, but would only show the threads relevant to the span:

In order to support this use case, pprof would need the ability to efficiently store timestamps, thread ids and span ids for the individual profiling events that are being recorded. Additionally the pprof UI might be extended to show this data, or the command line could be extended to target perfetto or other flame chart visualization tools.

UC 2: CPU Heatmaps (FlameScope)

Another use case we are interested in is the display of of CPU Heatmaps pioneered by FlameScope which provide a more powerful way to understand application behavior.

This use case is simpler than the first use case and only requires timestamp information for individual CPU samples. Additionally the UI could add this visualization or the command line could output the data in a format understood by flamescope.

Example

Let's say we have a wallclock profile that contains 3 events:

|time since start|duration|stack trace|trace id|span id|thread id| |-|-|-|-|-|-| |10ms|15ms|a;b;c;d;e;f;g;h|1|1|1| |25ms|5ms|a;b;c;d;e;f;g;h|1|1|1| |40ms|20ms|a;b;c;d;e;f;g;h|2|2|2|

Note: For the purpose of this example the stack trace is the same for all 3 events.

How could this data be encoded into pprof?

Using Labels (Today)

With the existing profile.proto, one may use labels to store the data like this (shown in pseudo pprof format):

sample_type: [walltime/nanoseconds]

sample {
  location_id: a
  location_id: b
  location_id: c
  location_id: d
  location_id: e
  location_id: f
  location_id: g
  location_id: h
  value: 1500000000
  label: {time_ms=10}
  label: {trace_id=1}
  label: {span_id=1}
  label: {thread_id=1}
}

sample {
  location_id: a
  location_id: b
  location_id: c
  location_id: d
  location_id: e
  location_id: f
  location_id: g
  location_id: h
  value: 500000000
  label: {time_ms=25}
  label: {trace_id=1}
  label: {span_id=1}
  label: {thread_id=1}
}

sample {
  location_id: a
  location_id: b
  location_id: c
  location_id: d
  location_id: e
  location_id: f
  location_id: g
  location_id: h
  value: 2000000000
  label: {time_ms=40}
  label: {trace_id=2}
  label: {span_id=2}
  label: {thread_id=2}
}

Unfortunately this requires to encode the location_id list three times b/c the Sample message has no concept of referencing a stack trace by id and each unique combination of labels requires us to have its own Sample. In practice this leads to very large pprof files.

Using Breakdown (Proposed Change)

Using the proposed profile.proto change in this PR, the same data could be encoded like shown below. In practice, this should lead to much smaller pprof sizes.

sample_type: [walltime/nanoseconds]
tick_unit: ms

sample {
  location_id: a
  location_id: b
  location_id: c
  location_id: d
  location_id: e
  location_id: f
  location_id: g
  location_id: h
  value: 3000000000
  breakdown: {
    tick: 10
    tick: 25
    tick: 40
    value: 15
    value: 5
    value: 20,
    label_set_id: 1
    label_set_id: 1
    label_set_id: 2
  }
}

labelSet {
  id: 1
  label: {trace_id=1}
  label: {span_id=1}
  label: {thread_id=1}
}

labelSet {
  id: 2
  label: {trace_id=2}
  label: {span_id=2}
  label: {thread_id=2}
}

Efficiency

This proposal can lead to significant size reduction of uncompressed pprofs compared to using the existing label mechanism when adding timestamps and trace ids. Workloads with less unique stack traces and longer profiling periods gain the most benefits from this proposal. E.g. in the examples below the gains are from 1.4x to 3.2x, but it's possible to construct examples that see bigger or smaller improvements.

That being said, the benefits mostly disappear after gzip compression. E.g. the same examples see only 1.01x to 1.22x compression gains. This is perhaps not surprising given that the duplicated stack traces are easy targets for compression.

For more details see felixge/pprof-breakdown and raw results (spreadsheet).

Compatibility

The proposed change is fully backwards compatible, but not fully forwards compatible when it comes to labels. The new format puts event specific labels into the new Breakdown message. This means that profiles taking advantage of the new profile.proto Breakdown labels won't be completely accessible to old versions of the pprof tool or other tools consuming pprof information. Those tools could still render basic flame graphs, but the label information would be invisible to them.

Next Steps

We're looking for feedback from the pprof maintainers to understand if "Support Timestamps and Labels for Individual Events" is a compelling feature or if the pprof project would rather stay focused on storing pre-aggregated data. Our suggested changes to profile.proto should mostly be seen as a demonstration of the technical feasibility of implementing such a proposal, but we're not too attached to the implementation details and happy to adjust them as needed.

Perhaps the small gains on compressed pprofs are not sufficient justification for the added complexity, and a simpler proposal to standardize the usage of the existing label mechanism for the use cases outlined above would offer better tradeoffs. Alternatively more optimizations to this proposal such as delta encoding and other tweaks could be explored.

Additionally we'd like to get feedback from the OSS community and potentially OTel group to make sure the outlined use cases are clear and useful to others.

What version of pprof are you using?

pprof (part of gperftools 2.0) Installed as part of gperftools 2.10 from Homebrew

What operating system and processor architecture are you using?

macOS Monterey 12.6, arm64, apple silicon

What did you do?

I linked gperftools into my binary with -L/opt/homebrew/opt/gperftools/lib -lprofiler -ltcmalloc as arguments to g++-12 (installed from brew). That all worked fine and generated the output in the file set by CPUPROFILE. Although when running pprof --web main main.prof I get a stream of errors which I've put in the text file below. I've also included the profile as well, its zipped because GitHub didn't like the extension.

errors.txt main.prof.zip

From what I've read here https://developer.apple.com/forums/thread/655588 it looks like the libraries have been moved as of macOS Big Sur 11.0.1.

What did you expect to see?

Not lots of errors, but strangely still seems to work, although something must be a bit broken. This is my first time using a profiler so I'm not too sure.

What did you see instead?

Lots of errors.

Initially filed at https://github.com/golang/go/issues/52000 by @fumin. Moving here as this seems to be an issue in pprof.

What version of Go are you using (go version)?

$ go version
go version go1.17.6 windows/amd64

Does this issue reproduce with the latest release?

Yes.

What operating system and processor architecture are you using (go env)?

$ go env
set GO111MODULE=
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\a3367\AppData\Local\go-build
set GOENV=C:\Users\a3367\AppData\Roaming\go\env
set GOEXE=.exe
set GOEXPERIMENT=
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GOMODCACHE=C:\Users\a3367\go\pkg\mod
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=C:\Users\a3367\go
set GOPRIVATE=
set GOPROXY=https://proxy.golang.org,direct
set GOROOT=C:\Program Files\Go
set GOSUMDB=sum.golang.org
set GOTMPDIR=
set GOTOOLDIR=C:\Program Files\Go\pkg\tool\windows_amd64
set GOVCS=
set GOVERSION=go1.17.6
set GCCGO=gccgo
set AR=ar
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=NUL
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -mthreads -fmessage-length=0 -fdebug-prefix-map=C:\Users\a3367\AppData\Local\Temp\go-build2334633044=/tmp/go-build -gno-record-gcc-switches
gdb --version: GNU gdb (GDB) 8.1

What did you do?

I profiled the standard library's png.Encode function and looked at this attached profile:

png_encode.zip

I then ran both weblist and list on the png.filter function.

What did you expect to see?

I expect both weblist and list to show the same result.

What did you see instead?

I saw list showing the correct result, with the sum of the flat time of png.abs8 in png.filter tallying with the total time spent on png.abs8. In particular, the below log shows that png.abs8 took 1.56 seconds in total.

PS C:\Users\a3367\work\misc\seg\output> go tool pprof .\png_encode.pprof
Type: cpu
Time: Mar 29, 2022 at 1:28pm (CST)
Duration: 31.43s, Total samples = 17.53s (55.77%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 16.92s, 96.52% of 17.53s total
Dropped 91 nodes (cum <= 0.09s)
Showing top 10 nodes out of 29
      flat  flat%   sum%        cum   cum%
     7.96s 45.41% 45.41%     13.07s 74.56%  image/png.filter
        2s 11.41% 56.82%      2.01s 11.47%  image/png.abs
     1.74s  9.93% 66.74%      1.74s  9.93%  runtime.memmove
     1.56s  8.90% 75.64%      1.56s  8.90%  image/png.abs8
     1.44s  8.21% 83.86%      3.46s 19.74%  image/png.paeth
     0.90s  5.13% 88.99%      0.90s  5.13%  hash/adler32.update
     0.80s  4.56% 93.55%      0.81s  4.62%  compress/flate.(*deflateFast).matchLen
     0.29s  1.65% 95.21%      0.31s  1.77%  compress/flate.(*huffmanEncoder).bitCounts
     0.12s  0.68% 95.89%      0.12s  0.68%  runtime.asyncPreempt
     0.11s  0.63% 96.52%      1.04s  5.93%  compress/flate.(*deflateFast).encode
(pprof)

Adding the time spent on png.abs8 in png.filter also shows the same 1.56 seconds.

(pprof) list png.filter
Total: 17.53s
ROUTINE ======================== image/png.filter in C:\Program Files\Go\src\image\png\writer.go
     7.96s     13.07s (flat, cum) 74.56% of Total
         .          .    202:   return len(b), nil
         .          .    203:}
         .          .    204:
         .          .    205:// Chooses the filter to use for encoding the current row, and applies it.
         .          .    206:// The return value is the index of the filter and also of the row in cr that has had it applied.
      10ms       10ms    207:func filter(cr *[nFilter][]byte, pr []byte, bpp int) int {
         .          .    208:   // We try all five filter types, and pick the one that minimizes the sum of absolute differences.
         .          .    209:   // This is the same heuristic that libpng uses, although the filters are attempted in order of
         .          .    210:   // estimated most likely to be minimal (ftUp, ftPaeth, ftNone, ftSub, ftAverage), rather than
         .          .    211:   // in their enumeration order (ftNone, ftSub, ftUp, ftAverage, ftPaeth).
         .          .    212:   cdat0 := cr[0][1:]
     110ms      110ms    213:   cdat1 := cr[1][1:]
         .          .    214:   cdat2 := cr[2][1:]
         .          .    215:   cdat3 := cr[3][1:]
         .          .    216:   cdat4 := cr[4][1:]
         .          .    217:   pdat := pr[1:]
         .          .    218:   n := len(cdat0)
         .          .    219:
         .          .    220:   // The up filter.
         .          .    221:   sum := 0
     310ms      310ms    222:   for i := 0; i < n; i++ {
     1.02s      1.03s    223:           cdat2[i] = cdat0[i] - pdat[i]
     230ms      940ms    224:           sum += abs8(cdat2[i])
         .          .    225:   }
         .          .    226:   best := sum
         .          .    227:   filter := ftUp
         .          .    228:
         .          .    229:   // The Paeth filter.
         .          .    230:   sum = 0
         .          .    231:   for i := 0; i < bpp; i++ {
         .          .    232:           cdat4[i] = cdat0[i] - pdat[i]
         .          .    233:           sum += abs8(cdat4[i])
         .          .    234:   }
     790ms      790ms    235:   for i := bpp; i < n; i++ {
     3.49s      6.99s    236:           cdat4[i] = cdat0[i] - paeth(cdat0[i-bpp], pdat[i], pdat[i-bpp])
     240ms      760ms    237:           sum += abs8(cdat4[i])
     180ms      180ms    238:           if sum >= best {
         .          .    239:                   break
         .          .    240:           }
         .          .    241:   }
      40ms       40ms    242:   if sum < best {
         .          .    243:           best = sum
         .          .    244:           filter = ftPaeth
         .          .    245:   }
         .          .    246:
         .          .    247:   // The none filter.
         .          .    248:   sum = 0
         .          .    249:   for i := 0; i < n; i++ {
         .          .    250:           sum += abs8(cdat0[i])
      10ms       10ms    251:           if sum >= best {
         .          .    252:                   break
         .          .    253:           }
         .          .    254:   }
         .          .    255:   if sum < best {
         .          .    256:           best = sum
         .          .    257:           filter = ftNone
         .          .    258:   }
         .          .    259:
         .          .    260:   // The sub filter.
         .          .    261:   sum = 0
         .          .    262:   for i := 0; i < bpp; i++ {
         .          .    263:           cdat1[i] = cdat0[i]
         .          .    264:           sum += abs8(cdat1[i])
         .          .    265:   }
     190ms      210ms    266:   for i := bpp; i < n; i++ {
     990ms         1s    267:           cdat1[i] = cdat0[i] - cdat0[i-bpp]
      80ms      390ms    268:           sum += abs8(cdat1[i])
     150ms      150ms    269:           if sum >= best {
         .          .    270:                   break
         .          .    271:           }
         .          .    272:   }
         .          .    273:   if sum < best {
         .          .    274:           best = sum
         .          .    275:           filter = ftSub
         .          .    276:   }
         .          .    277:
         .          .    278:   // The average filter.
         .          .    279:   sum = 0
         .          .    280:   for i := 0; i < bpp; i++ {
      70ms       80ms    281:           cdat3[i] = cdat0[i] - pdat[i]/2
         .          .    282:           sum += abs8(cdat3[i])
         .          .    283:   }
         .          .    284:   for i := bpp; i < n; i++ {
      30ms       30ms    285:           cdat3[i] = cdat0[i] - uint8((int(cdat0[i-bpp])+int(pdat[i]))/2)
      10ms       30ms    286:           sum += abs8(cdat3[i])
      10ms       10ms    287:           if sum >= best {
         .          .    288:                   break
         .          .    289:           }
         .          .    290:   }
         .          .    291:   if sum < best {
         .          .    292:           filter = ftAverage
(pprof)

However, weblist shows the wrong result, it seems to exagerate the result. Pprof listing.zip For example, on line 268, list shows only 80ms spent, whereas weblist shows 360ms spent.