runtime/trace: OOM in TestTraceStressStartStop on openbsd/386

[bcmills]

#!watchflakes
post <- goos == "openbsd" && log ~ `fatal error: runtime: out of memory` && log ~ `^runtime/trace_test.TestTraceStressStartStop`

Example: https://build.golang.org/log/0be8c98902db83cc7880a398efe8f7d6c9225606
(from #53576)

(attn @mknyszek; CC @golang/openbsd)

[mknyszek]

I'm a bit baffled as to why this is happening now. That test only ever runs the old execution tracer. Coincidentally, I recently landed a CL that switches to the new tracer, so this test should be skipped now. (There's an equivalent test in internal/trace/v2, but it's already been running on the builders and hasn't had an OOM issue on OpenBSD yet.)

[mknyszek]

Note: a bunch of these failures also showed up at #53576.

[bcmills]

Maybe some other test is running in parallel, or expanding the runtime's memory footprint in a way that leaks some additional pages?

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- goos == "openbsd" && log ~ `fatal error: runtime: out of memory` && log ~ `^runtime/trace_test.TestTraceStressStartStop`

2023-11-16 19:26 openbsd-386-72 go@d573a8a8 runtime/trace.TestTraceCPUProfile (log)

fatal error: runtime: out of memory

runtime stack:
runtime.throw({0x81ffb4e, 0x16})
	/tmp/workdir/go/src/runtime/panic.go:1023 +0x4d fp=0x12e44704 sp=0x12e446f0 pc=0x8082ddd
runtime.sysMapOS(0xad000000, 0x800000)
	/tmp/workdir/go/src/runtime/mem_bsd.go:81 +0x142 fp=0x12e44730 sp=0x12e44704 pc=0x805ef32
runtime.sysMap(0xad000000, 0x800000, 0x834b118)
	/tmp/workdir/go/src/runtime/mem.go:155 +0x3f fp=0x12e44740 sp=0x12e44730 pc=0x805ed0f
runtime.(*mheap).grow(0x833dde0, 0x375)
...
	/tmp/workdir/go/src/internal/trace/parser.go:269 +0x152b fp=0x6dcd8ba0 sp=0x6dcd8a6c pc=0x816775b
internal/trace.parse({0x8239b70, 0x6dde00f0}, {0x0, 0x0})
	/tmp/workdir/go/src/internal/trace/parser.go:104 +0x27 fp=0x6dcd8bec sp=0x6dcd8ba0 pc=0x8165f87
internal/trace.Parse({0x8239b70, 0x6dde00f0}, {0x0, 0x0})
	/tmp/workdir/go/src/internal/trace/parser.go:91 +0x37 fp=0x6dcd8c1c sp=0x6dcd8bec pc=0x8165e67
runtime/trace_test.parseTrace(0x6dca8300, {0x8239b70, 0x6dde00f0})
	/tmp/workdir/go/src/runtime/trace/trace_test.go:154 +0x47 fp=0x6dcd8d54 sp=0x6dcd8c1c pc=0x81b11c7
runtime/trace_test.TestTraceCPUProfile(0x6dca8300)
	/tmp/workdir/go/src/runtime/trace/trace_test.go:699 +0x461 fp=0x6dcd8f98 sp=0x6dcd8d54 pc=0x81b4361
testing.tRunner(0x6dca8300, 0x820a06c)

2023-11-20 15:56 openbsd-386-72 go@1d187fd0 runtime/trace (log)

fatal error: runtime: out of memory

runtime stack:
runtime.throw({0x8201b63, 0x16})
	/tmp/workdir/go/src/runtime/panic.go:1023 +0x4d fp=0x21321c84 sp=0x21321c70 pc=0x8082dfd
runtime.sysMapOS(0xae400000, 0x800000)
	/tmp/workdir/go/src/runtime/mem_bsd.go:81 +0x142 fp=0x21321cb0 sp=0x21321c84 pc=0x805ef12
runtime.sysMap(0xae400000, 0x800000, 0x834f118)
	/tmp/workdir/go/src/runtime/mem.go:155 +0x3f fp=0x21321cc0 sp=0x21321cb0 pc=0x805ecef
