runtime: allocated pages below zero on openbsd/riscv64 #63385

4a6f656c · 2023-10-05T04:29:42Z

#!watchflakes
post <- log ~ `fatal error: allocated pages below zero` && goos == "openbsd" && goarch == "riscv64"

The openbsd/riscv64 port is regularly failing with errors like:

runtime: inUse=0 npages=4
fatal error: allocated pages below zero?

https://build.golang.org/log/bb95405e34149982611770caf632d58e9bc50ff4
https://build.golang.org/log/e5fb11bcae4d4dab31c13f7e271852e39ae5a6df

This seems particularly reproducible (although still intermittent) via the TestArenaCollision test:

$ ../bin/go tool dist test -run runtime:cpu124                                          
                                                                                                                  
##### Test execution environment.                                                                                 
# GOARCH: riscv64                                                                                                 
# CPU:                                                                                                            
# GOOS: openbsd                                                                                                   
# OS Version: OpenBSD 7.4 OpenBSD 7.4 (GENERIC.MP) #423: Tue Oct  3 07:33:24 MDT 2023     deraadt@riscv64.openbsd.org:/usr/src/sys/arch/riscv64/compile/GENERIC.MP  riscv64
                                                                                                                  
##### GOMAXPROCS=2 runtime -cpu=1,2,4 -quick                                                                      
--- FAIL: TestArenaCollision (0.26s)                                                                              
    malloc_test.go:284: === RUN   TestArenaCollision                                                              
            malloc_test.go:301: reserved [0x60000000, 0x64000000)                                                 
            malloc_test.go:301: reserved [0x54000000, 0x58000000)                                                 
            malloc_test.go:301: reserved [0xa0000000, 0xa4000000)
            malloc_test.go:301: reserved [0x70000000, 0x74000000)                                                 
            malloc_test.go:301: reserved [0xc8000000, 0xcc000000)                                                 
        runtime: inUse=0 npages=1                                                                                 
        fatal error: allocated pages below zero?

inUse always appears to be zero, while npages is some small positive value.

It would seem that this is specific to openbsd/riscv64 and possibly even a kernel/mmap related problem.

/cc @mknyszek any pointers in tracking this down would be greatly appreciated.

The text was updated successfully, but these errors were encountered:

mknyszek · 2023-10-05T05:14:44Z

Hm, unfortunately this doesn't seem like it would be a kernel/mmap problem. This is a check that's failing when one or more pages are freed back to the page heap. What's happening is that some of the bookkeeping maintained per 4 MiB aligned address range indicates that the region is totally free, so it doesn't make sense to try and free memory back to it. I think it implies some kind of corruption of the data structure, or a data race. It could also mean that when the check isn't firing, some pages are getting allocated twice (which could lead to other memory corruption symptoms).

It may just be reproducing in TestArenaCollision because it allocates a whole bunch of memory and likely triggers a GC (causing other memory to be freed, since all the memory it allocates stays live indefinitely).

If this is straightforward to reproduce, my first thought would be to pepper debuglog calls around the various allocs and frees to the page heap and make sure nothing is being allocated (and thus later possibly freed) twice.

