Skip to content

runtime: stop-the-world never completes while goroutines are blocked in read(2) on a pipe (go1.26 regression) #81759

Open

Description

@sb10

Go version

go version go1.27.1 linux/amd64 (also go1.26.0, go1.26.3 and go1.26.8; go1.25.5 is not affected)

Output of go env in your module/workspace:

AR='ar'
CC='gcc'
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_ENABLED='0'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
CXX='g++'
GCCGO='gccgo'
GO111MODULE=''
GOAMD64='v1'
GOARCH='amd64'
GOAUTH='netrc'
GOBIN='/nfs/users/nfs_s/sb10/go/bin'
GOCACHE='/nfs/users/nfs_s/sb10/.cache/go-build'
GOCACHEPROG=''
GODEBUG=''
GOENV='/nfs/users/nfs_s/sb10/.config/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFIPS140='off'
GOFLAGS=''
GOGCCFLAGS='-fPIC -m64 -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=/tmp/go-build2312301903=/tmp/go-build -gno-record-gcc-switches'
GOHOSTARCH='amd64'
GOHOSTOS='linux'
GOINSECURE=''
GOMOD='/dev/null'
GOMODCACHE='/nfs/users/nfs_s/sb10/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='linux'
GOPACKAGESDRIVER=''
GOPATH='/nfs/users/nfs_s/sb10/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/nfs/users/nfs_s/sb10/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.27.1.linux-amd64'
GOSUMDB='sum.golang.org'
GOTELEMETRY='on'
GOTELEMETRYDIR='/nfs/users/nfs_s/sb10/.config/go/telemetry'
GOTMPDIR=''
GOTOOLCHAIN='go1.27.1'
GOTOOLDIR='/nfs/users/nfs_s/sb10/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.27.1.linux-amd64/pkg/tool/linux_amd64'
GOVCS=''
GOVERSION='go1.27.1'
GOWORK=''
PKG_CONFIG='pkg-config'

What did you do?

The program below runs as three processes. The first process (the watcher) makes two FIFOs, req and rep. It then re-execs itself as a Go "server" and as a "feeder":

  • The server opens both FIFOs with blocking syscall.Open, so the fds are not in the netpoller. It starts 4 goroutines that each loop on syscall.Read(req, 1 byte) and then syscall.Write(rep, 1 byte). The main goroutine runs for { runtime.GC() }.
  • The feeder writes 1 byte to req, then blocks reading the 1-byte reply from rep, and repeats. It prints a line every 1000 round trips.
  • The watcher reads the feeder's output. If no line arrives for 5s it prints HUNG; if 30s pass without a stall it prints OK. It then kills the server and feeder process group and removes the FIFOs.

The feeder only writes the next byte after the server replies, so at most one reader goroutine has data at a time. The other readers stay blocked in read(2) for as long as the server is stalled.

Run it with go run main.go. Setting GOTRACEBACK=all makes the watcher send SIGQUIT to the hung server before killing it, so the goroutine dump goes to stderr.

Host: Ubuntu 22.04, Linux 5.15.0-153-generic x86_64, 8 vCPUs (Intel Xeon Skylake).

// Command stwhang shows a stop-the-world that never completes while
// goroutines sit in blocking read(2) calls on a FIFO that another process
// writes to only after it gets a reply.
//
// Run with no arguments. It re-execs itself twice: as the Go server under
// test, and as the feeder. The original process watches the feeder's progress
// and prints one verdict line.
package main

import (
	"bufio"
	"fmt"
	"os"
	"os/exec"
	"path/filepath"
	"runtime"
	"strings"
	"syscall"
	"time"
)

const (
	readers  = 4
	duration = 30 * time.Second
	stall    = 5 * time.Second
)

func main() {
	if len(os.Args) == 3 {
		switch os.Args[1] {
		case "server":
			server(os.Args[2])
		case "feeder":
			feeder(os.Args[2])
		}
		return
	}
	os.Exit(watch())
}

