cmd/trace: explicit goroutine function names replaced by synthetic ones

[WhisperingChaos]

What version of Go are you using (go version)?

$ go version
go version go1.18beta1 linux/amd64

Does this issue reproduce with the latest release?

• Yes - 1.18beta1 is latest 1.18 release
• No - 1.17.1

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/user/.cache/go-build"
GOENV="/home/user/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/user/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/user/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/user/go1.18beta1/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/user/go1.18beta1/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.18beta1"
GCCGO="gccgo"
GOAMD64="v1"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/dev/null"
GOWORK=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build2821634988=/tmp/go-build -gno-record-gcc-switches"

What did you do?

• Statically compile the following source.
• Extract a 10 second interval of trace output:

    curl http://${TRACE_SERVICE_NAME}:${TRACE_SERVICE_PORT}/debug/pprof/trace?seconds=10 > ~/trace.out
    go tool trace -http=trace:${TRACE_SERVICE_PORT} ~/trace.out

• View trace output via Chrome.
• Performed above for both 1.18beta1 and 1.17.1 go compiler versions.

Links to go tool trace output files:

• 1.18beta1,
• 1.17.1.

What did you expect to see?

When viewing trace's "/goroutines" page:

• Expect the explicitly named: "msgSend" function in the "main" package to be listed as "main.msgSend".
• Expect the explicitly named: "msgReceive" function in the "main" package to be listed as "main.msgReceive".

When viewing specific goroutine events, selected from the trace timeline, expect the event "Title" field to display either:

• "main.msgSend" or
• "main.msgReceive".

What did you see instead?

When viewing trace's "/goroutines" page saw:

• "main.main.func1" and
• "main.main.func2".

When viewing specific goroutine events, selected from the trace timeline, the event "Title" field to displayed either:

• "main.main.func1" or
• "main.main.func2".

[ianlancetaylor]

CC @randall77 @danscales

[danscales]

Cc @mdempsky @cherrymui

I don't know much about how tracing determines the relevant function names for events. But I do notice that in Go 1.17, we are generating main.dwrap.1 and main.dwrap.2 (for use in the go calls in main()), and those functions looks like they are replace by main.func1 and main.func2 in Go 1.18beta1.

This renaming looks like it happened with Matthew's change 0132b91 . The change is in the function wrapGoDefer() in order.go. But I also see that Cherry did some changes related to defer/go wrapping. And I'm not sure if any of this is exactly relevant to the fact that the trace names change (but main.main.func1 and main.main.func2 are definitely new).

[cherrymui]

For register ABI we need to wrap functions with arguments and/or results at go statements. The start PC of the new goroutine is the PC of the wrapper, which has synthetic name. The runtime cannot record the underlying function's PC because the at the point of goroutine creation the underlying function hasn't run. Maybe we could add some metadata, but that seems more complex.

Maybe we could name the wrapper based on the callee, instead of caller. Then it will be "main.msgSend.wrapperN" or something. Maybe that is clearer.

If we really want to do that, the trace viewer could perhaps revert the name to the underlying function, either through an established naming convention or through some matadata.

[WhisperingChaos]

Given the comments above, perhaps there's some confusion between explicitly named functions and ones defined as anonymous or closures. Explicitly named functions are assigned a specific and unique function name by a developer when defining a function at package scope. Here are examples of explicit functions provided by the source link found in the body of the current Issue:

package main
.
.
.
func msgSend(
	msg chan<- naught,
) {
	for {
		msg <- naught{}
	}
}

func msgReceive(
	msg <-chan naught,
) {
	tkr := time.NewTicker(1 * time.Millisecond)
	for {
		<-msg
		<-tkr.C
	}
}

Here's how they are started as goroutines:

func main() {
	sr := make(chan naught)
	go msgSend(sr)
	go msgReceive(sr)
	select {}
}

Since they are defined and started as goroutines employing their explicit names, prior versions, like 1.17.1, of the go tool trace utility would display and report on their execution using these explicit names. In this situation, the 1.17.1 trace tool would display their names as: main.msgSend and main.msgReceive. These names represent the concatenation of the package name and the explicit function name defined at package scope. This naming system enables a developer to rapidly match goroutine names appearing in the trace with their associated source code.

