Skip to content

runtime: failure to detect write barriers inside nowritebarrierrec / questionable write barriers #73430

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Open
dr2chase opened this issue Apr 17, 2025 · 8 comments
Open

runtime: failure to detect write barriers inside nowritebarrierrec / questionable write barriers #73430

dr2chase opened this issue Apr 17, 2025 · 8 comments
Assignees
@mknyszek @JunyangShao
Labels
BugReport Issues describing a possible bug in the Go implementation. compiler/runtime Issues related to the Go compiler and/or runtime. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Backlog

Comments

@dr2chase
Copy link
Contributor

Go version

near dev tip as of mid-April 2025, e.g. 13b7c7d

Output of go env in your module/workspace:

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/drchase/Library/Caches/go-build'
GOCACHEPROG=''
GODEBUG=''
GOENV='/Users/drchase/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/mz/1gp2q1rx7cj2_g_j8sml9kc40095tn/T/go-build343059180=/tmp/go-build -gno-record-gcc-switches -fno-common'
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMOD='/Users/drchase/work/go-quick/src/go.mod'
GOMODCACHE='/Users/drchase/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/drchase/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/Users/drchase/work/go-quick'
GOSUMDB='sum.golang.org'
GOTELEMETRY='on'
GOTELEMETRYDIR='/Users/drchase/Library/Application Support/go/telemetry'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/Users/drchase/work/go-quick/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='devel go1.25-13b7c7d8d2 Sun Apr 13 20:20:58 2025 -0700'
GOWORK=''
PKG_CONFIG='pkg-config'

What did you do?

For other reasons, I modified the inlining budget from 80 to 800, then tried to rebuild with ./make.bash

What did you see happen?

A slow, bloated build.

What did you expect to see?

(annotated to add more information so as to avoid repeated work)

gp.syncGroup = nil
/Users/drchase/work/go-quick/src/runtime/mgc.go:646:16: write barrier prohibited by caller; gcStart
	/Users/drchase/work/go-quick/src/runtime/malloc.go:1427:11: called by mallocgcSmallScanNoHeader
	/Users/drchase/work/go-quick/src/runtime/malloc.go:1059:44: called by mallocgc
	/Users/drchase/work/go-quick/src/runtime/malloc.go:1716:17: called by newobject
	/Users/drchase/work/go-quick/src/runtime/mprof.go:322:10: called by stkbucket
	/Users/drchase/work/go-quick/src/runtime/mgcmark.go:816:8: called by gcFlushBgCredit


gp.syncGroup = nil
/Users/drchase/work/go-quick/src/runtime/mgcmark.go:436:16: write barrier prohibited by caller; gcAssistAlloc
	/Users/drchase/work/go-quick/src/runtime/malloc.go:1041:21: called by mallocgc
	/Users/drchase/work/go-quick/src/runtime/malloc.go:1716:17: called by newobject
	/Users/drchase/work/go-quick/src/runtime/mprof.go:322:10: called by stkbucket
	/Users/drchase/work/go-quick/src/runtime/mgcmark.go:816:8: called by gcFlushBgCredit


span.largeType = nil // Tell the GC not to look at this yet.
/Users/drchase/work/go-quick/src/runtime/malloc.go:1545:17: write barrier prohibited by caller; mallocgcLarge
	/Users/drchase/work/go-quick/src/runtime/malloc.go:1065:30: called by mallocgc
	/Users/drchase/work/go-quick/src/runtime/malloc.go:1716:17: called by newobject
	/Users/drchase/work/go-quick/src/runtime/mprof.go:322:10: called by stkbucket
	/Users/drchase/work/go-quick/src/runtime/mgcmark.go:816:8: called by gcFlushBgCredit


!!! finc.alllink = allfin (in queuefinalizer)
/Users/drchase/work/go-quick/src/runtime/mheap.go:2463:17: write barrier prohibited by caller; freeSpecial
	/Users/drchase/work/go-quick/src/runtime/mgcsweep.go:599:16: called by (*sweepLocked).sweep
	/Users/drchase/work/go-quick/src/runtime/mcache.go:160:43: called by (*mcache).refill
	/Users/drchase/work/go-quick/src/runtime/malloc.go:961:11: called by (*mcache).nextFree
	/Users/drchase/work/go-quick/src/runtime/malloc.go:1368:39: called by mallocgcSmallScanNoHeader
	/Users/drchase/work/go-quick/src/runtime/malloc.go:1059:44: called by mallocgc
	/Users/drchase/work/go-quick/src/runtime/malloc.go:1716:17: called by newobject
	/Users/drchase/work/go-quick/src/runtime/mprof.go:322:10: called by stkbucket
	/Users/drchase/work/go-quick/src/runtime/mgcmark.go:816:8: called by gcFlushBgCredit