// server blocks readers goroutines in read(2) on dir/req, replies to each
// byte on dir/rep, and runs the GC back to back.
func server(dir string) {
	req := must(syscall.Open(filepath.Join(dir, "req"), syscall.O_RDONLY, 0))
	rep := must(syscall.Open(filepath.Join(dir, "rep"), syscall.O_WRONLY, 0))
	for i := 0; i < readers; i++ {
		go func() {
			buf := make([]byte, 1)
			for {
				if n, err := syscall.Read(req, buf); err == syscall.EINTR {
					continue
				} else if n != 1 {
					panic(fmt.Sprint("read: ", n, err))
				}
				must(syscall.Write(rep, buf))
			}
		}()
	}
	for {
		runtime.GC()
	}
}

// feeder writes one byte to dir/req, waits for the one-byte reply on dir/rep,
// and prints a line every 1000 round trips.
func feeder(dir string) {
	req := must(syscall.Open(filepath.Join(dir, "req"), syscall.O_WRONLY, 0))
	rep := must(syscall.Open(filepath.Join(dir, "rep"), syscall.O_RDONLY, 0))
	buf := []byte{'x'}
	for i := 1; ; i++ {
		must(syscall.Write(req, buf))
		if n := must(syscall.Read(rep, buf)); n != 1 {
			os.Exit(1)
		}
		if i%1000 == 0 {
			fmt.Println(i)
		}
	}
}

// watch starts the server and feeder, and reports HUNG if the feeder makes
// no progress for the stall period.
func watch() int {
	dir := must(os.MkdirTemp("", "stwhang"))
	defer os.RemoveAll(dir)
	for _, name := range []string{"req", "rep"} {
		must(0, syscall.Mkfifo(filepath.Join(dir, name), 0o600))
	}

	srv := exec.Command(os.Args[0], "server", dir)
	srv.Stderr = os.Stderr
	srv.SysProcAttr = &syscall.SysProcAttr{Setpgid: true}
	must(0, srv.Start())

	fdr := exec.Command(os.Args[0], "feeder", dir)
	fdr.SysProcAttr = &syscall.SysProcAttr{Setpgid: true, Pgid: srv.Process.Pid}
	out := must(fdr.StdoutPipe())
	must(0, fdr.Start())
	defer func() { // kill the server and feeder process group, then reap both
		syscall.Kill(-srv.Process.Pid, syscall.SIGKILL)
		srv.Wait()
		fdr.Wait()
	}()

	progress := make(chan string)
	go func() {
		for sc := bufio.NewScanner(out); sc.Scan(); {
			progress <- sc.Text()
		}
		close(progress)
	}()

	last, end := "0", time.After(duration)
	for {
		select {
		case p, ok := <-progress:
			if !ok {
				fmt.Printf("ERROR: feeder exited after %s round trips\n", last)
				return 2
			}
			last = p
		case <-time.After(stall):
			fmt.Printf("HUNG: %s: no progress for %s after %s round trips; server threads (wchan/state): %s\n",
				runtime.Version(), stall, last, threads(srv.Process.Pid))
			if os.Getenv("GOTRACEBACK") != "" {
				syscall.Kill(srv.Process.Pid, syscall.SIGQUIT)
				time.Sleep(2 * time.Second)
			}
			return 1
		case <-end:
			fmt.Printf("OK: %s: %s round trips in %s, no hang\n", runtime.Version(), last, duration)
			return 0
		}
	}
}

// threads counts the server's threads by kernel wait channel and state.
func threads(pid int) string {
	counts := map[string]int{}
	tasks, _ := filepath.Glob(fmt.Sprintf("/proc/%d/task/*", pid))
	for _, task := range tasks {
		wchan, _ := os.ReadFile(task + "/wchan")
		stat, _ := os.ReadFile(task + "/stat")
		state := "?"
		if f := strings.Fields(string(stat)); len(f) > 2 {
			state = f[2]
		}
		counts[string(wchan)+"/"+state]++
	}
	return fmt.Sprint(counts)
}