It seems, with the introduction of 1.18beta1, that instead of displaying a function's explicit name, it substitutes a synthetic one. I would categorize this as anomalous behavior of 1.18beta1 given the behavior of prior trace versions.

Although I consider generating synthetic names of main.main.func1 and main.main.func2 as a bug for explicitly defined and started goroutines, these would be the expected names if they were instead anonymously declared inside a function. In this situation, the synthetic names convey, like their explicit counterparts, a reference that permits a developer to match the synthetic name to its source. For example, main.main.func1 locates the anonymous function's code in the main package, within the .main function declared at package scope, and .func1 as the first syntactically defined anonymous function body within the .main function.

Here's an example where I would expect the synthetic names mentioned above to appear in the go tool trace report:

package main
.
.
.

func main() {
	msg := make(chan naught)
	// main.main.func1
	go func() {
		for {
			msg <- naught{}
		}
	}()
	// main.main.func2
	go func() {
		tkr := time.NewTicker(1 * time.Millisecond)
		for {
			<-msg
			<-tkr.C
		}
	}()
	select {}
}

[ianlancetaylor]

Ping @cherrymui . Is this something we can address for 1.18? Thanks.

[cherrymui]

While it may be related to register ABI, Go 1.17 already has register ABI enabled so it's unclear to me why this is not the case with Go 1.17.

(@WhisperingChaos this is no confusing. While a top-level function is named, it is not specified that the goroutine needs to be named/labeled as such. I agree it is good to have, though.)

[cherrymui]

@WhisperingChaos is your 1.17 trace file actually from Go 1.17? Or it is from a non-AMD64 machine? For Go 1.17 on AMD64 I actually got main.main·dwrap·1.

[WhisperingChaos]

@cherrymui

I'm sorry, what I thought was version 1.17.1 was instead "go version devel +55626ee50b Mon May 24 20:10:04 2021 +0000 linux/amd64". I had used version 1.17.1 as the boot version to compile this experimental template version. My bad. Therefore displaying main.main·dwrap·1 instead of main.msgSend and main.main·dwrap·2 for main.msgReceive occurs as you describe in your posts. But should it?

The "wrapping" method was only recently introduced with go 1.17. The commit: 0132b91 mentioned by danscales ascribes the change to improve support for closures, therefore, in the case of explicitly named and called functions, perhaps this change inadvertantly removed the use of a function's actual name when declared at package scope and explicitly called?

Although I've searched this repository's closed issues and reviewed the release notes for 1.17, I have been unable to find a discussion alerting users to this visible and impactful change nor the reasoning behind it. I would appreciate your help if you can direct me to this discussion, as I would really like to understand the benefit of synthetic names instead of explicit ones.

Prior to this change, the use of explicit names would easily permit one to correlate the function name to its code. Also, trace provides an instance count N= on the "/goroutines" web page following each named go routine. This N= may no longer represent the total, as starting the same go routine from a different line of code produces a different synthetic goroutine name.

One other notable difference from older versions of trace, is the absence of the "Start Stack Trace" field. This field used to appear in an event's detail, immediately above the "End Stack Trace". The "Start Stack Trace" would display the call stack of functions that eventually invoked the goroutine using the go keyword. Here's an old blog post that contains an example of the "Start Stack Trace" field for a goroutine.

I mention this difference in the context of this discussion because the newly introduced synthetic names act as a minimal start stack trace mechanism. They uniquely reference the code responsible for a goroutine's invocation - line of code in a specific package. Essentially, the synthetic name would be equivalent to the "Start Stack Trace" entry that immediately issues the go operation to schedule the goroutine. However, the "Start Stack Trace" field would have potentially included more information. I assume this field would have also detailed any function calls performed by active (parent) ones - functions that haven't yet returned and eventually lead to the invocation of the goroutine.

Finally, if I had to decide on how to address this issue, I'd reflect on how an end user would employ the elements of the trace report to ferret out goroutine execution problems in their code. It seems to me that this wrapped method of synthetically generating a name should remain hidden from the end user. It's not something that an end user need be aware of when monitoring goroutine execution. Therefore, I would drop the .wrapperN suffix from the potential solution you mentioned in a prior post which suggested generating: main.msgSend.wrapperN.

[gopherbot]

Change https://go.dev/cl/384158 mentions this issue: cmd/compile, runtime: use unwrapped PC for goroutine creation tracing