runtime.(*mheap).grow(0x8341de0, 0x375)
...
runtime.gopark(0x0, 0x0, 0xa, 0x10, 0x1)
	/tmp/workdir/go/src/runtime/proc.go:402 +0xfa fp=0x6f4c2fd4 sp=0x6f4c2fc0 pc=0x8085dba
runtime.block()
	/tmp/workdir/go/src/runtime/select.go:103 +0x32 fp=0x6f4c2fe8 sp=0x6f4c2fd4 pc=0x80968b2
runtime/trace_test.TestTraceStressStartStop.func1.10()
	/tmp/workdir/go/src/runtime/trace/trace_test.go:496 +0x23 fp=0x6f4c2ff0 sp=0x6f4c2fe8 pc=0x81b6b73
runtime.goexit({})
	/tmp/workdir/go/src/runtime/asm_386.s:1363 +0x1 fp=0x6f4c2ff4 sp=0x6f4c2ff0 pc=0x80b77b1
created by runtime/trace_test.TestTraceStressStartStop.func1 in goroutine 35
	/tmp/workdir/go/src/runtime/trace/trace_test.go:494 +0x6c8

2023-11-21 16:29 openbsd-386-72 go@78d037b0 runtime/trace (log)

fatal error: runtime: out of memory

runtime stack:
runtime.throw({0x8201b63, 0x16})
	/tmp/workdir/go/src/runtime/panic.go:1023 +0x4d fp=0x3dd75914 sp=0x3dd75900 pc=0x8082dfd
runtime.sysMapOS(0x9f800000, 0x400000)
	/tmp/workdir/go/src/runtime/mem_bsd.go:81 +0x142 fp=0x3dd75940 sp=0x3dd75914 pc=0x805ef12
runtime.sysMap(0x9f800000, 0x400000, 0x834f118)
	/tmp/workdir/go/src/runtime/mem.go:155 +0x3f fp=0x3dd75950 sp=0x3dd75940 pc=0x805ecef
runtime.(*mheap).grow(0x8341de0, 0x1)
...

goroutine 116 gp=0x60982488 m=nil [GC worker (idle)]:
runtime.gopark(0x820c1dc, 0x6098e060, 0x1a, 0x14, 0x0)
	/tmp/workdir/go/src/runtime/proc.go:402 +0xfa fp=0x60a03794 sp=0x60a03780 pc=0x8085dba
runtime.gcBgMarkWorker()
	/tmp/workdir/go/src/runtime/mgc.go:1310 +0xe5 fp=0x60a037f0 sp=0x60a03794 pc=0x8064575
runtime.goexit({})
	/tmp/workdir/go/src/runtime/asm_386.s:1363 +0x1 fp=0x60a037f4 sp=0x60a037f0 pc=0x80b77b1
created by runtime.gcBgMarkStartWorkers in goroutine 35
	/tmp/workdir/go/src/runtime/mgc.go:1234 +0x1f

2023-11-21 17:59 openbsd-386-72 go@070139a1 runtime/trace (log)

fatal error: runtime: out of memory

runtime stack:
runtime.throw({0x8201b6f, 0x16})
	/tmp/workdir/go/src/runtime/panic.go:1023 +0x4d fp=0x212e0044 sp=0x212e0030 pc=0x8082dfd
runtime.sysMapOS(0x82c00000, 0x400000)
	/tmp/workdir/go/src/runtime/mem_bsd.go:81 +0x142 fp=0x212e0070 sp=0x212e0044 pc=0x805ef12
runtime.sysMap(0x82c00000, 0x400000, 0x834f138)
	/tmp/workdir/go/src/runtime/mem.go:155 +0x3f fp=0x212e0080 sp=0x212e0070 pc=0x805ecef
runtime.(*mheap).grow(0x8341e00, 0x12)
...
runtime.gopark(0x0, 0x0, 0xa, 0x10, 0x1)
	/tmp/workdir/go/src/runtime/proc.go:402 +0xfa fp=0x4fd067d4 sp=0x4fd067c0 pc=0x8085dba
runtime.block()
	/tmp/workdir/go/src/runtime/select.go:103 +0x32 fp=0x4fd067e8 sp=0x4fd067d4 pc=0x80968b2
