pprof collection across reflected functions

[bfallik]

I don't know if this is an actual bug, a documentation bug, or neither but I hit an interesting corner case trying to collect pprof measurements that I wanted to report. While working with https://github.com/urfave/cli I ran into urfave/cli#551 trying to collect pprof data.

Is pprof collection expected to work on code that calls into a reflected function? If so, I don't believe it does so there may be a real bug. If not it would be helpful if the docs mentioned this limitation.

Thanks.

[aalexand]

Thanks for reporting this. Here some investigation notes.

Program I used to reproduce:

package rfstack

import (
  "fmt"
  "os"
  "reflect"
  "runtime"
  "testing"
)

var data []byte

type P struct{}

func alloc() {
  stk := make([]uintptr, 32)
  stk = stk[:runtime.Callers(0, stk)]
  frames := runtime.CallersFrames(stk)
  for {
    frame, more := frames.Next()
    fmt.Fprintf(os.Stderr, "%#x\t%s\n", frame.PC, frame.Function)
    if !more {
      break
    }
  }

  data = make([]byte, 16*1024*1024)
}

func caller(rec int) {
  if rec == 0 {
    alloc()
  } else {
    caller(rec - 1)
  }
}

func (p *P) Foo() {
  caller(5)
}

func hotspot() {
  for i := 0; i < (1 << 31); i++ {
  }
}

func (p *P) Bar() {
  hotspot()
}

func TestHeap(t *testing.T) {
  var p P
  reflect.ValueOf(&p).MethodByName("Foo").Call([]reflect.Value{})
}

func TestCPU(t *testing.T) {
  var p P
  reflect.ValueOf(&p).MethodByName("Bar").Call([]reflect.Value{})
}

Running it I can see the stack looks like what it is expected to look like:

$ go test -v -memprofile mem.prof rfstack_test.go 
=== RUN   TestHeap
0x406f4d  runtime.Callers
0x479fb2  command-line-arguments.alloc
0x47a20b  command-line-arguments.caller
0x47a221  command-line-arguments.caller
0x47a221  command-line-arguments.caller
0x47a221  command-line-arguments.caller
0x47a221  command-line-arguments.caller
0x47a221  command-line-arguments.caller
0x47a259  command-line-arguments.(*P).Foo
0x4566cb  runtime.call32
0x4e0f37  reflect.Value.call
0x4e0853  reflect.Value.Call
0x47a371  command-line-arguments.TestHeap
0x4750d0  testing.tRunner
0x4591a0  runtime.goexit
--- PASS: TestHeap (0.00s)
=== RUN   TestCPU
--- PASS: TestCPU (0.67s)
PASS
ok    command-line-arguments  0.711s

and the heap profile file has the 0x47a222 value repeated 5 times too, so the stack frames below the reflection frame are in the profile:

$ cat mem.prof 
heap profile: 1: 16777216 [1: 16777216] @ heap/1048576
1: 16777216 [1: 16777216] @ 0x47a174 0x47a20c 0x47a222 0x47a222 0x47a222 0x47a222 0x47a222 0x47a25a 0x4566cc 0x4e0f38 0x4e0854 0x47a372 0x4750d1 0x4591a1

# runtime.MemStats
# Alloc = 16925600
# TotalAlloc = 16957344
# Sys = 22202616
# Lookups = 4
# Mallocs = 488
# Frees = 182
# HeapAlloc = 16925600
# HeapSys = 17301504
# HeapIdle = 57344
# HeapInuse = 17244160
# HeapReleased = 0
# HeapObjects = 306
# Stack = 524288 / 524288
# MSpan = 9920 / 16384
# MCache = 14400 / 16384
# BuckHashSys = 1442375
# NextGC = 17949064
# PauseNs = [238794 279742 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
# NumGC = 2
# DebugGC = false

Yet, pprof output seems to have stripped all frames from runtime.call32 and below:

$ pprof rfstack.test mem.prof 
File: rfstack.test
Type: space
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 16MB, 100% of 16MB total
      flat  flat%   sum%        cum   cum%
      16MB   100%   100%       16MB   100%  reflect.Value.call /usr/lib/google-golang/src/reflect/value.go
         0     0%   100%       16MB   100%  command-line-arguments.TestHeap /usr/local/google/home/aalexand/projects/golang-reflection-stack/rfstack_test.go
         0     0%   100%       16MB   100%  reflect.Value.Call /usr/lib/google-golang/src/reflect/value.go
         0     0%   100%       16MB   100%  runtime.goexit /usr/lib/google-golang/src/runtime/asm_amd64.s
         0     0%   100%       16MB   100%  testing.tRunner /usr/lib/google-golang/src/testing/testing.go