func must[T any](v T, err error) T {
	if err != nil {
		panic(err)
	}
	return v
}

What did you see happen?

On go1.26 and go1.27 the server stops replying, after anywhere from 1,000 to 307,000 round trips in these runs. It never recovers:

$ go run main.go
HUNG: go1.27.1: no progress for 5s after 101000 round trips; server threads (wchan/state): map[futex_wait_queue_me/S:11 pipe_read/S:3]

Hung runs per version, 30s per run (blank: not tried):

Version default (8 CPUs) GODEBUG=asyncpreemptoff=1 GOMAXPROCS=1 GOMAXPROCS=2 GOMAXPROCS=8
go1.25.5 0/10 0/5 0/5 0/5 0/5
go1.26.0 10/10
go1.26.3 10/10 5/5 0/5 4/5 5/5
go1.26.8 10/10
go1.27.1 10/10 5/5 0/5 4/5 5/5

In every hung run the server's threads were in the same kernel state, read from /proc/<pid>/task/*/{wchan,stat}: 3 threads sleeping in pipe_read and all the others in futex_wait_queue_me. In a few runs, one thread was also running (wchan 0, state R). The one reader that got the feeder's last byte has left read(2), but its reply never arrives. The feeder is blocked in pipe_read on rep.

The SIGQUIT dump (go1.27.1, trimmed to the relevant goroutines) shows a mark-termination stop-the-world in progress. The reader that returned from read(2) is [runnable] and has no M, and no goroutine is running. Goroutines 20 and 22 are the same as goroutine 19: [syscall], each still on an M. The other goroutines in the dump are idle GC workers, the finalizer, the sweeper, the scavenger, and a second mark worker in semacquire inside gcMarkDone.

goroutine 1 gp=0x10a627a101e0 m=nil [wait for GC cycle]:
runtime.gopark(0x10a627a9ecf0?, 0x10a627a52000?, 0x0?, 0x0?, 0x0?)
	$GOROOT/src/runtime/proc.go:474 +0xca
runtime.goparkunlock(...)
	$GOROOT/src/runtime/proc.go:480
runtime.gcWaitOnMark(0x19d2)
	$GOROOT/src/runtime/mgc.go:663 +0x5b
runtime.GC()
	$GOROOT/src/runtime/mgc.go:558 +0x45
main.server({0x7ffec3f40823, 0xa9})
	main.go:60 +0x136
main.main()
	main.go:32 +0x66
runtime.main()
	$GOROOT/src/runtime/proc.go:302 +0x427
runtime.goexit({})
	$GOROOT/src/runtime/asm_amd64.s:1264 +0x1

goroutine 19 gp=0x10a627b823c0 m=10 mp=0x10a627b01808 [syscall]:
syscall.Syscall(0x0, 0x5, 0x10a627a75777, 0x1)
	$GOROOT/src/syscall/syscall_linux.go:74 +0x25
syscall.read(0x5?, {0x10a627a75777?, 0x1?, 0x1?})
	$GOROOT/src/syscall/zsyscall_linux_amd64.go:736 +0x38
syscall.Read(...)
	$GOROOT/src/syscall/syscall_unix.go:183
main.server.func1()
	main.go:50 +0x46
runtime.goexit({})
	$GOROOT/src/runtime/asm_amd64.s:1264 +0x1
created by main.server in goroutine 1
	main.go:47 +0x11e

goroutine 21 gp=0x10a627b82780 m=nil [runnable]:
syscall.Syscall(0x0, 0x5, 0x10a627a76777, 0x1)
	$GOROOT/src/syscall/syscall_linux.go:74 +0x25
syscall.read(0x6?, {0x10a627a76777?, 0x1?, 0x1?})
	$GOROOT/src/syscall/zsyscall_linux_amd64.go:736 +0x38
