internal/trace: TestTraceStress failing on openbsd-386-72 builders

[timothy-king]

The openbsd-386-72 builders are consistently failing on https://build.golang.org/. There seems to be a theme of memory outs and time outs TestTraceStress. Here are a few samples:

Memory outs on internal/trace.TestTraceStress :
https://build.golang.org/log/b4d1346be8bd45d05571d33dea70ed26e46fe405
https://build.golang.org/log/f3aca232d11e5cedc57bb3e76f698d271c5d8d8d
https://build.golang.org/log/0de00ca53f8cd5b89dbfd1f8123c5718738cd7db

fatal error: runtime: out of memory
...
goroutine 112 gp=0x64c07328 m=nil [chan receive, 2 minutes]:
runtime.gopark(0x8280d08, 0x678831f4, 0xe, 0x7, 0x2)
	/tmp/workdir/go/src/runtime/proc.go:435 +0xfa fp=0x64c35e60 sp=0x64c35e4c pc=0x80b797a
runtime.chanrecv(0x678831c0, 0x64c35ed3, 0x1)
	/tmp/workdir/go/src/runtime/chan.go:639 +0x3bd fp=0x64c35e9c sp=0x64c35e60 pc=0x804db4d
runtime.chanrecv1(0x678831c0, 0x64c35ed3)
	/tmp/workdir/go/src/runtime/chan.go:489 +0x1c fp=0x64c35eb0 sp=0x64c35e9c pc=0x804d75c
testing.(*T).Run(0x66f0e128, {0x826b913, 0x7}, 0x684de550)
	/tmp/workdir/go/src/testing/testing.go:1831 +0x466 fp=0x64c35f34 sp=0x64c35eb0 pc=0x813f6b6
internal/trace_test.testTraceProg(0x66f0e128, {0x826c1c3, 0x9}, 0x8280ca4)
	/tmp/workdir/go/src/internal/trace/trace_test.go:651 +0x22b fp=0x64c35f70 sp=0x64c35f34 pc=0x82190ab
internal/trace_test.TestTraceStress(0x66f0e128)
	/tmp/workdir/go/src/internal/trace/trace_test.go:510 +0x37 fp=0x64c35f84 sp=0x64c35f70 pc=0x8218757
testing.tRunner(0x66f0e128, 0x8280b64)
	/tmp/workdir/go/src/testing/testing.go:1764 +0x113 fp=0x64c35fe4 sp=0x64c35f84 pc=0x813e773
testing.(*T).Run.gowrap1()
	/tmp/workdir/go/src/testing/testing.go:1823 +0x28 fp=0x64c35ff0 sp=0x64c35fe4 pc=0x813f7f8
runtime.goexit({})
	/tmp/workdir/go/src/runtime/asm_386.s:1393 +0x1 fp=0x64c35ff4 sp=0x64c35ff0 pc=0x80bcfe1
created by testing.(*T).Run in goroutine 1
	/tmp/workdir/go/src/testing/testing.go:1823 +0x447
FAIL	internal/trace	154.958s

Time out (?) on internal/trace.TestTraceStress :
https://build.golang.org/log/3e7cb75f09a4ec9d1d32e047b7b951e2e75d7e0b

FAIL: TestTraceStress (128.27s)
    --- FAIL: TestTraceStress/Default (128.27s)
        exec.go:213: test timed out while running command: /tmp/workdir/go/bin/go run testdata/testprog/stress.go
        trace_test.go:616: exit status 1
--- FAIL: TestTraceStressStartStop (9.68s)
    --- FAIL: TestTraceStressStartStop/Default (9.68s)
        exec.go:213: test timed out while running command: /tmp/workdir/go/bin/go run testdata/testprog/stress-start-stop.go
        trace_test.go:616: signal: killed