runtime/trace_test.TestTraceStressStartStop.func1.10()
	/tmp/workdir/go/src/runtime/trace/trace_test.go:496 +0x23 fp=0x4fd067f0 sp=0x4fd067e8 pc=0x81b6b73
runtime.goexit({})
	/tmp/workdir/go/src/runtime/asm_386.s:1363 +0x1 fp=0x4fd067f4 sp=0x4fd067f0 pc=0x80b77b1
created by runtime/trace_test.TestTraceStressStartStop.func1 in goroutine 35
	/tmp/workdir/go/src/runtime/trace/trace_test.go:494 +0x6c8

2023-11-21 20:34 openbsd-386-72 go@00715d08 runtime/trace (log)

fatal error: runtime: out of memory

runtime stack:
runtime.throw({0x8201b6f, 0x16})
	/tmp/workdir/go/src/runtime/panic.go:1023 +0x4d fp=0x46bb8494 sp=0x46bb8480 pc=0x8082dfd
runtime.sysMapOS(0xa9c00000, 0x1000000)
	/tmp/workdir/go/src/runtime/mem_bsd.go:81 +0x142 fp=0x46bb84c0 sp=0x46bb8494 pc=0x805ef12
runtime.sysMap(0xa9c00000, 0x1000000, 0x834f138)
	/tmp/workdir/go/src/runtime/mem.go:155 +0x3f fp=0x46bb84d0 sp=0x46bb84c0 pc=0x805ecef
runtime.(*mheap).grow(0x8341e00, 0x6c4)
...

goroutine 87 gp=0x6a9027e8 m=nil [GC worker (idle)]:
runtime.gopark(0x820c1e8, 0x6a92a078, 0x1a, 0x14, 0x0)
	/tmp/workdir/go/src/runtime/proc.go:402 +0xfa fp=0x6a8c0794 sp=0x6a8c0780 pc=0x8085dba
runtime.gcBgMarkWorker()
	/tmp/workdir/go/src/runtime/mgc.go:1310 +0xe5 fp=0x6a8c07f0 sp=0x6a8c0794 pc=0x8064575
runtime.goexit({})
	/tmp/workdir/go/src/runtime/asm_386.s:1363 +0x1 fp=0x6a8c07f4 sp=0x6a8c07f0 pc=0x80b77b1
created by runtime.gcBgMarkStartWorkers in goroutine 35
	/tmp/workdir/go/src/runtime/mgc.go:1234 +0x1f

2023-11-21 21:27 openbsd-386-72 go@351d8520 runtime/trace (log)

fatal error: runtime: out of memory

runtime stack:
runtime.throw({0x8202d22, 0x16})
	/tmp/workdir/go/src/runtime/panic.go:1023 +0x4d fp=0x27d50c24 sp=0x27d50c10 pc=0x808372d
runtime.sysMapOS(0xa0400000, 0x400000)
	/tmp/workdir/go/src/runtime/mem_bsd.go:81 +0x142 fp=0x27d50c50 sp=0x27d50c24 pc=0x805f032
runtime.sysMap(0xa0400000, 0x400000, 0x8350218)
	/tmp/workdir/go/src/runtime/mem.go:155 +0x3f fp=0x27d50c60 sp=0x27d50c50 pc=0x805ee0f
runtime.(*mheap).grow(0x8342ee0, 0x1)
...

goroutine 131 gp=0x61500368 m=nil [GC worker (idle)]:
runtime.gopark(0x820d3b4, 0x61510018, 0x1a, 0x14, 0x0)
	/tmp/workdir/go/src/runtime/proc.go:402 +0xfa fp=0x61482f94 sp=0x61482f80 pc=0x80866ea
runtime.gcBgMarkWorker()
	/tmp/workdir/go/src/runtime/mgc.go:1310 +0xe5 fp=0x61482ff0 sp=0x61482f94 pc=0x8064695
runtime.goexit({})
	/tmp/workdir/go/src/runtime/asm_386.s:1363 +0x1 fp=0x61482ff4 sp=0x61482ff0 pc=0x80b8121
created by runtime.gcBgMarkStartWorkers in goroutine 35
	/tmp/workdir/go/src/runtime/mgc.go:1234 +0x1f