(pprof) tree
Showing nodes accounting for 16MB, 100% of 16MB total
----------------------------------------------------------+-------------
      flat  flat%   sum%        cum   cum%   calls calls% + context      
----------------------------------------------------------+-------------
                                              16MB   100% |   reflect.Value.Call /usr/lib/google-golang/src/reflect/value.go
      16MB   100%   100%       16MB   100%                | reflect.Value.call /usr/lib/google-golang/src/reflect/value.go
----------------------------------------------------------+-------------
                                              16MB   100% |   testing.tRunner /usr/lib/google-golang/src/testing/testing.go
         0     0%   100%       16MB   100%                | command-line-arguments.TestHeap /usr/local/google/home/aalexand/projects/golang-reflection-stack/rfstack_test.go
                                              16MB   100% |   reflect.Value.Call /usr/lib/google-golang/src/reflect/value.go
----------------------------------------------------------+-------------
                                              16MB   100% |   command-line-arguments.TestHeap /usr/local/google/home/aalexand/projects/golang-reflection-stack/rfstack_test.go
         0     0%   100%       16MB   100%                | reflect.Value.Call /usr/lib/google-golang/src/reflect/value.go
                                              16MB   100% |   reflect.Value.call /usr/lib/google-golang/src/reflect/value.go
----------------------------------------------------------+-------------
         0     0%   100%       16MB   100%                | runtime.goexit /usr/lib/google-golang/src/runtime/asm_amd64.s
                                              16MB   100% |   testing.tRunner /usr/lib/google-golang/src/testing/testing.go
----------------------------------------------------------+-------------
                                              16MB   100% |   runtime.goexit /usr/lib/google-golang/src/runtime/asm_amd64.s
         0     0%   100%       16MB   100%                | testing.tRunner /usr/lib/google-golang/src/testing/testing.go
                                              16MB   100% |   command-line-arguments.TestHeap /usr/local/google/home/aalexand/projects/golang-reflection-stack/rfstack_test.go
----------------------------------------------------------+-------------

I first thought this could be a symbolization issue, but the addresses of interest symbolize fine through the binary:

$ addr2line -f -e rfstack.test 0x47a222 0x47a25a
command-line-arguments.caller
/usr/local/google/home/aalexand/projects/golang-reflection-stack/rfstack_test.go:36
command-line-arguments.(*P).Foo
/usr/local/google/home/aalexand/projects/golang-reflection-stack/rfstack_test.go:40

[aalexand]

What happens is that profile. RemoveUninteresting() turns out to be overly aggressively pruning the frames for the use case in hand. For heap profiles the "drop" pattern list includes runtime\..* regular expression and so the frame runtime.call32 matches it and gets dropped along with all the callee frames.

There is the counterpart "keep" pattern list which only includes runtime\.panic item today, and I think the fix is to add runtime\.call32 there, but I want to double-check with the Go team.

[aalexand]

Adding

`runtime\.call32`,
`runtime\.call64`,

to the allocSkipRxStr list changes the pprof output to the expected:

File: rfstack.test
Type: space
Showing nodes accounting for 16MB, 100% of 16MB total
      flat  flat%   sum%        cum   cum%
      16MB   100%   100%       16MB   100%  command-line-arguments.alloc /usr/local/google/home/aalexand/projects/golang-reflection-stack/rfstack_test.go
         0     0%   100%       16MB   100%  command-line-arguments.(*P).Foo /usr/local/google/home/aalexand/projects/golang-reflection-stack/rfstack_test.go
         0     0%   100%       16MB   100%  command-line-arguments.TestHeap /usr/local/google/home/aalexand/projects/golang-reflection-stack/rfstack_test.go
         0     0%   100%       16MB   100%  command-line-arguments.caller /usr/local/google/home/aalexand/projects/golang-reflection-stack/rfstack_test.go
         0     0%   100%       16MB   100%  reflect.Value.Call /usr/lib/google-golang/src/reflect/value.go
         0     0%   100%       16MB   100%  reflect.Value.call /usr/lib/google-golang/src/reflect/value.go
         0     0%   100%       16MB   100%  runtime.call32 /usr/lib/google-golang/src/runtime/asm_amd64.s
         0     0%   100%       16MB   100%  runtime.goexit /usr/lib/google-golang/src/runtime/asm_amd64.s
         0     0%   100%       16MB   100%  testing.tRunner /usr/lib/google-golang/src/testing/testing.go

The discussion on golang-nuts hasn't been too active so far, so I'll file a Go bug to get it going.

[bfallik]

@aalexand great, thanks for investigating. Glad to hear this might get fixed.

[aalexand]

Filed golang/go#18077.