--- FAIL: TestTraceManyStartStop (0.38s)
    --- FAIL: TestTraceManyStartStop/Default (0.38s)
        exec.go:213: test timed out while running command: /tmp/workdir/go/bin/go run testdata/testprog/many-start-stop.go
        trace_test.go:614: stderr: SIGQUIT: quit
            PC=0x26428f5b m=1 sigcode=0
            
            goroutine 0 gp=0x56808368 m=1 mp=0x56842008 [idle]:
            runtime.usleep(0x14)
            	runtime/sys_openbsd2.go:140 +0x19 fp=0x45a5aa84 sp=0x45a5aa74 pc=0x809ff99
            runtime.sysmon()
            	runtime/proc.go:6075 +0xa6 fp=0x45a5aae0 sp=0x45a5aa84 pc=0x808e856
            runtime.mstart1()
            	runtime/proc.go:1845 +0x72 fp=0x45a5aaf0 sp=0x45a5aae0 pc=0x8085ba2
            runtime.mstart0()
            	runtime/proc.go:1802 +0x4b fp=0x45a5aafc sp=0x45a5aaf0 pc=0x8085b1b
            runtime.mstart()
            	runtime/asm_386.s:275 +0x5 fp=0x45a5ab00 sp=0x45a5aafc pc=0x80bdad5
            
            goroutine 1 gp=0x56808128 m=nil [semacquire]:
            runtime.gopark(0x8754c50, 0x8b76b20, 0x12, 0x5, 0x4)
            	runtime/proc.go:435 +0xfa fp=0x568cdae0 sp=0x568cdacc pc=0x80b94fa
            runtime.goparkunlock(...)
            	runtime/proc.go:441
            runtime.semacquire1(0x56a823e8, 0x0, 0x1, 0x0, 0x12)
            	runtime/sema.go:178 +0x27b fp=0x568cdb10 sp=0x568cdae0 pc=0x8095adb
            sync.runtime_Semacquire(0x56a823e8)
            	runtime/sema.go:71 +0x35 fp=0x568cdb28 sp=0x568cdb10 pc=0x80ba9d5
            sync.(*WaitGroup).Wait(0x56a823e0)
            	sync/waitgroup.go:118 +0x5f fp=0x568cdb44 sp=0x568cdb28 pc=0x80cc01f
            cmd/go/internal/work.(*Builder).Do(0x56874230, {0x880c2a0, 0x8b7c060}, 0x56af3c88)
            	cmd/go/internal/work/exec.go:231 +0x419 fp=0x568cdbdc sp=0x568cdb44 pc=0x85845c9
            cmd/go/internal/run.runRun({0x880c2a0, 0x8b7c060}, 0x8b66960, {0x5681c028, 0x1, 0x1})
            	cmd/go/internal/run/run.go:174 +0x7ff fp=0x568cdc90 sp=0x568cdbdc pc=0x85d531f
            main.invoke(0x8b66960, {0x5681c020, 0x2, 0x2})
            	cmd/go/main.go:339 +0x8b7 fp=0x568cde64 sp=0x568cdc90 pc=0x861f2d7
            main.main()
            	cmd/go/main.go:218 +0x1031 fp=0x568cdfac sp=0x568cde64 pc=0x861e371
            runtime.main()
            	runtime/proc.go:283 +0x288 fp=0x568cdff0 sp=0x568cdfac pc=0x8082a88
            runtime.goexit({})
            	runtime/asm_386.s:1393 +0x1 fp=0x568cdff4 sp=0x568cdff0 pc=0x80beec1
            
            goroutine 2 gp=0x56808488 m=nil [force gc (idle)]:
            runtime.gopark(0x8754c50, 0x8b6d9a8, 0x11, 0xa, 0x1)
            	runtime/proc.go:435 +0xfa fp=0x5683efdc sp=0x5683efc8 pc=0x80b94fa
            runtime.goparkunlock(...)
            	runtime/proc.go:441
            runtime.forcegchelper()
            	runtime/proc.go:348 +0xc7 fp=0x5683eff0 sp=0x5683efdc pc=0x8082de7
            runtime.goexit({})
            	runtime/asm_386.s:1393 +0x1 fp=0x5683eff4 sp=0x5683eff0 pc=0x80beec1
            created by runtime.init.6 in goroutine 1
            	runtime/proc.go:336 +0x1d
            
            goroutine 3 gp=0x568085a8 m=nil [runnable]:
            runtime.goschedIfBusy()
            	runtime/proc.go:387 +0x36 fp=0x5683f7cc sp=0x5683f7c0 pc=0x8082e96
            runtime.bgsweep(0x56824040)
            	runtime/mgcsweep.go:301 +0x141 fp=0x5683f7e8 sp=0x5683f7cc pc=0x806ef31
            runtime.gcenable.gowrap1()
            	runtime/mgc.go:203 +0x21 fp=0x5683f7f0 sp=0x5683f7e8 pc=0x8060951
            runtime.goexit({})
            	runtime/asm_386.s:1393 +0x1 fp=0x5683f7f4 sp=0x5683f7f0 pc=0x80beec1
            created by runtime.gcenable in goroutine 1
            	runtime/mgc.go:203 +0x71
            
            goroutine 4 gp=0x568086c8 m=nil [runnable]:
            runtime.gopark(0x8754c50, 0x8b6e940, 0x13, 0xe, 0x2)
            	runtime/proc.go:435 +0xfa fp=0x5683ff68 sp=0x5683ff54 pc=0x80b94fa
            runtime.goparkunlock(...)
            	runtime/proc.go:441
            runtime.(*scavengerState).sleep(0x8b6e940, 0x410388c800000000)
            	runtime/mgcscavenge.go:504 +0x149 fp=0x5683ffcc sp=0x5683ff68 pc=0x806c729
            runtime.bgscavenge(0x56824040)
            	runtime/mgcscavenge.go:662 +0xa0 fp=0x5683ffe8 sp=0x5683ffcc pc=0x806cbb0
            runtime.gcenable.gowrap2()
            	runtime/mgc.go:204 +0x21 fp=0x5683fff0 sp=0x5683ffe8 pc=0x8060911
            runtime.goexit({})
            	runtime/asm_386.s:1393 +0x1 fp=0x5683fff4 sp=0x5683fff0 pc=0x80beec1
            created by runtime.gcenable in goroutine 1
            	runtime/mgc.go:204 +0xb1
            
            goroutine 5 gp=0x56808c68 m=nil [finalizer wait]:
            runtime.gopark(0x8754b04, 0x8b7c130, 0x10, 0xa, 0x1)
            	runtime/proc.go:435 +0xfa fp=0x5683e798 sp=0x5683e784 pc=0x80b94fa
            runtime.runfinq()
            	runtime/mfinal.go:193 +0xf0 fp=0x5683e7f0 sp=0x5683e798 pc=0x805fab0
            runtime.goexit({})
            	runtime/asm_386.s:1393 +0x1 fp=0x5683e7f4 sp=0x5683e7f0 pc=0x80beec1
            created by runtime.createfing in goroutine 1
            	runtime/mfinal.go:163 +0x5a
            
            goroutine 6 gp=0x56808fc8 m=nil [runnable]:
            runtime.gopark(0x8754ae4, 0x56824274, 0xe, 0x7, 0x2)
            	runtime/proc.go:435 +0xfa fp=0x56840790 sp=0x5684077c pc=0x80b94fa
            runtime.chanrecv(0x56824240, 0x0, 0x1)
            	runtime/chan.go:639 +0x3bd fp=0x568407cc sp=0x56840790 pc=0x8050c0d
            runtime.chanrecv1(0x56824240, 0x0)
            	runtime/chan.go:489 +0x1c fp=0x568407e0 sp=0x568407cc pc=0x805081c
            runtime.unique_runtime_registerUniqueMapCleanup.func1(...)
            	runtime/mgc.go:1731
            runtime.unique_runtime_registerUniqueMapCleanup.gowrap1()
            	runtime/mgc.go:1734 +0x34 fp=0x568407f0 sp=0x568407e0 pc=0x80640e4
            runtime.goexit({})
            	runtime/asm_386.s:1393 +0x1 fp=0x568407f4 sp=0x568407f0 pc=0x80beec1
            created by unique.runtime_registerUniqueMapCleanup in goroutine 1
            	runtime/mgc.go:1729 +0x96
            
            goroutine 8 gp=0x56809208 m=nil [runnable]:
            syscall.syscall(0x80d9450, 0x3, 0x56d68000, 0x8000)
            	runtime/sys_openbsd3.go:28 +0x20 fp=0x568cb3bc sp=0x568cb3ac pc=0x80bc800
            syscall.read(0x3, {0x56d68000, 0x8000, 0x8000})
            	syscall/zsyscall_openbsd_386.go:1192 +0x49 fp=0x568cb3e4 sp=0x568cb3bc pc=0x80d7a59
            syscall.Read(...)
            	syscall/syscall_unix.go:183
            internal/poll.ignoringEINTRIO(...)
            	internal/poll/fd_unix.go:745
            internal/poll.(*FD).Read(0x56afdb80, {0x56d68000, 0x8000, 0x8000})
            	internal/poll/fd_unix.go:161 +0x229 fp=0x568cb42c sp=0x568cb3e4 pc=0x81344e9
            os.(*File).read(...)
            	os/file_posix.go:29
            os.(*File).Read(0x56afefc0, {0x56d68000, 0x8000, 0x8000})
            	os/file.go:124 +0x6a fp=0x568cb450 sp=0x568cb42c pc=0x813cf6a
            io.copyBuffer({0x3a095550, 0x56826a10}, {0x8808f40, 0x56afefc8}, {0x0, 0x0, 0x0})
            	io/io.go:429 +0x1e0 fp=0x568cb49c sp=0x568cb450 pc=0x812c090
            io.Copy(...)
            	io/io.go:388
            os.genericWriteTo(0x56afefc0, {0x3a095550, 0x56826a10})
            	os/file.go:275 +0x6f fp=0x568cb4d0 sp=0x568cb49c pc=0x813d80f
            os.(*File).WriteTo(0x56afefc0, {0x3a095550, 0x56826a10})
            	os/file.go:253 +0x61 fp=0x568cb4f0 sp=0x568cb4d0 pc=0x813d741
            io.copyBuffer({0x3a095550, 0x56826a10}, {0x8808ec0, 0x56afefc0}, {0x0, 0x0, 0x0})
            	io/io.go:411 +0x186 fp=0x568cb53c sp=0x568cb4f0 pc=0x812c036
            io.Copy(...)
            	io/io.go:388
            cmd/go/internal/cache.FileHash({0x56ae6a00, 0x20})
            	cmd/go/internal/cache/hash.go:165 +0x26a fp=0x568cb5d8 sp=0x568cb53c pc=0x8228afa
            cmd/go/internal/work.(*Builder).fileHash(0x56874230, {0x56ae6a00, 0x20})
            	cmd/go/internal/work/buildid.go:402 +0x37 fp=0x568cb62c sp=0x568cb5d8 pc=0x8580c17
            cmd/go/internal/work.(*Builder).buildActionID(0x56874230, 0x56af2248)
            	cmd/go/internal/work/exec.go:397 +0x207d fp=0x568cb830 sp=0x568cb62c pc=0x858749d
            cmd/go/internal/work.(*Builder).build(0x56874230, {0x880c2a0, 0x8b7c060}, 0x56af2248)
            	cmd/go/internal/work/exec.go:475 +0x2a2 fp=0x568cbe84 sp=0x568cb830 pc=0x8587d32
            cmd/go/internal/work.(*buildActor).Act(0x56ac1998, 0x56874230, {0x880c2a0, 0x8b7c060}, 0x56af2248)
            	cmd/go/internal/work/action.go:461 +0x33 fp=0x568cbea0 sp=0x568cbe84 pc=0x8577133
            cmd/go/internal/work.(*Builder).Do.func3({0x880c2a0, 0x8b7c060}, 0x56af2248)
            	cmd/go/internal/work/exec.go:153 +0x7fd fp=0x568cbf88 sp=0x568cbea0 pc=0x858510d
            cmd/go/internal/work.(*Builder).Do.func4()
            	cmd/go/internal/work/exec.go:222 +0xae fp=0x568cbff0 sp=0x568cbf88 pc=0x85847ae
            runtime.goexit({})
            	runtime/asm_386.s:1393 +0x1 fp=0x568cbff4 sp=0x568cbff0 pc=0x80beec1
            created by cmd/go/internal/work.(*Builder).Do in goroutine 1
            	cmd/go/internal/work/exec.go:208 +0x37a
            
            goroutine 13 gp=0x56ac77a8 m=nil [GC worker (idle)]:
            runtime.gopark(0x8754b10, 0x56a9fd10, 0x1a, 0xa, 0x0)
            	runtime/proc.go:435 +0xfa fp=0x56840f8c sp=0x56840f78 pc=0x80b94fa
            runtime.gcBgMarkWorker(0x56a15c80)
            	runtime/mgc.go:1362 +0xeb fp=0x56840fe8 sp=0x56840f8c pc=0x806327b
            runtime.gcBgMarkStartWorkers.gowrap1()
            	runtime/mgc.go:1278 +0x21 fp=0x56840ff0 sp=0x56840fe8 pc=0x8063171
            runtime.goexit({})
            	runtime/asm_386.s:1393 +0x1 fp=0x56840ff4 sp=0x56840ff0 pc=0x80beec1
            created by runtime.gcBgMarkStartWorkers in goroutine 8
            	runtime/mgc.go:1278 +0x114
            
            eax    0x4
            ebx    0x463c12b8
            ecx    0x0
            edx    0x0
            edi    0x98
            esi    0x43de7904
            ebp    0x45a5a9f0
            esp    0x45a5a9dc
            eip    0x26428f5b
            eflags 0x247
            cs     0x2b
            fs     0x5b
            gs     0x63
        trace_test.go:616: exit status 2

