cmd/trace: goroutine analysis view attributes time to "Unknown time"

[seizethedave]

Go version

1.25.3 Linux

Output of go env in your module/workspace:

% go1.25.3 env
AR='ar'
CC='clang'
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_ENABLED='1'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
CXX='clang++'
GCCGO='gccgo'
GO111MODULE=''
GOARCH='arm64'
GOARM64='v8.0'
GOAUTH='netrc'
GOBIN=''
GOCACHE='/Users/davidgrant/Library/Caches/go-build'
GOCACHEPROG=''
GODEBUG=''
GOENV='/Users/davidgrant/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFIPS140='off'
GOFLAGS=''
GOGCCFLAGS='-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/5b/k0df38mx6sqg7ryycmtpyty80000gn/T/go-build991633255=/tmp/go-build -gno-record-gcc-switches -fno-common'
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMOD='/dev/null'
GOMODCACHE='/Users/davidgrant/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/davidgrant/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/Users/davidgrant/sdk/go1.25.3'
GOSUMDB='sum.golang.org'
GOTELEMETRY='local'
GOTELEMETRYDIR='/Users/davidgrant/Library/Application Support/go/telemetry'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/Users/davidgrant/sdk/go1.25.3/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.25.3'
GOWORK=''
PKG_CONFIG='pkg-config'

What did you do?

I collected a trace from a running Go program:

curl -o my.trace "http://localhost:8011/debug/pprof/trace?seconds=1"

What did you see happen?

When I view the trace locally (go1.25.3 tool trace my.trace), the "Goroutine analysis" link (/goroutines) shows me something like this:

Large-ish amounts of time attributed to "Unknown time." I've tried on a half dozen different services, both on arm64 and amd64. It always seems to be there.

(I cannot share these traces publicly, but I could share them via email if desired.)

What did you expect to see?

I expect the latency to be divided among known things. 😄

[nsrip-dd]

From Gopher slack:

I took a look at some traces I have handy, and I see this as well. One case where I see lots of "unknown" time is when the goroutine was blocked when execution tracing started. To confirm this, I opened the same trace in gotraceui and checked for "blocked" time at the start of a goroutine where I saw "unknown" time. I see roughly the same amount of time for "blocked" as you do for "unknown" in the go tool trace view.

If the goroutine is blocked long enough for the tracer to advance generations, the tracer will record a traceback for the where the goroutine is blocked. That can be used determine why it's blocked, e.g. if runtime.chanrecv is in the traceback it's probably a channel receive, etc. A parser/UI can use that traceback to assign a more specific type to the blocking time (I recently updated the Datadog UI to do this.)

[nsrip-dd]

For a little more technical detail, here's an example of an event that'd be considered "unknown" time:

M=-1 P=-1 G=-1 StateTransition Time=372851633376000 Resource=Goroutine(4205928) Reason="" GoID=4205928 Undetermined->Waiting
Stack=
        runtime.gopark @ 0x33a7c4d
                GOROOT/src/runtime/proc.go:435
        runtime.selectgo @ 0x337ae75
                GOROOT/src/runtime/select.go:351
        github.com/gocql/gocql.(*Conn).heartBeat @ 0x59533e4
                external/com_github_gocql_gocql/conn.go:610

Note that the state transition is from Undetermined to Waiting, and there's no "reason". In go tool trace it looks like we consider this kind of event the "creation" of the goroutine, looking back to the last sync time to determine the "creation" time, and initialize all the stat data structures for the goroutine: source. We don't actually update any stats. I think the time since the creation time is counted towards the total time for the goroutine, but since that time is not assigned a more specific type, that time is considered "unknown": source.

I wonder if traceAdvance can make use of the wait reason it records to assign a "reason" to the event when it records an previously-untraced goroutine? e.g. here.

[prattmic]

cc @mknyszek