Remote symbolization fails

[ErwanLegrand]

What version of pprof are you using?

Tested with Git revision 4b386c2. (With a patch to work around #276.)

What operating system and processor architecture are you using?

Linux AMD64

What did you do?

I tried to obtain a profile remotely. The server is written in C. Profiles are generated by gperftools 2.1 (for /pprof/profile) and jemalloc 3.4.1(for /pprof/heap). The request handler for /prof/symbol handles loader relocations/ASLR perfectly well.

What did you expect to see?

Collection of profile succeeds, as it does with the old pprof.

What did you see instead?

$ pprof --symbolize=remote https+insecure://XXX/pprof/heap
Fetching profile over HTTP from https+insecure://XXX/pprof/heap
pprof: unexpected negative adjusted address, mapping &{4 0 18446744073709551615 0 https+insecure://XXX/pprof/heap  false false false false 0 0} source 18446744073709551615, offset 0

[ErwanLegrand]

@aalexand @rauls5382 I have opened this new issue to track the other problem I have mentioned in the comments of #276.

The profiles are in the old pprof format, as this is what libprofiler and libjemalloc generate. (Although I have not checked whether newer releases have switched to the newer format.)

Note that this also fails if --symbolize=remote is omitted, even though in this case no request is sent to /pprof/symbol.

I believe pprof must perform some computations to account for relocations when profiling locally, because it uses addr2line which does not include support for relocations. But I fail to see why this would be needed in the case of remote debugging. A server written in C can properly perform address to symbol resolution by using Ian Lance Taylor's glorious libbacktrace. I would expect the Go runtime package to do the same. (Although I admit I have not actually tried using Func.FuncForPC or Func.FileLine within an executable built with -buildmode=pie.)

[aalexand]

As far as I can tell, collecting data using gperftools and viewing that with pprof works fine for ALSR binaries. See example below. Closing the issue, feel free to re-open with more details on how to reproduce.

@aalexand:tmp$ cat busyloop.c 

int foo() {
  int sum = 0;
  for (int i = 0; i < 6; i++) {
    for (volatile int j = 0; j < (1 << 30); j++) {
      sum += j;
    }
  }
  return sum;
}

int main() {
  return foo();
}

@aalexand:tmp$ gcc -pie -fPIE -O2 -g -o busyloop -lprofiler busyloop.c

@aalexand:tmp$ readelf --segments busyloop

Elf file type is DYN (Shared object file)
Entry point 0x650
There are 9 program headers, starting at offset 64

Program Headers:
  Type           Offset             VirtAddr           PhysAddr
                 FileSiz            MemSiz              Flags  Align
  PHDR           0x0000000000000040 0x0000000000000040 0x0000000000000040
                 0x00000000000001f8 0x00000000000001f8  R E    0x8
  INTERP         0x0000000000000238 0x0000000000000238 0x0000000000000238
                 0x000000000000001c 0x000000000000001c  R      0x1
      [Requesting program interpreter: /lib64/ld-linux-x86-64.so.2]
  LOAD           0x0000000000000000 0x0000000000000000 0x0000000000000000
                 0x00000000000009a8 0x00000000000009a8  R E    0x200000
  LOAD           0x0000000000000df8 0x0000000000200df8 0x0000000000200df8
                 0x0000000000000230 0x0000000000000238  RW     0x200000
  DYNAMIC        0x0000000000000e10 0x0000000000200e10 0x0000000000200e10
                 0x00000000000001c0 0x00000000000001c0  RW     0x8
  NOTE           0x0000000000000254 0x0000000000000254 0x0000000000000254
                 0x0000000000000044 0x0000000000000044  R      0x4
  GNU_EH_FRAME   0x0000000000000854 0x0000000000000854 0x0000000000000854
                 0x0000000000000044 0x0000000000000044  R      0x4
  GNU_STACK      0x0000000000000000 0x0000000000000000 0x0000000000000000
                 0x0000000000000000 0x0000000000000000  RW     0x10
  GNU_RELRO      0x0000000000000df8 0x0000000000200df8 0x0000000000200df8
                 0x0000000000000208 0x0000000000000208  R      0x1

 Section to Segment mapping:
  Segment Sections...
   00     
   01     .interp 
   02     .interp .note.ABI-tag .note.gnu.build-id .gnu.hash .dynsym .dynstr .gnu.version .gnu.version_r .rela.dyn .init .plt .plt.got .text .fini .rodata .eh_frame_hdr .eh_frame 
   03     .init_array .fini_array .jcr .dynamic .got .got.plt .data .bss 
   04     .dynamic 
   05     .note.ABI-tag .note.gnu.build-id 
   06     .eh_frame_hdr 
   07     
   08     .init_array .fini_array .jcr .dynamic .got 
@aalexand:tmp$ CPUPROFILE=/tmp/profile.out ./busyloop
PROFILE: interrupts/evictions/bytes = 1222/23/1360
@aalexand:tmp$ pprof -raw /tmp/profile.out
Some binary filenames not available. Symbolization may be incomplete.
Try setting PPROF_BINARY_PATH to the search path for local binaries.
PeriodType: cpu nanoseconds
Period: 10000000
Samples:
samples/count cpu/nanoseconds
          8   80000000: 1 2 
        164 1640000000: 3 2 
          2   20000000: 4 2 
          2   20000000: 5 2 
        183 1830000000: 6 2 
        653 6530000000: 7 2 
        210 2100000000: 8 2 
Locations
     1: 0x55cb74fbc62c M=1 foo /tmp/busyloop.c:6 s=0
             main /tmp/busyloop.c:13 s=0
     2: 0xffffffffffffffff M=2 
     3: 0x55cb74fbc639 M=1 foo /tmp/busyloop.c:5 s=0
             main /tmp/busyloop.c:13 s=0
     4: 0x55cb74fbc632 M=1 foo /tmp/busyloop.c:5 s=0
             main /tmp/busyloop.c:13 s=0
     5: 0x55cb74fbc62e M=1 foo /tmp/busyloop.c:5 s=0
             main /tmp/busyloop.c:13 s=0
     6: 0x55cb74fbc635 M=1 foo /tmp/busyloop.c:5 s=0
             main /tmp/busyloop.c:13 s=0
     7: 0x55cb74fbc63d M=1 foo /tmp/busyloop.c:5 s=0
             main /tmp/busyloop.c:13 s=0
     8: 0x55cb74fbc628 M=1 foo /tmp/busyloop.c:6 s=0
             main /tmp/busyloop.c:13 s=0
Mappings
1: 0x55cb74fbc000/0x55cb74fbd000/0x0 /tmp/busyloop 8d0701235bc8685268b5f941d0c2bf17c131368f [FN][FL][LN][IN]
2: 0x0/0xffffffffffffffff/0x0 

[ankon]

I was able to reproduce the same issue: I'm creating CPU profiles using libprofiler in the server, and have the /pprof/symbol endpoint available to resolve symbols. In my case this is a NodeJS application, so I really need to use the remote side.

I stepped through the code at the time this happened, and basically it turns out that this is a problem in the way addresses/offsets are added. #396 fixes the problem I see by using the math/big package for handling overflow when adjusting addresses.

[aalexand]

@ankon Can you post a reproducer?

[ankon]

The actual code involved:

1. Run https://github.com/ankon/node-remote-pprof/blob/master/sample/index.js: git clone, npm install, PORT=3000 node --perf-basic-prof-only-functions sample/index.js (NodeJS 8.11.2, macOS 10.13.5, perftools installed via brew install gperftools)
2. In another window: Run ab -n 1000 http://localhost:3000/endpoint to produce "traffic"
3. In another window: Run pprof -http localhost:3001 -seconds 3 -symbolize remote http://localhost:3000/pprof/growth (or ..../pprof/profile)

Maybe I could try to attach the output of /pprof/growth, so you can see the "big" addresses?

In any case what I saw in the debugger was that offset indeed was 0, but the address that needed adjusting was >MaxInt64. The sum then became a negative int64.

[aalexand]

@ankon Thanks, reproduced. I got #397 which should fix it. With the fix I was able to get the output like below, please check if it looks expected. Asking because there is a number of unsymbolized locations, not sure if it's OK.

$ go run pprof.go -top -seconds 3 -symbolize remote http://localhost:3000/pprof/profile
Fetching profile over HTTP from http://localhost:3000/pprof/profile?seconds=3
Please wait... (3s)
Saved profile in /Users/aalexand/pprof/pprof.libtcmalloc.4.dylib.samples.cpu.003.pb.gz
File: libtcmalloc.4.dylib
Type: cpu
Showing nodes accounting for 2.28s, 77.82% of 2.93s total
Dropped 189 nodes (cum <= 0.01s)
      flat  flat%   sum%        cum   cum%
     0.93s 31.74% 31.74%      0.93s 31.74%  0x7fffef31ccd6
     0.70s 23.89% 55.63%      0.71s 24.23%  LazyCompile:*_writeRaw
     0.23s  7.85% 63.48%      0.23s  7.85%  0x7fffef31e9ea
     0.13s  4.44% 67.92%      0.13s  4.44%  0x7fffef31ccee
     0.08s  2.73% 70.65%      0.08s  2.73%  0x7fffef31cca6
     0.06s  2.05% 72.70%      0.06s  2.05%  0x7fffef31dec2
     0.04s  1.37% 74.06%      0.04s  1.37%  0x7fffef3137da
     0.03s  1.02% 75.09%      0.03s  1.02%  0x0000000101a3e0d0 (in node)
     0.02s  0.68% 75.77%      0.02s  0.68%  0x0000000101a132ba (in node)
     0.02s  0.68% 76.45%      0.02s  0.68%  0x7fffef31d7d2
     0.01s  0.34% 76.79%      0.11s  3.75%  LazyCompile:*DoJoin
     0.01s  0.34% 77.13%      0.43s 14.68%  LazyCompile:*Socket._writeGeneric
     0.01s  0.34% 77.47%      0.32s 10.92%  LazyCompile:*bytesToUuid
     0.01s  0.34% 77.82%      1.59s 54.27%  LazyCompile:*router.get
         0     0% 77.82%      2.19s 74.74%  0x000000010155f002 (in node)
         0     0% 77.82%      0.02s  0.68%  0x000000010155f003 (in node)
         0     0% 77.82%      0.03s  1.02%  0x000000010155f017 (in node)
         0     0% 77.82%      0.02s  0.68%  0x000000010155f02a (in node)
         0     0% 77.82%      0.02s  0.68%  0x000000010155f044 (in node)
         0     0% 77.82%      0.02s  0.68%  0x000000010155f062 (in node)
         0     0% 77.82%      0.03s  1.02%  0x000000010155f245 (in node)
         0     0% 77.82%      2.19s 74.74%  0x0000000101560833 (in node)
...