CC @mknyszek, @prattmic, @golang/runtime, and @golang/openbsd for visibility

[gabyhelp]

Related Issues and Documentation

• x/review/git-codereview: frequent timeouts on openbsd-386 builder since 2021-10-19 #49529 (closed)
• runtime/trace: running out of memory on Plan 9 builders #24013 (closed)
• runtime: SIGBUS during TestTraceStress on freebsd-386-gce101 #10212 (closed)
• runtime/trace: TestTraceStress and TestTraceStressStartStop running out of memory on plan9 and windows #21873 (closed)
• os/exec: test timeouts on openbsd #19547 (closed)
• os: (*Process).Wait sometimes hangs on netbsd #50138 (closed)
• runtime: fatal error: unexpected signal during runtime execution inside gcmarkwb_m #10664 (closed)
• build: test timeouts / flakes (TestCgoPprofPIE, TestCgoExternalThreadSIGPROF) #18038 (closed)
• cmd/fix: timeout in TestRewrite on netbsd builders #50581
• runtime: timeouts in TestChan on netbsd-arm64-bsiegert and openbsd-arm64-jsing #52703 (closed)

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

[timothy-king]

@dmitshur Are the openbsd 386 builders perhaps too constrained for this 'stress test'? If so, disabling on this OS+ARCH seems like a reasonable choice.

[timothy-king]

@dmitshur pointed out this is a continuation of #64322. This seems to be happening fairly consistently at the moment.

[dmitshur]

It is possible the builder resource limits are not sufficient for the increased demands. Increasing memory (if it's viable, given it's 32-bit) might help, but that kind of builder maintenance work is not a good fit for the legacy variant of this builder. Instead, it'd be preferrable to make progress on adding a LUCI version of this builder (#61122), or a newer OS version thereof (#63568).

If progress on the above needs some time, I think it's reasonable for port maintainers (CC @golang/openbsd) to add a test skip, so at least the builder can produce more signal in other areas.