cmd/pprof: Profile is incorrect

[calmh]

Go 1.7. I was inspecting a CPU profile sent to me for an ARM binary by a user. The top level items make sense but the deeper you get into the stack the more it veers off into cyberspace, with the call stack implicating functions and packages than can never be called from the higher levels. I'll link to the relevant files here and point out some of the discrepancies in the hope that the cause may be obvious to someone.

The profiled binary: https://github.com/syncthing/syncthing/releases/download/v0.14.5/syncthing-linux-arm-v0.14.5.tar.gz (compiled with Go 1.7 on linux-amd64 for linux-arm)

The profile: https://nym.se/t/syncthing-cpu-linux-arm-v0.14.5-142747.pprof

A "web" overview: https://nym.se/r/dbqn.svg

An interesting branch to look at here is the 5.37s one slightly to the right. It shows:

github.com/s/s/model.(*rwFolder).pullerIteration
  |
  v
github.com/s/s/model.(*rwFolder).pullerRoutine
  |
  v
github.com/s/s/lib/ignore.parseIgnoreFile
  |
  v
tabwriter.(*Writer).writeN

However, none of the rwFolder methods ever call ignore.parseIgnoreFile - it's an unexported function in another package, after all - and the github.com/syncthing/syncthing/lib/ignore package does not import tabwriter nor do anything to cause calls to it via some other package.

I'm fairly sure the profile is from the binary in question, as it has a function to create such a profile and tags it with the platform and release version as seen in the profile name.

[rsc]

This profile was not generated with this binary.

The profile is mostly binary but at the end there is a copy of /proc/self/maps. It says

MAPPED_LIBRARIES:
00010000-00539000 r-xp 00000000 b3:02 265046     /usr/bin/syncthing
00539000-009aa000 r--p 00529000 b3:02 265046     /usr/bin/syncthing
009aa000-009d7000 rw-p 0099a000 b3:02 265046     /usr/bin/syncthing
009d7000-009ef000 rw-p 00000000 00:00 0 
00b00000-00b38000 rw-p 00000000 00:00 0 
00b38000-0f10c000 ---p 00000000 00:00 0          [heap]
0f10c000-1bf30000 rw-p 00000000 00:00 0          [stack:2182]
1bf30000-30d02000 ---p 00000000 00:00 0 
b68fb000-b6f04000 rw-p 00000000 00:00 0 
be8c3000-be8e4000 rw-p 00000000 00:00 0          [stack]
ffff0000-ffff1000 r-xp 00000000 00:00 0          [vectors]

This does not match any of the released syncthing binaries from 0.14.0 to 0.14.5. Look, for example, at the second mapping, the read-only data. It starts at file offset 0x529000 and is mapped at virtual address 0x539000.

In contrast, the read-only data in each binary starts later than that:

$ for i in syncthing-0*; do echo $i; readelf -l $i | egrep '^  (Type|LOAD)'; done
syncthing-0.14.0
  Type           Offset   VirtAddr   PhysAddr   FileSiz MemSiz  Flg Align
  LOAD           0x000000 0x00010000 0x00010000 0x5b1fbc 0x5b1fbc R E 0x1000
  LOAD           0x5b2000 0x005c2000 0x005c2000 0x5fe89a 0x5fe89a R   0x1000
  LOAD           0xbb1000 0x00bc1000 0x00bc1000 0x28ec0 0x41990 RW  0x1000
syncthing-0.14.1
  Type           Offset   VirtAddr   PhysAddr   FileSiz MemSiz  Flg Align
  LOAD           0x000000 0x00010000 0x00010000 0x5b7414 0x5b7414 R E 0x1000
  LOAD           0x5b8000 0x005c8000 0x005c8000 0x60314a 0x60314a R   0x1000
  LOAD           0xbbc000 0x00bcc000 0x00bcc000 0x28ee0 0x419b0 RW  0x1000
syncthing-0.14.2
  Type           Offset   VirtAddr   PhysAddr   FileSiz MemSiz  Flg Align
  LOAD           0x000000 0x00010000 0x00010000 0x5b7414 0x5b7414 R E 0x1000
  LOAD           0x5b8000 0x005c8000 0x005c8000 0x60314a 0x60314a R   0x1000
  LOAD           0xbbc000 0x00bcc000 0x00bcc000 0x28ee0 0x419b0 RW  0x1000
syncthing-0.14.3
  Type           Offset   VirtAddr   PhysAddr   FileSiz MemSiz  Flg Align
  LOAD           0x000000 0x00010000 0x00010000 0x5b79b4 0x5b79b4 R E 0x1000
  LOAD           0x5b8000 0x005c8000 0x005c8000 0x6035c2 0x6035c2 R   0x1000
  LOAD           0xbbc000 0x00bcc000 0x00bcc000 0x28ee0 0x419b0 RW  0x1000
syncthing-0.14.4
  Type           Offset   VirtAddr   PhysAddr   FileSiz MemSiz  Flg Align
  LOAD           0x000000 0x00010000 0x00010000 0x56e5fc 0x56e5fc R E 0x1000
  LOAD           0x56f000 0x0057f000 0x0057f000 0x5bf332 0x5bf332 R   0x1000
  LOAD           0xb2f000 0x00b3f000 0x00b3f000 0x27338 0x3fd48 RW  0x1000
syncthing-0.14.5
  Type           Offset   VirtAddr   PhysAddr   FileSiz MemSiz  Flg Align
  LOAD           0x000000 0x00010000 0x00010000 0x540c04 0x540c04 R E 0x1000
  LOAD           0x541000 0x00551000 0x00551000 0x47ad4c 0x47ad4c R   0x1000
  LOAD           0x9bc000 0x009cc000 0x009cc000 0x2d138 0x453d0 RW  0x1000
$ 

Put another way, the text (code) segment in each of these released binaries has a larger FileSiz/MemSiz than the 0x529000 that was mapped in the binary the profile came from.

Clearly the profile came from /usr/bin/syncthing, but it wasn't one of these.

In the long term, Go pprof profiles will become self-contained, so that you don't need a binary. We're not there yet. But this profile definitely didn't come from this binary.