2023-11-21 21:27 openbsd-386-72 go@48a6362d runtime/trace (log)

fatal error: runtime: out of memory

runtime stack:
runtime.throw({0x8202d22, 0x16})
	/tmp/workdir/go/src/runtime/panic.go:1023 +0x4d fp=0x217318c4 sp=0x217318b0 pc=0x808372d
runtime.sysMapOS(0xa3800000, 0x400000)
	/tmp/workdir/go/src/runtime/mem_bsd.go:81 +0x142 fp=0x217318f0 sp=0x217318c4 pc=0x805f032
runtime.sysMap(0xa3800000, 0x400000, 0x8350218)
	/tmp/workdir/go/src/runtime/mem.go:155 +0x3f fp=0x21731900 sp=0x217318f0 pc=0x805ee0f
runtime.(*mheap).grow(0x8342ee0, 0x1)
...
runtime.gopark(0x0, 0x0, 0xa, 0x10, 0x1)
	/tmp/workdir/go/src/runtime/proc.go:402 +0xfa fp=0x649037d4 sp=0x649037c0 pc=0x80866ea
runtime.block()
	/tmp/workdir/go/src/runtime/select.go:103 +0x32 fp=0x649037e8 sp=0x649037d4 pc=0x8097232
runtime/trace_test.TestTraceStressStartStop.func1.10()
	/tmp/workdir/go/src/runtime/trace/trace_test.go:496 +0x23 fp=0x649037f0 sp=0x649037e8 pc=0x81b7523
runtime.goexit({})
	/tmp/workdir/go/src/runtime/asm_386.s:1363 +0x1 fp=0x649037f4 sp=0x649037f0 pc=0x80b8121
created by runtime/trace_test.TestTraceStressStartStop.func1 in goroutine 35
	/tmp/workdir/go/src/runtime/trace/trace_test.go:494 +0x6c8

2023-11-21 21:29 openbsd-386-72 go@90ba4452 runtime/trace (log)

fatal error: runtime: out of memory

runtime stack:
runtime.throw({0x8202d22, 0x16})
	/tmp/workdir/go/src/runtime/panic.go:1023 +0x4d fp=0x2ec54984 sp=0x2ec54970 pc=0x808372d
runtime.sysMapOS(0x95c00000, 0x400000)
	/tmp/workdir/go/src/runtime/mem_bsd.go:81 +0x142 fp=0x2ec549b0 sp=0x2ec54984 pc=0x805f032
runtime.sysMap(0x95c00000, 0x400000, 0x8350218)
	/tmp/workdir/go/src/runtime/mem.go:155 +0x3f fp=0x2ec549c0 sp=0x2ec549b0 pc=0x805ee0f
runtime.(*mheap).grow(0x8342ee0, 0x12)
...
runtime.gopark(0x0, 0x0, 0xa, 0x10, 0x1)
	/tmp/workdir/go/src/runtime/proc.go:402 +0xfa fp=0x5683afd4 sp=0x5683afc0 pc=0x80866ea
runtime.block()
	/tmp/workdir/go/src/runtime/select.go:103 +0x32 fp=0x5683afe8 sp=0x5683afd4 pc=0x8097232
runtime/trace_test.TestTraceStressStartStop.func1.10()
	/tmp/workdir/go/src/runtime/trace/trace_test.go:496 +0x23 fp=0x5683aff0 sp=0x5683afe8 pc=0x81b7523
runtime.goexit({})
	/tmp/workdir/go/src/runtime/asm_386.s:1363 +0x1 fp=0x5683aff4 sp=0x5683aff0 pc=0x80b8121
created by runtime/trace_test.TestTraceStressStartStop.func1 in goroutine 35
	/tmp/workdir/go/src/runtime/trace/trace_test.go:494 +0x6c8

— watchflakes

[mknyszek]

This has probably stopped happening since the new tracer was turned on by default, since this test isn't run anymore. In that sense it's fixed, but if for whatever reason the new tracer gets rolled back, watchflakes will probably reopen this if I close it. So, I'm going to optimistically close it but leave it open so I remember to resolve it if that happens.

I am not particularly concerned that this is going to be anything more than a test issue.