syscall.Read(...)
	$GOROOT/src/syscall/syscall_unix.go:183
main.server.func1()
	main.go:50 +0x46
runtime.goexit({})
	$GOROOT/src/runtime/asm_amd64.s:1264 +0x1
created by main.server in goroutine 1
	main.go:47 +0x11e

goroutine 25 gp=0x10a627b82f00 m=5 mp=0x10a627c00008 [stopping the world]:
runtime.systemstack_switch()
	$GOROOT/src/runtime/asm_amd64.s:481 +0x8
runtime.gcMarkDone()
	$GOROOT/src/runtime/mgc.go:1065 +0x21f
runtime.gcBgMarkWorker(0x10a627b860e0)
	$GOROOT/src/runtime/mgc.go:1928 +0x2c5
runtime.gcBgMarkStartWorkers.gowrap1()
	$GOROOT/src/runtime/mgc.go:1711 +0x17
runtime.goexit({})
	$GOROOT/src/runtime/asm_amd64.s:1264 +0x1
created by runtime.gcBgMarkStartWorkers in goroutine 1
	$GOROOT/src/runtime/mgc.go:1711 +0xfc

What did you expect to see?

The program should run for the full 30s and print OK, as it does on go1.25.5. Goroutines blocked in a syscall should not stop the stop-the-world from completing. The reader that returned from its syscall should then run and reply.

Context: I found this in a FUSE server built on go-fuse, in wr. There, a process blocked on a FUSE request plays the feeder's role, and /dev/fuse plays req. The program above reproduces the hang without FUSE, cgo or third-party code. It is not #11155: nothing here forks, and no thread is blocked in vfork or chdir.

Suspected area (unverified): go1.26's change to how stop-the-world takes the Ps of goroutines in syscalls (_Psyscall removed; setBlockOnExitSyscall in runtime/proc.go).

