Golang cmd/trace: syscall profile omits most events

$ go version
go version go1.26-devel_4ab1aec007 Fri Aug 1 11:56:27 2025 -0700 darwin/arm64

The "go tool trace" command provides access to some execution tracing data in pprof format, including the calling context, count, and duration of the program's (non-raw) syscalls.

It's described in the "go tool trace" web UI as: "All four profiles represent causes of delay that prevent a goroutine from running on a logical processor: because it was waiting for the network, for a synchronization operation on a mutex or channel, for a system call, or for a logical processor to become available."

The filtering is incorrect for the syscall profile. (I haven't verified the other three profile types.) It depends on a StateTransition event into the Syscall state which includes a stack (good), but it fails to find the end of the syscall because it expects another StateTransition event out of the Syscall state which also includes a stack. The event marking the end of a syscall doesn't have a call stack, so it's not detected.

This results in most of the Syscall events being absent from the profile. Here's a reproducer demonstrating the problem: a goroutine calls hidden1 to do a single syscall and exit, another goroutine calls hidden2 to do two syscalls and then exit, and a third goroutine calls visible which does a single syscall but also takes care to generate a non-syscall-related StateTransition event which contains a stack before exiting. Only the visible goroutine ends up in the profile.

All four syscalls across all three goroutines should appear in the profile, with durations corresponding to the time between the "Running->Syscall" and "Syscall->Running" StateTransition events.

CC @mknyszek @cagedmantis

Here's the incorrect tool behavior:

$ go version
go version go1.26-devel_4ab1aec007 Fri Aug 1 11:56:27 2025 -0700 darwin/arm64

$ go run /tmp/trace-pprof-syscall.go -trace /tmp/t1

$ go tool trace -pprof=syscall /tmp/t1 > /tmp/p1

$ go tool pprof -traces /tmp/p1
Main binary filename not available.
Type: delay
-----------+-------------------------------------------------------
    6.78us   syscall.Stat
             os.statNolog.func1
             os.ignoringEINTR
             os.statNolog
             os.Stat
             main.stat
             main.visible
-----------+-------------------------------------------------------

And the relevant contents of the execution trace:

$ go run github.com/rhysh/go-tracing-toolbox/cmd/etgrep -input /tmp/t1 | grep Syscall
M=8667515904 P=0 G=8 StateTransition Time=2303192401384704 Resource=Goroutine(8) Reason="" GoID=8 Running->Syscall
M=8667515904 P=0 G=8 StateTransition Time=2303192401390912 Resource=Goroutine(8) Reason="" GoID=8 Syscall->Running
M=8667515904 P=0 G=7 StateTransition Time=2303192401392832 Resource=Goroutine(7) Reason="" GoID=7 Running->Syscall
M=8667515904 P=0 G=7 StateTransition Time=2303192401395584 Resource=Goroutine(7) Reason="" GoID=7 Syscall->Running
M=8667515904 P=0 G=7 StateTransition Time=2303192401396160 Resource=Goroutine(7) Reason="" GoID=7 Running->Syscall
M=6161674240 P=2 G=6 StateTransition Time=2303192401396416 Resource=Goroutine(6) Reason="" GoID=6 Running->Syscall
M=8667515904 P=0 G=7 StateTransition Time=2303192401398656 Resource=Goroutine(7) Reason="" GoID=7 Syscall->Running
M=6161674240 P=2 G=6 StateTransition Time=2303192401403584 Resource=Goroutine(6) Reason="" GoID=6 Syscall->Running

$ go run github.com/rhysh/go-tracing-toolbox/cmd/etgrep -input /tmp/t1 -stacks -goroutine 6
M=6161674240 P=2 G=-1 StateTransition Time=2303192401381120 Resource=Goroutine(6) Reason="" GoID=6 Runnable->Running
M=6161674240 P=2 G=6 Metric Time=2303192401393856 Name="/memory/classes/heap/objects:bytes" Value=Value{Uint64(2752512)}
M=6161674240 P=2 G=6 Metric Time=2303192401395392 Name="/memory/classes/heap/objects:bytes" Value=Value{Uint64(2760704)}
M=6161674240 P=2 G=6 StateTransition Time=2303192401396416 Resource=Goroutine(6) Reason="" GoID=6 Running->Syscall
  100c79577 syscall.Stat /usr/local/go/src/syscall/zsyscall_darwin_arm64.go:1963
  100c8843f os.statNolog.func1 /usr/local/go/src/os/stat_unix.go:32
  100c88430 os.ignoringEINTR /usr/local/go/src/os/file_posix.go:256
  100c88420 os.statNolog /usr/local/go/src/os/stat_unix.go:31
  100c8807f os.Stat /usr/local/go/src/os/stat.go:13
  100c9a707 main.stat /tmp/trace-pprof-syscall.go:38
  100c9a76b main.hidden1 /tmp/trace-pprof-syscall.go:45
M=6161674240 P=2 G=6 StateTransition Time=2303192401403584 Resource=Goroutine(6) Reason="" GoID=6 Syscall->Running
M=6161674240 P=2 G=6 StateTransition Time=2303192401403968 Resource=Goroutine(6) Reason="" GoID=6 Running->NotExist

$ go run github.com/rhysh/go-tracing-toolbox/cmd/etgrep -input /tmp/t1 -stacks -goroutine 7
M=8667515904 P=0 G=-1 StateTransition Time=2303192401392256 Resource=Goroutine(7) Reason="" GoID=7 Runnable->Running
M=8667515904 P=0 G=7 StateTransition Time=2303192401392832 Resource=Goroutine(7) Reason="" GoID=7 Running->Syscall
  100c79577 syscall.Stat /usr/local/go/src/syscall/zsyscall_darwin_arm64.go:1963
  100c8843f os.statNolog.func1 /usr/local/go/src/os/stat_unix.go:32
  100c88430 os.ignoringEINTR /usr/local/go/src/os/file_posix.go:256
  100c88420 os.statNolog /usr/local/go/src/os/stat_unix.go:31
  100c8807f os.Stat /usr/local/go/src/os/stat.go:13
  100c9a707 main.stat /tmp/trace-pprof-syscall.go:38
  100c9a7ab main.hidden2 /tmp/trace-pprof-syscall.go:49
M=8667515904 P=0 G=7 StateTransition Time=2303192401395584 Resource=Goroutine(7) Reason="" GoID=7 Syscall->Running
M=8667515904 P=0 G=7 StateTransition Time=2303192401396160 Resource=Goroutine(7) Reason="" GoID=7 Running->Syscall
  100c79577 syscall.Stat /usr/local/go/src/syscall/zsyscall_darwin_arm64.go:1963
  100c8843f os.statNolog.func1 /usr/local/go/src/os/stat_unix.go:32
  100c88430 os.ignoringEINTR /usr/local/go/src/os/file_posix.go:256
  100c88420 os.statNolog /usr/local/go/src/os/stat_unix.go:31
  100c8807f os.Stat /usr/local/go/src/os/stat.go:13
  100c9a707 main.stat /tmp/trace-pprof-syscall.go:38
  100c9a7af main.hidden2 /tmp/trace-pprof-syscall.go:50
M=8667515904 P=0 G=7 StateTransition Time=2303192401398656 Resource=Goroutine(7) Reason="" GoID=7 Syscall->Running
M=8667515904 P=0 G=7 StateTransition Time=2303192401398912 Resource=Goroutine(7) Reason="" GoID=7 Running->NotExist

$ go run github.com/rhysh/go-tracing-toolbox/cmd/etgrep -input /tmp/t1 -stacks -goroutine 8
M=8667515904 P=0 G=-1 StateTransition Time=2303192401383872 Resource=Goroutine(8) Reason="" GoID=8 Runnable->Running
M=8667515904 P=0 G=8 StateTransition Time=2303192401384704 Resource=Goroutine(8) Reason="" GoID=8 Running->Syscall
  100c79577 syscall.Stat /usr/local/go/src/syscall/zsyscall_darwin_arm64.go:1963
  100c8843f os.statNolog.func1 /usr/local/go/src/os/stat_unix.go:32
  100c88430 os.ignoringEINTR /usr/local/go/src/os/file_posix.go:256
  100c88420 os.statNolog /usr/local/go/src/os/stat_unix.go:31
  100c8807f os.Stat /usr/local/go/src/os/stat.go:13
  100c9a707 main.stat /tmp/trace-pprof-syscall.go:38
  100c9a7eb main.visible /tmp/trace-pprof-syscall.go:54
M=8667515904 P=0 G=8 StateTransition Time=2303192401390912 Resource=Goroutine(8) Reason="" GoID=8 Syscall->Running
M=8667515904 P=0 G=8 StateTransition Time=2303192401391488 Resource=Goroutine(8) Reason="sleep" GoID=8 Running->Waiting
  100c5d5ef time.Sleep /usr/local/go/src/runtime/time.go:363
  100c9a7f7 main.visible /tmp/trace-pprof-syscall.go:55
M=6160527360 P=3 G=-1 StateTransition Time=2303192402542400 Resource=Goroutine(8) Reason="" GoID=8 Waiting->Runnable
M=6160527360 P=3 G=-1 StateTransition Time=2303192402545536 Resource=Goroutine(8) Reason="" GoID=8 Runnable->Running
M=6160527360 P=3 G=8 StateTransition Time=2303192402545856 Resource=Goroutine(8) Reason="" GoID=8 Running->NotExist

And the reproducer:

$ cat /tmp/trace-pprof-syscall.go
package main

import (
        "bytes"
        "flag"
        "log"
        "os"
        "runtime/trace"
        "time"
)

func main() {
        out := flag.String("trace", "", "Path to execution trace file")
        flag.Parse()

        var buf bytes.Buffer
        err := trace.Start(&buf)
        if err != nil {
                log.Fatalf("trace.Start: %v", err)
        }
        defer func() {
                trace.Stop()

                err = os.WriteFile(*out, buf.Bytes(), 0600)
                if err != nil {
                        log.Fatalf("os.WriteFile: %v", err)
                }
        }()

        go hidden1()
        go hidden2()
        go visible()

        time.Sleep(10 * time.Millisecond)
}

func stat() {
        _, err := os.Stat(".")
        if err != nil {
                log.Fatalf("os.Stat: %v", err)
        }
}

func hidden1() {
        stat()
}

func hidden2() {
        stat()
        stat()
}

func visible() {
        stat()
        time.Sleep(1 * time.Millisecond)
}

Comment From: gabyhelp

Related Issues

• cmd/trace: visualize time taken by syscall #57307 (closed)
• cmd/pprof: macOS 10.12 profile overcounts system calls #17406 (closed)
• runtime/pprof: syscall exit trace processing is buggy #11262 (closed)
• runtime/pprof: TestCPUProfileWithFork is flaky #18349 (closed)
• runtime/pprof: TestStackBarrierProfiling hangs #15477 (closed)
• runtime/pprof: under-samples work on short-lived threads #40435 (closed)
• runtime/pprof: Missing labels from goroutines stacks containing systemstack #48577 (closed)
• runtime: timeout in runtime/pprof on linux-amd64-race #18884 (closed)
• runtime/pprof: collecting a CPU profile takes ~200ms of wall time #63043

Related Code Changes

• runtime: replace sysBlockTraced with tracedSyscallEnter

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}