If you haven't used debuglog before, it's a very handy low-overhead tool for identifying what actually happened in the runtime. Because it's low overhead, it maintains a low chance of perturbing bugs involving race conditions and tends to reproduce real thread orderings. You can enable it by passing -tags debuglog to go test or go build. You use it in the runtime by calling dlog().s("string example").u64(5).end() from almost anywhere in the runtime. It'll print the log when the program crashes. (If it's not doing so, find some reasonable place to call printDebugLog.) The only place you might run into trouble is trying to call it from signal handlers. It's safe, but you may run out of nosplit stack space. Don't forget to call .end()!

gopherbot · 2023-10-05T17:00:27Z

Found new dashboard test flakes for:

#!watchflakes
post <- log ~ `fatal error: allocated pages below zero` && goos == "openbsd" && goarch == "riscv64"

2023-09-28 17:55 openbsd-riscv64-jsing sys@2964e1e4 go@3a69dcdc go/types [build] (log)

runtime: inUse=0 npages=3
fatal error: allocated pages below zero?

runtime stack:
runtime.throw({0x91b6fa?, 0x0?})
	runtime/panic.go:1018 +0x44 fp=0x123f5f310 sp=0x123f5f2e8 pc=0x53b6c
runtime.(*scavChunkData).free(0x0?, 0x3, 0x45350?)
	runtime/mgcscavenge.go:1341 +0xd8 fp=0x123f5f330 sp=0x123f5f310 pc=0x3daf0
runtime.(*scavengeIndex).free(0x10a8cc0, 0x146, 0xc7, 0x3)
	runtime/mgcscavenge.go:1154 +0xa4 fp=0x123f5f368 sp=0x123f5f330 pc=0x3d71c
...
runtime.gcMarkTermination()
	runtime/mgc.go:1101 +0x510 fp=0x50041ef8 sp=0x50041d18 pc=0x33050
runtime.gcMarkDone()
	runtime/mgc.go:941 +0x25c fp=0x50041f48 sp=0x50041ef8 pc=0x32a0c
runtime.gcBgMarkWorker()
	runtime/mgc.go:1445 +0x374 fp=0x50041fd8 sp=0x50041f48 pc=0x33d84
runtime.goexit({})
	runtime/asm_riscv64.s:521 +0x4 fp=0x50041fd8 sp=0x50041fd8 pc=0x89ea4
created by runtime.gcBgMarkStartWorkers in goroutine 1
	runtime/mgc.go:1237 +0x2c

2023-09-28 17:55 openbsd-riscv64-jsing sys@2964e1e4 go@68a12a80 runtime [build] (log)

runtime: inUse=0 npages=4
fatal error: allocated pages below zero?

runtime stack:
runtime.throw({0x9169de?, 0x440009c0?})
	/home/joel/src/go-openbsd-riscv64-bootstrap/src/runtime/panic.go:837 +0x44 fp=0xb64d82f8 sp=0xb64d82d0 pc=0x5318c
runtime.(*scavChunkData).free(0x74838?, 0x4, 0xb64d8360?)
	/home/joel/src/go-openbsd-riscv64-bootstrap/src/runtime/mgcscavenge.go:1381 +0xd8 fp=0xb64d8318 sp=0xb64d82f8 pc=0x3d288
runtime.(*scavengeIndex).free(...)
	/home/joel/src/go-openbsd-riscv64-bootstrap/src/runtime/mgcscavenge.go:1159
...
	/home/joel/src/go-openbsd-riscv64-bootstrap/src/runtime/proc.go:3812 +0x68 fp=0xb64d86d0 sp=0xb64d8698 pc=0x5dca0
runtime.newstack()
	/home/joel/src/go-openbsd-riscv64-bootstrap/src/runtime/stack.go:1071 +0x2b0 fp=0xb64d88b8 sp=0xb64d86d0 pc=0x6e968
runtime.morestack()
	/home/joel/src/go-openbsd-riscv64-bootstrap/src/runtime/asm_riscv64.s:204 +0x58 fp=0xb64d88c0 sp=0xb64d88b8 pc=0x87698

goroutine 175 [running]:
	goroutine running on other thread; stack unavailable
created by runtime.gcBgMarkStartWorkers in goroutine 1
	/home/joel/src/go-openbsd-riscv64-bootstrap/src/runtime/mgc.go:1237 +0x2c

2023-10-04 10:08 openbsd-riscv64-jsing go@0074125c encoding/gob.TestLargeSlice (log)

runtime: inUse=0 npages=1
fatal error: allocated pages below zero?

runtime stack:
runtime.throw({0x1c2d9c?, 0x64821cfb?})
	/home/gopher/build/go/src/runtime/panic.go:1018 +0x44 fp=0x4cbaaad8 sp=0x4cbaaab0 pc=0x46ddc
runtime.(*scavChunkData).free(0x320048?, 0x1, 0x5eca0?)
	/home/gopher/build/go/src/runtime/mgcscavenge.go:1341 +0xd8 fp=0x4cbaaaf8 sp=0x4cbaaad8 pc=0x34218
runtime.(*scavengeIndex).free(0x346760, 0x1df, 0x87, 0x1)
	/home/gopher/build/go/src/runtime/mgcscavenge.go:1154 +0xa4 fp=0x4cbaab30 sp=0x4cbaaaf8 pc=0x33e44
...
	/home/gopher/build/go/src/encoding/gob/decode.go:1234 +0xfc fp=0xd3a1ddf8 sp=0xd3a1dd20 pc=0x130d6c
encoding/gob.(*Decoder).DecodeValue(0x70074000, {0x17d480?, 0x70119800?, 0x70114a00?})
	/home/gopher/build/go/src/encoding/gob/decoder.go:229 +0x1a0 fp=0xd3a1de70 sp=0xd3a1ddf8 pc=0x131d70
encoding/gob.(*Decoder).Decode(0x70074000, {0x17d480?, 0x70119800?})
	/home/gopher/build/go/src/encoding/gob/decoder.go:204 +0x144 fp=0xd3a1dec0 sp=0xd3a1de70 pc=0x131b94
encoding/gob.testEncodeDecode(0x7022d6c0, {0x17d480, 0x701197e8}, {0x17d480, 0x70119800})
	/home/gopher/build/go/src/encoding/gob/codec_test.go:1559 +0x288 fp=0xd3a1df30 sp=0xd3a1dec0 pc=0x14a358
encoding/gob.TestLargeSlice.func1(0x0?)
	/home/gopher/build/go/src/encoding/gob/codec_test.go:1579 +0xcc fp=0xd3a1df78 sp=0xd3a1df30 pc=0x1604bc
testing.tRunner(0x7022d6c0, 0x1cd0f8)

2023-10-04 15:11 openbsd-riscv64-jsing go@a9036396 runtime.TestFakeTime (log)

--- FAIL: TestFakeTime (16.20s)
    crash_test.go:152: running /home/gopher/build/go/bin/go build -o /home/gopher/build/tmp/go-build1023398732/testfaketime_-tags=faketime.exe -tags=faketime
    time_test.go:31: building testfaketime [-tags=faketime]: exit status 1
        # runtime
        runtime: inUse=0 npages=5
        fatal error: allocated pages below zero?

        runtime stack:
        runtime.throw({0x91b6fa?, 0x74df4?})
        	runtime/panic.go:1018 +0x44 fp=0x649e2470 sp=0x649e2448 pc=0x53b6c
...
        	runtime/mgc.go:203 +0x2c fp=0xe40417d8 sp=0xe40417c8 pc=0x319f4
        runtime.goexit({})
        	runtime/asm_riscv64.s:521 +0x4 fp=0xe40417d8 sp=0xe40417d8 pc=0x89ea4
        created by runtime.gcenable in goroutine 1
        	runtime/mgc.go:203 +0x70

        goroutine 16 [running]:
        	goroutine running on other thread; stack unavailable
        created by runtime.gcBgMarkStartWorkers in goroutine 1
        	runtime/mgc.go:1237 +0x2c

2023-10-04 16:05 openbsd-riscv64-jsing go@0c64ebce cmd/link.TestMachOBuildVersion (log)

--- FAIL: TestMachOBuildVersion (15.45s)
    link_test.go:377: [/home/gopher/build/go/bin/go build -ldflags=-linkmode=internal -o /home/gopher/build/tmp/TestMachOBuildVersion1940749510/001/main /home/gopher/build/tmp/TestMachOBuildVersion1940749510/001/main.go]: exit status 1:
        # runtime
        runtime: inUse=0 npages=4
        fatal error: allocated pages below zero?

        runtime stack:
        runtime.throw({0x91b6fa?, 0x106bba0?})
        	runtime/panic.go:1018 +0x44 fp=0x36af2bf0a8 sp=0x36af2bf080 pc=0x53b6c
        runtime.(*scavChunkData).free(0x750c0?, 0x4, 0xaf2bf110?)
...
        runtime.gcMarkTermination()
        	runtime/mgc.go:1101 +0x510 fp=0x6003c6f8 sp=0x6003c518 pc=0x33050
        runtime.gcMarkDone()
        	runtime/mgc.go:941 +0x25c fp=0x6003c748 sp=0x6003c6f8 pc=0x32a0c
        runtime.gcBgMarkWorker()
        	runtime/mgc.go:1445 +0x374 fp=0x6003c7d8 sp=0x6003c748 pc=0x33d84
        runtime.goexit({})
        	runtime/asm_riscv64.s:521 +0x4 fp=0x6003c7d8 sp=0x6003c7d8 pc=0x89ea4
        created by runtime.gcBgMarkStartWorkers in goroutine 1
        	runtime/mgc.go:1237 +0x2c

2023-10-04 16:50 openbsd-riscv64-jsing go@3a69dcdc cmd/go.TestGoListExport (log)

vcs-test.golang.org rerouted to http://127.0.0.1:19379
https://vcs-test.golang.org rerouted to https://127.0.0.1:36129
go test proxy running at GOPROXY=http://127.0.0.1:24112/mod
--- FAIL: TestGoListExport (17.46s)
    go_test.go:1227: running testgo [list -f {{.Export}} strings]
    go_test.go:1231: running testgo [list -export -f {{.Export}} strings]
    go_test.go:1231: standard error:
    go_test.go:1231: # runtime
        runtime: inUse=0 npages=4
        fatal error: allocated pages below zero?
...
        traceback: unexpected SPWRITE function runtime.morestack
        runtime.morestack()
        	runtime/asm_riscv64.s:204 +0x58 fp=0x6a921c60 sp=0x6a921c58 pc=0x87d30

        goroutine 179 [running]:
        	goroutine running on other thread; stack unavailable
        created by runtime.gcBgMarkStartWorkers in goroutine 1
        	runtime/mgc.go:1237 +0x2c

    go_test.go:1231: go [list -export -f {{.Export}} strings] failed unexpectedly in /home/gopher/build/go/src/cmd/go: exit status 1

2023-10-04 22:08 openbsd-riscv64-jsing net@5d5a036a go@bc150700 runtime [build] (log)

runtime: inUse=0 npages=5
fatal error: allocated pages below zero?

runtime stack:
runtime.throw({0x72caf7?, 0x6a14c?})
	../../go/src/runtime/panic.go:837 +0x44 fp=0x11c941ad0 sp=0x11c941aa8 pc=0x4a744
runtime.(*scavChunkData).free(0x0?, 0x5, 0x4f1ec?)
	../../go/src/runtime/mgcscavenge.go:1381 +0xd8 fp=0x11c941af0 sp=0x11c941ad0 pc=0x376d0
runtime.(*scavengeIndex).free(0xd46ca0, 0x1c2, 0x8, 0x5)
	../../go/src/runtime/mgcscavenge.go:1159 +0xa4 fp=0x11c941b28 sp=0x11c941af0 pc=0x371fc
...
runtime.sweepone()
	../../go/src/runtime/mgcsweep.go:393 +0x140 fp=0x70045780 sp=0x70045728 pc=0x38590
runtime.bgsweep(0x0?)
	../../go/src/runtime/mgcsweep.go:301 +0x14c fp=0x700457c8 sp=0x70045780 pc=0x382ec
runtime.gcenable.func1()
	../../go/src/runtime/mgc.go:203 +0x2c fp=0x700457d8 sp=0x700457c8 pc=0x2c7dc
runtime.goexit()
	../../go/src/runtime/asm_riscv64.s:521 +0x4 fp=0x700457d8 sp=0x700457d8 pc=0x7e434
created by runtime.gcenable in goroutine 1
	../../go/src/runtime/mgc.go:203 +0x70

runtime: allocated pages below zero on openbsd/riscv64 #63385

runtime: allocated pages below zero on openbsd/riscv64 #63385

Comments

4a6f656c commented Oct 5, 2023 • edited by cherrymui

mknyszek commented Oct 5, 2023 • edited

gopherbot commented Oct 5, 2023

gopherbot commented Oct 5, 2023

gopherbot commented Oct 6, 2023

gopherbot commented Oct 7, 2023

gopherbot commented Oct 7, 2023

gopherbot commented Oct 7, 2023

gopherbot commented Oct 7, 2023

gopherbot commented Oct 7, 2023

gopherbot commented Oct 7, 2023

gopherbot commented Oct 7, 2023

gopherbot commented Oct 7, 2023

gopherbot commented Oct 9, 2023

gopherbot commented Oct 9, 2023

gopherbot commented Oct 10, 2023

gopherbot commented Oct 10, 2023

gopherbot commented Oct 10, 2023

gopherbot commented Oct 10, 2023

gopherbot commented Oct 10, 2023

gopherbot commented Oct 25, 2023

gopherbot commented Oct 25, 2023

gopherbot commented Oct 25, 2023

gopherbot commented Oct 25, 2023

gopherbot commented Oct 26, 2023

gopherbot commented Oct 26, 2023

gopherbot commented Oct 26, 2023

gopherbot commented Oct 26, 2023

gopherbot commented Nov 29, 2023

gopherbot commented Nov 29, 2023

gopherbot commented Nov 29, 2023

gopherbot commented Nov 30, 2023

gopherbot commented Nov 30, 2023

gopherbot commented Nov 30, 2023

gopherbot commented Nov 30, 2023

gopherbot commented Dec 1, 2023

gopherbot commented Dec 1, 2023

gopherbot commented Dec 1, 2023

gopherbot commented Dec 1, 2023

gopherbot commented Dec 1, 2023

gopherbot commented Dec 1, 2023

gopherbot commented Dec 2, 2023

gopherbot commented Dec 2, 2023

gopherbot commented Dec 2, 2023

gopherbot commented Dec 2, 2023

gopherbot commented Dec 2, 2023

gopherbot commented Dec 3, 2023

gopherbot commented Dec 3, 2023

gopherbot commented Dec 5, 2023

gopherbot commented Dec 8, 2023

gopherbot commented Dec 9, 2023

gopherbot commented Dec 9, 2023

gopherbot commented Dec 9, 2023

gopherbot commented Dec 9, 2023

gopherbot commented Dec 9, 2023

gopherbot commented Dec 10, 2023

gopherbot commented Dec 10, 2023

gopherbot commented Dec 11, 2023

4a6f656c commented Oct 5, 2023 •

edited by cherrymui

mknyszek commented Oct 5, 2023 •

edited