Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

runtime: perf_events shows deep call stacks with repeated address #12968

Closed
rhysh opened this issue Oct 17, 2015 · 3 comments
Closed

runtime: perf_events shows deep call stacks with repeated address #12968

rhysh opened this issue Oct 17, 2015 · 3 comments
Labels
FrozenDueToAge
Milestone
Go1.7Maybe

Comments

@rhysh
Copy link
Contributor

rhysh commented Oct 17, 2015

When profiling a process with perf_events I see some call stacks that are very deep, repeating a single address many times (usually around 100 or 125). The repeated addresses that I've checked always refer to a CALL runtime.deferreturn(SB) instruction, whereas non-repeated addresses refer to the instruction after a CALL to a different function.

The output of perf script -k $debugkernel -i perf.data includes some samples like the following:

redacted 1234 cycles:
              5dabd5 sync/atomic.LoadUint64 (/redacted)
              4a5557 net.(*netFD).readUnlock (/redacted)
              4a5e51 net.(*netFD).Read (/redacted)
              4a5e51 net.(*netFD).Read (/redacted)
              4a5e51 net.(*netFD).Read (/redacted)
              4a5e51 net.(*netFD).Read (/redacted)
              4a5e51 net.(*netFD).Read (/redacted)
              4a5e51 net.(*netFD).Read (/redacted)
// etc, for a total of 124 instances of address 4a5e51

The relevant section of go tool objdump output is as follows:

        fd_unix.go:241  0x4a5e3b        4889942400010000                MOVQ DX, 0x100(SP)
        fd_unix.go:241  0x4a5e43        48894c2460                      MOVQ CX, 0x60(SP)
        fd_unix.go:241  0x4a5e48        48898c2408010000                MOVQ CX, 0x108(SP)
        fd_unix.go:243  0x4a5e50        90                              NOPL
        fd_unix.go:243  0x4a5e51        e85aaff8ff                      CALL runtime.deferreturn(SB)
        fd_unix.go:243  0x4a5e56        488bac24c8000000                MOVQ 0xc8(SP), BP
        fd_unix.go:243  0x4a5e5e        4881c4d0000000                  ADDQ $0xd0, SP
        fd_unix.go:243  0x4a5e65        c3                              RET
        fd_unix.go:241  0x4a5e66        488d1d53554200                  LEAQ 0x425553(IP), BX
        fd_unix.go:241  0x4a5e6d        48891c24                        MOVQ BX, 0(SP)
        fd_unix.go:241  0x4a5e71        e8daeaf6ff                      CALL runtime.newobject(SB)

The function that appears to be called by the first instance of net.(*netFD).Read certainly shows up as a deferred function, but I don't believe net.(*netFD).Read should show up on the sampled stack this many times. It looks like the call stack would appear to be infinite if perf script didn't cut it off after 125 frames. The identity of net.(*netFD).Read's caller is lost.

My program is compiled with a Go toolchain that I built with GOEXPERIMENT=framepointer. I'm using Go version 30b9663, running the process on linux/amd64 with kernel version 3.13, and profiling it with perf_events, via perf record -g -F 977 -p 1234 -o perf.data -- sleep 300 and perf script -k $debugkernel -i perf.data

$ go version
go version devel +30b9663 Tue Oct 13 21:06:58 2015 +0000 linux/amd64
@ianlancetaylor ianlancetaylor added this to the Unplanned milestone Oct 17, 2015
@ianlancetaylor
Copy link
Member

CC @aclements

@aclements
Copy link
Member

Since we're planning to enable frame pointers by default for 1.7 (#15840), I'm putting this in a 1.7 milestone.

I'm not sure exactly what's happening yet, but I'm sure it's because the calling convention around deferreturn (and jmpdefer in particular) is very strange. I'm not surprised it screws up BP.

@aclements aclements modified the milestones: Go1.7Maybe, Unplanned May 26, 2016
@gopherbot
Copy link
Contributor

CL https://golang.org/cl/23457 mentions this issue.

@golang golang locked and limited conversation to collaborators May 26, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge
Projects
None yet
Milestone
Go1.7Maybe
Development

No branches or pull requests
4 participants
@rhysh @aclements @ianlancetaylor @gopherbot