Git Product home page Git Product logo

Comments (5)

aalexand avatar aalexand commented on May 2, 2024

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

from pprof.

aalexand avatar aalexand commented on May 2, 2024

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.

from pprof.

aalexand avatar aalexand commented on May 2, 2024

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.

from pprof.

bfallik avatar bfallik commented on May 2, 2024

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

from pprof.

aalexand avatar aalexand commented on May 2, 2024

Filed golang/go#18077.

from pprof.

Related Issues (20)

Recommend Projects

  • React photo React

    A declarative, efficient, and flexible JavaScript library for building user interfaces.

  • Vue.js photo Vue.js

    🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.

  • Typescript photo Typescript

    TypeScript is a superset of JavaScript that compiles to clean JavaScript output.

  • TensorFlow photo TensorFlow

    An Open Source Machine Learning Framework for Everyone

  • Django photo Django

    The Web framework for perfectionists with deadlines.

  • D3 photo D3

    Bring data to life with SVG, Canvas and HTML. 📊📈🎉

Recommend Topics

  • javascript

    JavaScript (JS) is a lightweight interpreted programming language with first-class functions.

  • web

    Some thing interesting about web. New door for the world.

  • server

    A server is a program made to process requests and deliver data to clients.

  • Machine learning

    Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.

  • Game

    Some thing interesting about game, make everyone happy.

Recommend Org

  • Facebook photo Facebook

    We are working to build community through open source technology. NB: members must have two-factor auth.

  • Microsoft photo Microsoft

    Open source projects and samples from Microsoft.

  • Google photo Google

    Google ❤️ Open Source for everyone.

  • D3 photo D3

    Data-Driven Documents codes.