Pprof won't show symbols

#1

Hello!

I’m trying to use gperftools to profile a FUSE file system I have written. To do this, I have used the cpuprofiler crate in my code and started/stopped the profiler around the main processing loop. (cpuprofiler is a very thin layer on top of the native C libprofiler library provided by gperftools so it’s unlikely for it to be the root cause of my problems.)

Now, generating the profile from my application seems to work and pprof can interpret it just fine:

$ pprof --text target/debug/sandboxfs prof
Using local file target/debug/sandboxfs.                 
Using local file prof.                                   
Total: 186 samples                                       
      58  31.2%  31.2%       58  31.2% 0x00007fff5fb0d736
      42  22.6%  53.8%       42  22.6% 0x00007fff5fb0b97e
      22  11.8%  65.6%       22  11.8% 0x00007fff5fb0ae5e
      10   5.4%  71.0%       10   5.4% 0x0000000103c15fe7
       8   4.3%  75.3%        8   4.3% 0x00007fff5fbb7830
       8   4.3%  79.6%        8   4.3% 0x00007fff5fbb7898
[...]

Unfortunately, as you can see, I get no debugging symbols whatsoever.

The profile file seems to be valid (based on some random troubleshooting instructions I found online) in the sense that it includes the table of mappings at the end, as such:

$ tail prof
10432a000-104332000 r-xp 00009000 00:00 0           /tmp/gperftools/lib/libprofiler.0.dylib
104325000-10432a000 r-xp 00008000 00:00 0           /tmp/gperftools/lib/libprofiler.0.dylib
10431d000-104325000 r-xp 00000000 00:00 0           /tmp/gperftools/lib/libprofiler.0.dylib
10430e000-104316000 r-xp 0003a000 00:00 0           /usr/local/lib/libosxfuse.2.dylib
1042fb000-10430e000 r-xp 00027000 00:00 0           /usr/local/lib/libosxfuse.2.dylib
1042d4000-1042fb000 r-xp 00000000 00:00 0           /usr/local/lib/libosxfuse.2.dylib
103da1000-1042d2000 r-xp 004bf000 00:00 0           /Users/jmmv/os/sandboxfs/./target/debug/sandboxfs
103d71000-103da1000 r-xp 00490000 00:00 0           /Users/jmmv/os/sandboxfs/./target/debug/sandboxfs
1038e1000-103d71000 r-xp 00000000 00:00 0           /Users/jmmv/os/sandboxfs/./target/debug/sandboxfs
038e1000-1038e1000 r-xp 00000000 00:00 0           /Users/jmmv/os/sandboxfs/./target/debug/sandboxfs

Long shot but… any hints?

This is on macOS Mojave. FWIW, Go’s go tool pprof seems to work OK on Go code, and as far as I know, this and gperftools are essentially the same thing.

In case you are curious about the specific code, it’s in this pull request: https://github.com/bazelbuild/sandboxfs/pull/66

Thank you!

0 Likes

#2

A couple of things that I found important to do when using pprof, hope it helps

0 Likes

#3

These didn’t help unfortunately. But I ended up finding https://github.com/google/pprof/issues/324 and from there might have figured some things out.

First, I installed the Go version of pprof with go get and then ran it on my profile (with a lot of trial an error) like this:

$ PPROF_BINARY_PATH=$(pwd)/target/debug /tmp/gopath/bin/pprof /tmp/prof                                                                                                 
Local symbolization failed for sandboxfs: error reading Mach-O file /Users/jmmv/os/sandboxfs/./target/debug/sandboxfs: could not identify base for /Users/jmmv/os/sandboxfs/./target/debug/sandboxfs: __TEXT segment address (0x100000000) > mapping start address (0x686e000)
Some binary filenames not available. Symbolization may be incomplete.
Try setting PPROF_BINARY_PATH to the search path for local binaries.
File: libc++.1.dylib
Type: cpu

The error this prints is interesting. So then I went and deleted the last line from the profile (the one that shows a base address lower than the text segment) and ran it again:

PPROF_BINARY_PATH=$(pwd)/target/debug /tmp/gopath/bin/pprof /tmp/prof
Some binary filenames not available. Symbolization may be incomplete.
Try setting PPROF_BINARY_PATH to the search path for local binaries.
File: libc++.1.dylib
Type: cpu
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) text
Showing nodes accounting for 1420ms, 94.04% of 1510ms total
Showing top 10 nodes out of 180
      flat  flat%   sum%        cum   cum%
     370ms 24.50% 24.50%      370ms 24.50%  _lstat64
     360ms 23.84% 48.34%      360ms 23.84%  _writev
     260ms 17.22% 65.56%      260ms 17.22%  _read
     140ms  9.27% 74.83%      140ms  9.27%  __platform_memcmp
      60ms  3.97% 78.81%       60ms  3.97%  ___getdirentries64
      60ms  3.97% 82.78%       60ms  3.97%  __platform_memmove$VARIANT$Nehalem
      50ms  3.31% 86.09%       50ms  3.31%  _je_rallocx
      40ms  2.65% 88.74%       40ms  2.65%  ___mmap
      40ms  2.65% 91.39%       40ms  2.65%  __platform_memset$VARIANT$Ivybridge
      40ms  2.65% 94.04%       40ms  2.65%  _fstat64

which now shows symbols and the profile seems to be good.

Still no idea why the regular pprof may not work and why I have to manually edit the profile. Will try on Linux later to see if things work out of the box.

0 Likes

#4

Aha, things are more interesting.

First, the claim that I have to edit the profile to remove a bogus entry is false. Even without doing that, pprof is able to show details.

Second, with a more realistic profile tracing real binary load… even the non-Go pprof tool shows stuff with symbol names, but they all come “late” in the trace. What I think is happening is that most of the samples happen within system libraries and this pprof tool cannot symbolize them for some reason, so it looks as if no symbols were found. However, with enough samples falling into the Rust code, the Rust symbols from my application show up. The Go version of pprof somehow is able to handle the symbols for system libraries properly.

0 Likes