!!! *header = typ (in heapSetTypeSmallHeader)
/Users/drchase/work/go-quick/src/runtime/malloc.go:1474:39: write barrier prohibited by caller; mallocgcSmallScanHeader
	/Users/drchase/work/go-quick/src/runtime/malloc.go:1061:42: called by mallocgc
	/Users/drchase/work/go-quick/src/runtime/malloc.go:1716:17: called by newobject
	/Users/drchase/work/go-quick/src/runtime/mprof.go:322:10: called by stkbucket
	/Users/drchase/work/go-quick/src/runtime/mgcmark.go:816:8: called by gcFlushBgCredit

I see several things going on here.

First, it indeed looks like operations that are superficially write-barrier triggering. They may not all be "real" write barriers, but they are definitely stores of pointer values into data structures.

Second, they were not detected until the inlining was turned very far up. There might be other write barriers that aren't getting detected.

Third, I think we need to fix the stack traces in the write-barrier-rec report, because inlining is missing I think, some of those I had to figure out carefully.
@gopherbot gopherbot added the compiler/runtime Issues related to the Go compiler and/or runtime. label Apr 17, 2025
@dr2chase
Copy link
Contributor Author

@golang/compiler

I initially thought this was not a problem because it all hangs on an unlock at the end of gcFlushBgCredit, but then realized that the caller depends on this. And also, not detected.

@gabyhelp
Copy link

Related Issues

Related Code Changes

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

@gabyhelp gabyhelp added the BugReport Issues describing a possible bug in the Go implementation. label Apr 17, 2025
@prattmic
Copy link
Member

cc @golang/runtime

@prattmic prattmic added this to the Backlog milestone Apr 18, 2025
@prattmic prattmic added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Apr 18, 2025
@mknyszek
Copy link
Contributor

One thing that's a little confusing is why it looks like stkbucket is being called by gcFlushBgCredit. I don't see calls there, and the CPU profiling signal handler doesn't allocate...

(Referring to:)

span.largeType = nil // Tell the GC not to look at this yet.
/Users/drchase/work/go-quick/src/runtime/malloc.go:1545:17: write barrier prohibited by caller; mallocgcLarge
	/Users/drchase/work/go-quick/src/runtime/malloc.go:1065:30: called by mallocgc
	/Users/drchase/work/go-quick/src/runtime/malloc.go:1716:17: called by newobject
	/Users/drchase/work/go-quick/src/runtime/mprof.go:322:10: called by stkbucket
	/Users/drchase/work/go-quick/src/runtime/mgcmark.go:816:8: called by gcFlushBgCredit

@prattmic
Copy link
Member

unlock -> unlockWithRank -> unlock2 -> (*mLockProfile).recordUnlock -> (*mLockProfile).store -> saveBlockEventStack -> stkbucket

@prattmic
Copy link
Member

cc @rhysh

1 similar comment
@prattmic
Copy link
Member

cc @rhysh

@rhysh
Copy link
Contributor

rhysh commented Apr 24, 2025

I can reproduce the failure by changing inlineMaxBudget in src/cmd/compile/internal/inline/inl.go from 80 to 800 and running ./make.bash. I'm trying to make sense of the error message. The full output I see includes a complaint of "lostStk escapes to heap".

gcFlushBgCredit at mgcmark.go:816 makes a call to unlock. That can eventually lead to a stkbucket call as @prattmic described. But mprof.go:322 is another call to unlock. I don't see an allocation at that line.

gcFlushBgCredit is //go:nowritebarrierrec.
unlock has no WB annotations.
unlockWithRank has no WB annotations.
unlock2 is //go:nowritebarrier.
(*mLockProfile).recordUnlock is //go:nowritebarrierrec.
(*mLockProfile).store has no WB annotations.
saveBlockEventStack has no WB annotations.
stkbucket has no WB annotations.
unlock (again) has no WB annotations.

But part of the output I see is /usr/local/go/src/runtime/mprof.go:322:10: lostStk escapes to heap, not allowed in runtime. That's part of (*mLockProfile).store. If I move lostStk to a package-level variable, then I get a build that ends with "signal: killed", which I interpret as the "slow, bloated build" that @dr2chase expected.

I haven't found why lostStk is interpreted as escaping for this build (but not for others). That may be the cause of the newobject calls, and thus be the root cause of the WB complaints.

$ git rev-parse HEAD
702f164ed1a4a64cfa60e10723b9b7344bd3f601

