1

I have this below code that prints different program counter values depending on where its run from.

Code:

package main

import (
    "fmt"
    "runtime"
)

func foo() {
    bar()
}

func bar() {
    pcs := make([]uintptr, 10)
    _ = runtime.Callers(0, pcs)
    for _, pc := range pcs {
        fmt.Printf("Value of pc %+v\n", runtime.FuncForPC(pc).Name())
    }
}

func main() {
    foo()
}
  1. When running using go run or the compiled binary, it prints (main.bar is missing)
Value of pc runtime.Callers
Value of pc runtime.Callers
Value of pc main.main
Value of pc main.foo
Value of pc runtime.main
Value of pc runtime.goexit
  1. When running the code from Visual Studio Code (Only in debug mode, it works fine)
Value of pc runtime.Callers
Value of pc main.bar
Value of pc main.foo
Value of pc main.main
Value of pc runtime.main
Value of pc runtime.goexit
  1. When running in Playground, (foo, bar, both are missing)
Value of pc runtime.Callers
Value of pc runtime.Callers
Value of pc main.main
Value of pc main.main
Value of pc runtime.main
Value of pc runtime.goexit

I'm using a framework (logrus) which relies on the PCs order to perform some operation (logging the filename).
Since the PC values keeps changing depending on where its run from, it works in Debug Mode but fails when running using go run or the compiled binary.

Any idea what could be causing the PCs to load differently? Any config or optimization that's kicking in?

Kishore Bandi
  • 5,537
  • 2
  • 31
  • 52
  • 1
    This is likely due to function inlining, see https://stackoverflow.com/questions/63785981/panic-stacktrace-does-not-show-function-parameters for how that impacts stack traces and how you can confirm that. – Marc Sep 30 '20 at 10:54
  • Does this answer your question? [panic() stacktrace does not show function parameters](https://stackoverflow.com/questions/63785981/panic-stacktrace-does-not-show-function-parameters) – Marc Sep 30 '20 at 11:08
  • @Marc I added the `go:noinline` but it still doesn't show `bar` method. Any other configs that might help here? – Kishore Bandi Sep 30 '20 at 11:16
  • No offense, but you probably added it wrong or didn't recompile your binary. You also really shouldn't do this just to get around a bug in a logging library. – Marc Sep 30 '20 at 11:17
  • @Marc No issues, I doubted my implementation as well :) There is a difference with and without `go:noinline`. The only difference is, now the output in `GoPlayground` and using `go run` is the same. But the issue of `bar` not showing up still persists. Strangely this was working a couple of weeks back and we just started noticing that `filenames` were not getting logged by `logrus` and drilled down the issue to this PCs behaviour https://play.golang.org/p/h9fOdZbvHTe – Kishore Bandi Sep 30 '20 at 11:19
  • You may want to read the comments for [runtime.Callers](https://golang.org/pkg/runtime/#Callers): `Iterating over the returned slice of PCs directly is discouraged, as is using FuncForPC on any of the returned PCs, since these cannot account for inlining or return program counter adjustment.` – Marc Sep 30 '20 at 11:30
  • @Marc True, like icza pointed out `logrus` shouldn't be using `runtime.Callers` API. It looks like they fixed it by looping over the stack values and looking for this package based on caller. https://github.com/sirupsen/logrus/commit/af6ac8cee616a8cd9f2b2afaa78dc66c7d420495 – Kishore Bandi Sep 30 '20 at 11:32

1 Answers1

2

Documentation of runtime.Callers() states:

To translate these PCs into symbolic information such as function names and line numbers, use CallersFrames. CallersFrames accounts for inlined functions and adjusts the return program counters into call program counters. Iterating over the returned slice of PCs directly is discouraged, as is using FuncForPC on any of the returned PCs, since these cannot account for inlining or return program counter adjustment.

Doc suggests to use runtime.CallersFrames() to obtain function information from the raw counters which knows about and accounts for function inlining, for example:

pcs := make([]uintptr, 10)
n := runtime.Callers(0, pcs)
pcs = pcs[:n]

frames := runtime.CallersFrames(pcs)
for {
    frame, more := frames.Next()
    if !more {
        break
    }
    fmt.Println("Function:", frame.Function)
}

This should output regardless of how you call / run it (try it on the Go Playground):

Function: runtime.Callers
Function: main.bar
Function: main.foo
Function: main.main
Function: runtime.main
icza
  • 389,944
  • 63
  • 907
  • 827
  • Unfortunately, the `logrus` framework internally uses `runtime.Callers` API to figure this out. So any workarounds to get it working using this API call? How does debug mode achieve this, maybe skips some optimization steps? – Kishore Bandi Sep 30 '20 at 11:03
  • @BandiKishore Likely when running in debug mode, function inlining is disabled so you can inspect / trace each function call. Debug mode is not about performance but traceability. – icza Sep 30 '20 at 11:04
  • If `logrus` uses `runtime.Callers()` without `runtime.CallersFrames()`, it seriously needs an update. – icza Sep 30 '20 at 11:05
  • hmm, so I guess the only option I've got is to raise a bug to `logrus` repo. For regular call stack it uses `runtime.CallersFrames()` but during singleton initialization to figure out `logrus package` it using this API. https://github.com/sirupsen/logrus/blob/master/entry.go#L177 – Kishore Bandi Sep 30 '20 at 11:09
  • @BandiKishore Yes, you should create an issue there. – icza Sep 30 '20 at 11:11
  • Accepting your answer. This issue has been fixed by `logrus`. They still don't use `CallersFrames` but they have handled it by looping over the entire stack to get the right API package. https://github.com/sirupsen/logrus/commit/af6ac8cee616a8cd9f2b2afaa78dc66c7d420495 – Kishore Bandi Sep 30 '20 at 11:30
  • I think for the example the break condition should be positioned at the end of the for loop to output the topmost frame (the last entry in frames) – Marcus Jul 19 '22 at 14:59