Activity

  1. ianlancetaylor commented on Sep 25, 2026

    @ianlancetaylor
    Contributor

    CC @golang/runtime

  2. mknyszek commented on Sep 25, 2026

    @mknyszek
    Contributor

    I think I understand the problem here, and I think the hunch about setBlockOnExitSyscall is right. I suspect because we don't check gcwaiting after the CAS to _Gsyscall, we can end up failing to grab the P in stopTheWorld, and the syscalling goroutine never actually checks in with the GC. There's basically a race between checking and setting gcwaiting and _Gsyscall on the goroutine.

    I wrote here that this is just an optimization, but no, it's load-bearing.

    I think the fix is to move the gcwaiting check after the switch to _Gsyscall, but I unfortunately don't quite remember why I moved it before. (It used to be after.)

  3. mknyszek commented on Sep 25, 2026

    @mknyszek
    Contributor

    Oh, right. setBlockOnExitSyscall expects the goroutine to no longer own its P once it sets _Gsyscall. It can't actually trivially hand it off. Hm...

    Perhaps we could just repeat setBlockOnExitSyscall in the wait loop in stopTheWorld, just like we call preemptall. What we can rely upon for sure is that (1) if the goroutine exits the syscall, it will hand it off and (2) if we win the race, we'll block it from doing so and can safely take its P. I do think this would work.

  4. thepudds commented on Sep 26, 2026

    @thepudds
    Member

    Maybe not super useful, but FWIW this seemed to bisect to 7244e92:

      first BAD:   7244e9221f | 2025-10-30 17:08 | runtime: eliminate _Psyscall
      GOOD parent: 5ef19c0d0c | 2025-10-30 16:55 | strconv: delete divmod1e9
    

    (That's probably not a surprise to Michael K. Alternatively, if it is a surprise to Michael K., then it's probably wrong 😅)

  5. alex3d commented on Sep 28, 2026

    @alex3d

    We hit this independently, in a c-shared library called from JVM threads on arm64 and 32-bit ARM Android devices, where each stall lasted 60 or 120 s. We have changes along the lines @mknyszek suggested and will mail them shortly. Two things we found that aren't in the thread yet:

    Most misses aren't the entry race. On every tick sysmon's retake takes the scan bit of each goroutine in a system call, and only then decides whether to take its P; for short system calls it usually lets go without it. A sweep in stopTheWorldWithSema that meets the bit held fails its CAS and moves on. With a runtime that records every acquisition of such a scan bit, all of the ~15 stalls we caught on darwin/arm64, windows/amd64 and linux/arm64 (Android) were this: the sweep found the goroutine in _Gsyscall|_Gscan, with retake the last to take the bit, within a few µs of the sweep. Several were on a build that publishes _Gsyscall before checking gcwaiting, so publishing first isn't enough; repeating the sweep catches both. Publishing first also costs: in our benchmarks it slowed cgo calls by up to 3%, or 5% when made from every P at once, on four of nine machines.

    forEachP has the same race. reentersyscall checks runSafePointFn before it publishes too, and forEachPInternal sweeps once. sysmon is awake then, but leaves the P alone for 10ms while other Ps are idle, so the ragged barrier waits that long: about a hundred forEachP calls a minute over 10ms on darwin/arm64 in the program below with a 2s timer, and about ten on an arm64 Android device.

    The stall lasts until sysmon wakes: it deep-sleeps while gcwaiting is set, for forcegcperiod/2 or until the next timer. So a pending timer caps it, and GODEBUG=schedtrace= any positive value removes it.

    A single-process reproducer. On go1.27.1 it stalls within minutes on darwin/arm64, linux/arm64 (Android) and windows/amd64 and arm64 (with CreatePipe). On x86-64 Linux it didn't stall in 5-minute runs, but a usleep(200) between the check of gcwaiting and the publish of _Gsyscall in reentersyscall makes it stall within 40 reads on every port we tried.

    package main
    
    import (
    	"log"
    	"runtime"
    	"syscall"
    	"time"
    )
    
    func main() {
    	var p [2]int
    	if err := syscall.Pipe(p[:]); err != nil { // blocking, not in the netpoller
    		log.Fatal(err)
    	}
    	go func() { // a pending timer caps a stall at about 10s; remove to see 60s
    		for {
    			time.Sleep(10 * time.Second)
    		}
    	}()
    	go func() {
    		for {
    			syscall.Write(p[1], make([]byte, 1<<20)[:1]) // allocate to keep the GC busy
    		}
    	}()
    	b := make([]byte, 64<<10)
    	for reads := 1; ; reads++ {
    		start := time.Now()
    		syscall.Read(p[0], b)
    		if took := time.Since(start); took > time.Second {
    			var m runtime.MemStats
    			runtime.ReadMemStats(&m)
    			log.Fatalf("a read took %.3f s after %d reads and %d GCs", took.Seconds(), reads, m.NumGC)
    		}
    	}
    }

    The changes:

    1. Repeat the sweep in the wait loops of both the stop and forEachP, taking a missed P as retake does (setBlockOnExitSyscall, takeP, resume, handoffp). It adds no lock and catches both kinds of miss; a miss costs one more 100µs wait.
    2. On top of it, right after the first sweep of the stop and of forEachP, retry a held scan bit for up to 10µs in total, holding no lock, so the common miss doesn't wait for the loop.

    With both, the reproducer ran 32 times for 5 minutes without a stall on darwin/arm64, linux/{arm64,arm,386,amd64} and windows/{amd64,arm64}, half of them with the window widened. Syscall and cgo call benchmarks, including internal/runtime/cgobench, and stop-the-world pause metrics didn't change on the machines we measured. Both touch the same if wait blocks as CL 837887 (#81657); whichever lands second is a trivial rebase.

    @mknyszek, would you prefer these as two CLs in a chain, so the second can be judged on its own, or folded into one?

    Since this is a regression in 1.26 with no fix but a runtime setting, could it be considered for backport to 1.26 and 1.27?

  6. mknyszek commented on Sep 28, 2026

    @mknyszek
    Contributor

    I thought of retake -- yeah, that shouldn't matter, and I don't think it's worth fixing. It's already best-effort. It's a very narrow race window, and if we miss it, then we'll just wait O(µs) if the system isn't particularly idle. There are almost certainly worse delays there already anyway.

    Good catch on forEachP.

    @mknyszek, would you prefer these as two CLs in a chain, so the second can be judged on its own, or folded into one

    One CL for everything is preferable, though without seeing the code I'm not 100% sure what you mean by (2).

    Since this is a regression in 1.26 with no fix but a runtime setting, could it be considered for backport to 1.26 and 1.27?

    Yes, it should be backported. It can cause global hangs with no workaround.

    That's probably not a surprise to Michael K.

    Yeah, not a surprise.

    Alternatively, if it is a surprise to Michael K., then it's probably wrong

    I make plenty of bad guesses... I did verify this one (just by looking at the logic in the code) though before posting. :P

  7. mknyszek commented on Sep 28, 2026

    @mknyszek
    Contributor

    Oh, and I also see what you're saying about retake, that it sort of saves us here from a complete hang sometimes, because retake comes in and takes the P back, it just might take a while.

    Again, I think the race window here is so small that just trying twice is almost certainly going to fix the issue in practice. I would even suggest to check again before waiting (at the top of the wait loop, instead of where preemptall is called). I think this solution is reasonable to backport.

    A full fix (which is definitely not reasonable to backport) would be to detach the P before the _Gsyscall commit point and put it in a 'staging' area non-atomically. If we see gcwaiting after _Gsyscall, both reentersyscall and the scheduler can try to CAS it out of that staging area. The scheduler would still be required to hold the _Gscan bit while doing so, so there's a guarantee that the P can't be removed from the staging area out from under it except via a race on the CAS, which is safe. This makes it possible for reentersyscall to return the P by itself. I haven't fully thought this through, but I think this would work without adding any new atomics to the fast path. There may be some other things that rely on walking the G->M->P chain optimistically that would need be handled carefully.

  8. alex3d commented on Sep 28, 2026

    @alex3d

    Sent as #81835: one CL, retaking before each wait in both the stop and forEachP, as you suggested.

    On (2): it was a spin of up to 10µs on the first retake while the scan bit was still held. We measured it against the version in the CL on darwin, linux (amd64, arm64, arm) and windows (amd64, arm64). On darwin/arm64 forEachP ran about 1.5M times a minute, 99.9% of them under 50µs; its wait loop still had to take a P after a sleep about 130 times a minute without the spin and 65 with it. That saves at most a few ms of forEachP time a minute, lost among the several hundred calls a minute that take over 100µs for other reasons. Stops almost never needed that wait either way, and no other platform showed a difference. So we dropped it: the retake before the first wait is enough.

  9. gopherbot commented on Sep 28, 2026

    @gopherbot
    Contributor

    Change https://go.dev/cl/840845 mentions this issue: runtime: retake syscall Ps in stopTheWorld's and forEachP's wait loops

  10. added
    NeedsInvestigationSomeone must examine and confirm this is a valid issue and not a duplicate of an existing one.
    on Sep 29, 2026
  11. prattmic commented on Sep 29, 2026

    @prattmic
    Member

    cc @golang/runtime

  12. self-assigned this
    on Sep 29, 2026
  13. gopherbot commented on Oct 1, 2026

    @gopherbot
    Contributor

    Change https://go.dev/cl/843245 mentions this issue: runtime: test that stopping the world retakes Ps from cgo callbacks

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

NeedsInvestigationSomeone must examine and confirm this is a valid issue and not a duplicate of an existing one.compiler/runtimeIssues related to the Go compiler and/or runtime.

Type

No type

Projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions