cmd/trace: always opening browser, not printing profile

[matthewhughes-uw]

Go version

go version go1.22.2 linux/amd64

Output of go env in your module/workspace:

GO111MODULE=''
GOARCH='amd64'
GOBIN=''
GOCACHE='/home/my-user/.cache/go-build'
GOENV='/home/my-user/.config/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='amd64'
GOHOSTOS='linux'
GOINSECURE=''
GOMODCACHE='/home/my-user/.local/share/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='linux'
GOPATH='/home/my-user/.local/share/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/usr/lib/go'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/usr/lib/go/pkg/tool/linux_amd64'
GOVCS=''
GOVERSION='go1.22.2'
GCCGO='gccgo'
GOAMD64='v1'
AR='ar'
CC='gcc'
CXX='g++'
CGO_ENABLED='1'
GOMOD='/tmp/proj/go.mod'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=/tmp/go-build1974410770=/tmp/go-build -gno-record-gcc-switches'

What did you do?

#!/usr/bin/env bash

set -o errexit -o pipefail -o nounset

# create a trivial module that supports 1.21.0+
go mod init m
go mod edit -go=1.21.0

cat <<'EOF' > lib.go
package lib

func Add(x int, y int) int {
	return x+y
}
EOF

cat <<'EOF' > lib_test.go
package lib

import (
	"testing"
)

func TestAdd(t *testing.T) {
	if Add(1,2) != 3 {
		t.Fatal("forgot how to add")
	}
}
EOF

# generate a trace using go1.21.0 ...
go1.21.0 test -trace=1_21_trace.out ./...

# and go1.21.0
go1.22.0 test -trace=1_22_trace.out ./...

What did you see happen?

When running go tool trace with the trace generated by go1.21.0 with -pprof a profile is printed to stdout:

$ go1.21.0 tool trace -pprof=net 1_21_trace.out | wc -c
93
$ go1.22.0 tool trace -pprof=net 1_21_trace.out | wc -c
90

This is expected

doing the same with the profile from go1.22.0 opens the browser:

$ go1.22.0 tool trace -pprof=net 1_22_trace.out | wc -c
2024/04/11 14:49:17 Preparing trace for viewer...
2024/04/11 14:49:17 Splitting trace for viewer...
2024/04/11 14:49:17 Opening browser. Trace viewer is listening on http://127.0.0.1:40941

This is unexpected

What did you expect to see?

Per the docs:

$ go1.22.0 tool trace -h
Usage of 'go tool trace':
Given a trace file produced by 'go test':
	go test -trace=trace.out pkg

Open a web browser displaying trace:
	go tool trace [flags] [pkg.test] trace.out

Generate a pprof-like profile from the trace:
    go tool trace -pprof=TYPE [pkg.test] trace.out

When I pass the -pprof flag I expect a profile to be generated

[matthewhughes-uw]

I see for v2 tracing pprofFlag is passed to the v2 main here but from what I can see the new main doesn't use this flag at all? Is it just that this functionality hasn't been implemented for v2?

EDIT: quick hack copying the v1 code that got it working (i.e. printing profiles, I make no guarantees that they are the expected profiles 🙃):

diff --git a/src/cmd/trace/v2/main.go b/src/cmd/trace/v2/main.go
index 0a60ef04db..21b247a3f8 100644
--- a/src/cmd/trace/v2/main.go
+++ b/src/cmd/trace/v2/main.go
@@ -27,6 +27,35 @@ func Main(traceFile, httpAddr, pprof string, debug int) error {
                return fmt.Errorf("failed to read trace file: %w", err)
        }
        defer tracef.Close()
+       parsed, err := parseTrace(tracef)
+       if err != nil {
+               return err
+       }
+
+       var pprofFunc traceviewer.ProfileFunc
+       switch pprof {
+       case "net":
+               pprofFunc = pprofByGoroutine(computePprofIO(), parsed)
+       case "sync":
+               pprofFunc = pprofByGoroutine(computePprofBlock(), parsed)
+       case "syscall":
+               pprofFunc = pprofByGoroutine(computePprofSyscall(), parsed)
+       case "sched":
+               pprofFunc = pprofByGoroutine(computePprofSched(), parsed)
+       }
+       if pprofFunc != nil {
+               records, err := pprofFunc(&http.Request{})
+               if err != nil {
+                       return fmt.Errorf("failed to generate pprof: %v\n", err)
+               }
+               if err := traceviewer.BuildProfile(records).Write(os.Stdout); err != nil {
+                       return fmt.Errorf("failed to generate pprof: %v\n", err)
+               }
+               os.Exit(0)
+       }
+       if pprof != "" {
+               return fmt.Errorf("unknown pprof type %s\n", pprof)
+       }
 
        // Debug flags.
        switch debug {
@@ -43,10 +72,6 @@ func Main(traceFile, httpAddr, pprof string, debug int) error {
        addr := "http://" + ln.Addr().String()
 
        log.Print("Preparing trace for viewer...")
-       parsed, err := parseTrace(tracef)
-       if err != nil {
-               return err
-       }
        // N.B. tracef not needed after this point.
        // We might double-close, but that's fine; we ignore the error.
        tracef.Close()

[cagedmantis]

@golang/runtime

[mknyszek]

Oops! This is an embarrassing oversight. Yeah, all the underlying code was ported, but the command-line flags got lost.

[gopherbot]

Change https://go.dev/cl/578318 mentions this issue: cmd/trace/v2: handle the -pprof flag

[gopherbot]

Change https://go.dev/cl/578356 mentions this issue: cmd/trace/v2: make the -pprof actually useful

[mknyszek]

It gets worse -- turns out for a long time the -pprof flags would produce profiles that accidentally filter out every goroutine. I sent https://go.dev/cl/578356 to fix this for at least the new traces.

[matthewhughes-uw]

Thanks for the quick fix!

[gopherbot]

Change https://go.dev/cl/600255 mentions this issue: cmd/trace/v2: handle the -pprof flag

[gopherbot]

Change https://go.dev/cl/600275 mentions this issue: cmd/trace/v2: make the -pprof actually useful