$ git diff
diff --git a/src/cmd/compile/internal/inline/inl.go b/src/cmd/compile/internal/inline/inl.go
index e30de3d8c8..4dc1a6f3f3 100644
--- a/src/cmd/compile/internal/inline/inl.go
+++ b/src/cmd/compile/internal/inline/inl.go
@@ -47,7 +47,7 @@ import (
 
 // Inlining budget parameters, gathered in one place
 const (
-       inlineMaxBudget       = 80
+       inlineMaxBudget       = 800
        inlineExtraAppendCost = 0
        // default is to inline if there's at most one call. -l=4 overrides this by using 1 instead.
        inlineExtraCallCost  = 57              // 57 was benchmarked to provided most benefit with no bad surprises; see https://github.com/golang/go/issues/19348#issuecomment-439370742

$ (cd ./src && ./make.bash)
Building Go cmd/dist using /Users/rhysh/sdk/go1.22.6. (go1.22.6 darwin/arm64)
Building Go toolchain1 using /Users/rhysh/sdk/go1.22.6.
Building Go bootstrap cmd/go (go_bootstrap) using Go toolchain1.
/usr/local/go/src/runtime/mgc.go:646:16: write barrier prohibited by caller; gcStart
	/usr/local/go/src/runtime/malloc.go:1429:11: called by mallocgcSmallScanNoHeader
	/usr/local/go/src/runtime/malloc.go:1061:44: called by mallocgc
	/usr/local/go/src/runtime/malloc.go:1718:17: called by newobject
	/usr/local/go/src/runtime/mprof.go:322:10: called by stkbucket
	/usr/local/go/src/runtime/mgcmark.go:816:8: called by gcFlushBgCredit
/usr/local/go/src/runtime/mgcmark.go:436:16: write barrier prohibited by caller; gcAssistAlloc
	/usr/local/go/src/runtime/malloc.go:1043:21: called by mallocgc
	/usr/local/go/src/runtime/malloc.go:1718:17: called by newobject
	/usr/local/go/src/runtime/mprof.go:322:10: called by stkbucket
	/usr/local/go/src/runtime/mgcmark.go:816:8: called by gcFlushBgCredit
/usr/local/go/src/runtime/malloc.go:1547:17: write barrier prohibited by caller; mallocgcLarge
	/usr/local/go/src/runtime/malloc.go:1067:30: called by mallocgc
	/usr/local/go/src/runtime/malloc.go:1718:17: called by newobject
	/usr/local/go/src/runtime/mprof.go:322:10: called by stkbucket
	/usr/local/go/src/runtime/mgcmark.go:816:8: called by gcFlushBgCredit
/usr/local/go/src/runtime/mheap.go:2464:17: write barrier prohibited by caller; freeSpecial
	/usr/local/go/src/runtime/mgcsweep.go:599:16: called by (*sweepLocked).sweep
	/usr/local/go/src/runtime/mcache.go:161:43: called by (*mcache).refill
	/usr/local/go/src/runtime/malloc.go:963:11: called by (*mcache).nextFree
	/usr/local/go/src/runtime/malloc.go:1370:39: called by mallocgcSmallScanNoHeader
	/usr/local/go/src/runtime/malloc.go:1061:44: called by mallocgc
	/usr/local/go/src/runtime/malloc.go:1718:17: called by newobject
	/usr/local/go/src/runtime/mprof.go:322:10: called by stkbucket
	/usr/local/go/src/runtime/mgcmark.go:816:8: called by gcFlushBgCredit
/usr/local/go/src/runtime/mprof.go:322:10: lostStk escapes to heap, not allowed in runtime
/usr/local/go/src/runtime/malloc.go:1476:39: write barrier prohibited by caller; mallocgcSmallScanHeader
	/usr/local/go/src/runtime/malloc.go:1063:42: called by mallocgc
	/usr/local/go/src/runtime/malloc.go:1718:17: called by newobject
	/usr/local/go/src/runtime/mprof.go:322:10: called by stkbucket
	/usr/local/go/src/runtime/mgcmark.go:816:8: called by gcFlushBgCredit

go tool dist: FAILED: /usr/local/go/pkg/tool/darwin_arm64/compile -std -pack -o /var/folders/pw/d_qmtcrd3vs0890gvmrq8qx80000gn/T/go-tool-dist-3995220440/runtime/_go_.a -p runtime -importcfg /var/folders/pw/d_qmtcrd3vs0890gvmrq8qx80000gn/T/go-tool-dist-3995220440/runtime/importcfg -asmhdr /var/folders/pw/d_qmtcrd3vs0890gvmrq8qx80000gn/T/go-tool-dist-3995220440/runtime/go_asm.h -symabis /var/folders/pw/d_qmtcrd3vs0890gvmrq8qx80000gn/T/go-tool-dist-3995220440/runtime/symabis /usr/local/go/src/runtime/alg.go /usr/local/go/src/runtime/arena.go /usr/local/go/src/runtime/asan0.go /usr/local/go/src/runtime/atomic_pointer.go /usr/local/go/src/runtime/badlinkname.go /usr/local/go/src/runtime/cgo.go /usr/local/go/src/runtime/cgocall.go /usr/local/go/src/runtime/cgocallback.go /usr/local/go/src/runtime/cgocheck.go /usr/local/go/src/runtime/chan.go /usr/local/go/src/runtime/checkptr.go /usr/local/go/src/runtime/compiler.go /usr/local/go/src/runtime/complex.go /usr/local/go/src/runtime/coro.go /usr/local/go/src/runtime/covercounter.go /usr/local/go/src/runtime/covermeta.go /usr/local/go/src/runtime/cpuflags.go /usr/local/go/src/runtime/cpuflags_arm64.go /usr/local/go/src/runtime/cpuprof.go /usr/local/go/src/runtime/create_file_unix.go /usr/local/go/src/runtime/debug.go /usr/local/go/src/runtime/debugcall.go /usr/local/go/src/runtime/debuglog.go /usr/local/go/src/runtime/debuglog_off.go /usr/local/go/src/runtime/defs_darwin_arm64.go /usr/local/go/src/runtime/env_posix.go /usr/local/go/src/runtime/error.go /usr/local/go/src/runtime/extern.go /usr/local/go/src/runtime/fastlog2.go /usr/local/go/src/runtime/fastlog2table.go /usr/local/go/src/runtime/fds_unix.go /usr/local/go/src/runtime/float.go /usr/local/go/src/runtime/hash64.go /usr/local/go/src/runtime/heapdump.go /usr/local/go/src/runtime/histogram.go /usr/local/go/src/runtime/iface.go /usr/local/go/src/runtime/lfstack.go /usr/local/go/src/runtime/linkname.go /usr/local/go/src/runtime/linkname_unix.go /usr/local/go/src/runtime/lock_sema.go /usr/local/go/src/runtime/lock_spinbit.go /usr/local/go/src/runtime/lockrank.go /usr/local/go/src/runtime/lockrank_off.go /usr/local/go/src/runtime/malloc.go /usr/local/go/src/runtime/map_fast32_noswiss.go /usr/local/go/src/runtime/map_fast64_noswiss.go /usr/local/go/src/runtime/map_faststr_noswiss.go /usr/local/go/src/runtime/map_noswiss.go /usr/local/go/src/runtime/mbarrier.go /usr/local/go/src/runtime/mbitmap.go /usr/local/go/src/runtime/mcache.go /usr/local/go/src/runtime/mcentral.go /usr/local/go/src/runtime/mcheckmark.go /usr/local/go/src/runtime/mcleanup.go /usr/local/go/src/runtime/mem.go /usr/local/go/src/runtime/mem_darwin.go /usr/local/go/src/runtime/mem_nonsbrk.go /usr/local/go/src/runtime/metrics.go /usr/local/go/src/runtime/mfinal.go /usr/local/go/src/runtime/mfixalloc.go /usr/local/go/src/runtime/mgc.go /usr/local/go/src/runtime/mgclimit.go /usr/local/go/src/runtime/mgcmark.go /usr/local/go/src/runtime/mgcpacer.go /usr/local/go/src/runtime/mgcscavenge.go /usr/local/go/src/runtime/mgcstack.go /usr/local/go/src/runtime/mgcsweep.go /usr/local/go/src/runtime/mgcwork.go /usr/local/go/src/runtime/mheap.go /usr/local/go/src/runtime/minmax.go /usr/local/go/src/runtime/mpagealloc.go /usr/local/go/src/runtime/mpagealloc_64bit.go /usr/local/go/src/runtime/mpagecache.go /usr/local/go/src/runtime/mpallocbits.go /usr/local/go/src/runtime/mprof.go /usr/local/go/src/runtime/mranges.go /usr/local/go/src/runtime/msan0.go /usr/local/go/src/runtime/msize.go /usr/local/go/src/runtime/mspanset.go /usr/local/go/src/runtime/mstats.go /usr/local/go/src/runtime/mwbbuf.go /usr/local/go/src/runtime/nbpipe_pipe.go /usr/local/go/src/runtime/netpoll.go /usr/local/go/src/runtime/netpoll_kqueue.go /usr/local/go/src/runtime/netpoll_kqueue_event.go /usr/local/go/src/runtime/nonwindows_stub.go /usr/local/go/src/runtime/note_other.go /usr/local/go/src/runtime/os_darwin.go /usr/local/go/src/runtime/os_darwin_arm64.go /usr/local/go/src/runtime/os_nonopenbsd.go /usr/local/go/src/runtime/os_unix.go /usr/local/go/src/runtime/os_unix_nonlinux.go /usr/local/go/src/runtime/panic.go /usr/local/go/src/runtime/pinner.go /usr/local/go/src/runtime/plugin.go /usr/local/go/src/runtime/preempt.go /usr/local/go/src/runtime/preempt_nonwindows.go /usr/local/go/src/runtime/print.go /usr/local/go/src/runtime/proc.go /usr/local/go/src/runtime/profbuf.go /usr/local/go/src/runtime/proflabel.go /usr/local/go/src/runtime/race0.go /usr/local/go/src/runtime/rand.go /usr/local/go/src/runtime/rdebug.go /usr/local/go/src/runtime/retry.go /usr/local/go/src/runtime/runtime.go /usr/local/go/src/runtime/runtime1.go /usr/local/go/src/runtime/runtime2.go /usr/local/go/src/runtime/runtime_boring.go /usr/local/go/src/runtime/rwmutex.go /usr/local/go/src/runtime/security_issetugid.go /usr/local/go/src/runtime/security_unix.go /usr/local/go/src/runtime/select.go /usr/local/go/src/runtime/sema.go /usr/local/go/src/runtime/set_vma_name_stub.go /usr/local/go/src/runtime/signal_arm64.go /usr/local/go/src/runtime/signal_darwin.go /usr/local/go/src/runtime/signal_darwin_arm64.go /usr/local/go/src/runtime/signal_unix.go /usr/local/go/src/runtime/sigqueue.go /usr/local/go/src/runtime/slice.go /usr/local/go/src/runtime/softfloat64.go /usr/local/go/src/runtime/stack.go /usr/local/go/src/runtime/stkframe.go /usr/local/go/src/runtime/string.go /usr/local/go/src/runtime/stubs.go /usr/local/go/src/runtime/stubs_arm64.go /usr/local/go/src/runtime/stubs_nonlinux.go /usr/local/go/src/runtime/stubs_nonwasm.go /usr/local/go/src/runtime/symtab.go /usr/local/go/src/runtime/symtabinl.go /usr/local/go/src/runtime/synctest.go /usr/local/go/src/runtime/sys_arm64.go /usr/local/go/src/runtime/sys_darwin.go /usr/local/go/src/runtime/sys_darwin_arm64.go /usr/local/go/src/runtime/sys_libc.go /usr/local/go/src/runtime/sys_nonppc64x.go /usr/local/go/src/runtime/tagptr.go /usr/local/go/src/runtime/tagptr_64bit.go /usr/local/go/src/runtime/test_stubs.go /usr/local/go/src/runtime/time.go /usr/local/go/src/runtime/time_nofake.go /usr/local/go/src/runtime/timestub.go /usr/local/go/src/runtime/tls_stub.go /usr/local/go/src/runtime/trace.go /usr/local/go/src/runtime/traceallocfree.go /usr/local/go/src/runtime/traceback.go /usr/local/go/src/runtime/tracebuf.go /usr/local/go/src/runtime/tracecpu.go /usr/local/go/src/runtime/traceevent.go /usr/local/go/src/runtime/tracemap.go /usr/local/go/src/runtime/traceregion.go /usr/local/go/src/runtime/traceruntime.go /usr/local/go/src/runtime/tracestack.go /usr/local/go/src/runtime/tracestatus.go /usr/local/go/src/runtime/tracestring.go /usr/local/go/src/runtime/tracetime.go /usr/local/go/src/runtime/tracetype.go /usr/local/go/src/runtime/type.go /usr/local/go/src/runtime/typekind.go /usr/local/go/src/runtime/unsafe.go /usr/local/go/src/runtime/utf8.go /usr/local/go/src/runtime/vdso_in_none.go /usr/local/go/src/runtime/vgetrandom_unsupported.go /usr/local/go/src/runtime/write_err.go: exit status 2

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

@mknyszek mknyszek

@JunyangShao JunyangShao

Labels
BugReport Issues describing a possible bug in the Go implementation. compiler/runtime Issues related to the Go compiler and/or runtime. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
Go Compiler / Runtime
Status: Todo
Milestone
Backlog
Development

No branches or pull requests
7 participants
@rhysh @mknyszek @prattmic @dr2chase @gopherbot @JunyangShao @gabyhelp