Skip to content
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.

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

runtime: TestStackGrowth failures #57601

Closed
gopherbot opened this issue Jan 4, 2023 · 16 comments
Closed

runtime: TestStackGrowth failures #57601

gopherbot opened this issue Jan 4, 2023 · 16 comments
Assignees
@cherrymui
Labels
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
Go1.21

Comments

@gopherbot
Copy link

gopherbot commented Jan 4, 2023 •
edited by cherrymui 

#!watchflakes
post <- pkg == "runtime" && `panic: finalizer started .* ago .* and ran \d+ iterations, but did not return` && goarch != "s390x"

Issue created automatically to collect these failures.

Example (log):

panic: finalizer started 104.093721ms ago (1.068654ms after registration) and ran 98 iterations, but did not return

runtime.gopark(0x843adec, 0x86a8a00, 0x12, 0x19, 0x4)
	/tmp/workdir/go/src/runtime/proc.go:381 +0xf6 fp=0x5884fe4c sp=0x5884fe38 pc=0x8089086
runtime.goparkunlock(...)
	/tmp/workdir/go/src/runtime/proc.go:387
runtime.semacquire1(0x58b94438, 0x0, 0x1, 0x0, 0x12)
	/tmp/workdir/go/src/runtime/sema.go:160 +0x239 fp=0x5884fe80 sp=0x5884fe4c pc=0x809a709
sync.runtime_Semacquire(0x58b94438)
	/tmp/workdir/go/src/runtime/sema.go:62 +0x35 fp=0x5884fe98 sp=0x5884fe80 pc=0x80bdec5
sync.(*WaitGroup).Wait(0x58b94430)
	/tmp/workdir/go/src/sync/waitgroup.go:116 +0x5f fp=0x5884feb4 sp=0x5884fe98 pc=0x80c795f
runtime_test.TestStackGrowth(0x58d82000)
	/tmp/workdir/go/src/runtime/stack_test.go:141 +0x55a fp=0x5884ff9c sp=0x5884feb4 pc=0x836e89a
testing.tRunner(0x58d82000, 0x843bb54)

— watchflakes
@gopherbot gopherbot added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. compiler/runtime Issues related to the Go compiler and/or runtime. labels Jan 4, 2023
@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "runtime" && test == "TestStackGrowth"
2022-11-29 01:18 openbsd-386-71 go@0fd7be7e runtime.TestStackGrowth (log) 
panic: finalizer started 104.093721ms ago (1.068654ms after registration) and ran 98 iterations, but did not return

runtime.gopark(0x843adec, 0x86a8a00, 0x12, 0x19, 0x4)
	/tmp/workdir/go/src/runtime/proc.go:381 +0xf6 fp=0x5884fe4c sp=0x5884fe38 pc=0x8089086
runtime.goparkunlock(...)
	/tmp/workdir/go/src/runtime/proc.go:387
runtime.semacquire1(0x58b94438, 0x0, 0x1, 0x0, 0x12)
	/tmp/workdir/go/src/runtime/sema.go:160 +0x239 fp=0x5884fe80 sp=0x5884fe4c pc=0x809a709
sync.runtime_Semacquire(0x58b94438)
	/tmp/workdir/go/src/runtime/sema.go:62 +0x35 fp=0x5884fe98 sp=0x5884fe80 pc=0x80bdec5
sync.(*WaitGroup).Wait(0x58b94430)
	/tmp/workdir/go/src/sync/waitgroup.go:116 +0x5f fp=0x5884feb4 sp=0x5884fe98 pc=0x80c795f
runtime_test.TestStackGrowth(0x58d82000)
	/tmp/workdir/go/src/runtime/stack_test.go:141 +0x55a fp=0x5884ff9c sp=0x5884feb4 pc=0x836e89a
testing.tRunner(0x58d82000, 0x843bb54)
2022-12-14 19:13 openbsd-386-71 go@5c682f94 runtime.TestStackGrowth (log) 
panic: finalizer started 152.908275ms ago (1.393595ms after registration) and ran 153 iterations, but did not return

runtime.gopark(0x843a718, 0x86a8180, 0x12, 0x19, 0x4)
	/tmp/workdir/go/src/runtime/proc.go:381 +0xf6 fp=0x5a04ee4c sp=0x5a04ee38 pc=0x8089086
runtime.goparkunlock(...)
	/tmp/workdir/go/src/runtime/proc.go:387
runtime.semacquire1(0x5a5613f8, 0x0, 0x1, 0x0, 0x12)
	/tmp/workdir/go/src/runtime/sema.go:160 +0x239 fp=0x5a04ee80 sp=0x5a04ee4c pc=0x809a6f9
sync.runtime_Semacquire(0x5a5613f8)
	/tmp/workdir/go/src/runtime/sema.go:62 +0x35 fp=0x5a04ee98 sp=0x5a04ee80 pc=0x80bdeb5
sync.(*WaitGroup).Wait(0x5a5613f0)
	/tmp/workdir/go/src/sync/waitgroup.go:116 +0x5f fp=0x5a04eeb4 sp=0x5a04ee98 pc=0x80c794f
runtime_test.TestStackGrowth(0x5a1a3770)
	/tmp/workdir/go/src/runtime/stack_test.go:141 +0x55a fp=0x5a04ef9c sp=0x5a04eeb4 pc=0x836e32a
testing.tRunner(0x5a1a3770, 0x843b484)

— watchflakes

@bcmills

This comment was marked as outdated.

Sign in to view
@bcmills bcmills marked this as a duplicate of #57585 Jan 6, 2023
@bcmills bcmills closed this as not planned Won't fix, can't repro, duplicate, stale Jan 6, 2023
@bcmills bcmills reopened this Jan 6, 2023
@bcmills
Copy link
Contributor

bcmills commented Jan 6, 2023

https://build.golang.org/log/5571acfcf4d4d6de5d3f22b56f8c2dca2623f7cc (netbsd-arm64-bsiegert) also has one of these, so it's not just openbsd-.*-71.

@bcmills bcmills marked this as not a duplicate of #57585 Jan 6, 2023
@bcmills
Copy link
Contributor

bcmills commented Jan 6, 2023

Hmm, but that's also a test timeout, not specific to this test (which only ran, in parallel, for 14s). 🤔

@bcmills bcmills closed this as not planned Won't fix, can't repro, duplicate, stale Jan 6, 2023
@bcmills bcmills mentioned this issue Jan 6, 2023
Closed
@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "runtime" && `panic: finalizer started .* ago .* and ran \d+ iterations, but did not return`
2023-01-09 18:21 openbsd-386-71 go@8232a09e runtime.TestStackGrowth (log) 
panic: finalizer started 181.140689ms ago (1.280705ms after registration) and ran 191 iterations, but did not return

runtime.gopark(0x843a6f0, 0x86a7c40, 0x12, 0x19, 0x4)
	/tmp/workdir/go/src/runtime/proc.go:381 +0xf6 fp=0x5944de4c sp=0x5944de38 pc=0x8089086
runtime.goparkunlock(...)
	/tmp/workdir/go/src/runtime/proc.go:387
runtime.semacquire1(0x596ce088, 0x0, 0x1, 0x0, 0x12)
	/tmp/workdir/go/src/runtime/sema.go:160 +0x239 fp=0x5944de80 sp=0x5944de4c pc=0x809a6f9
sync.runtime_Semacquire(0x596ce088)
	/tmp/workdir/go/src/runtime/sema.go:62 +0x35 fp=0x5944de98 sp=0x5944de80 pc=0x80bdeb5
sync.(*WaitGroup).Wait(0x596ce080)
	/tmp/workdir/go/src/sync/waitgroup.go:116 +0x5f fp=0x5944deb4 sp=0x5944de98 pc=0x80c794f
runtime_test.TestStackGrowth(0x595bf950)
	/tmp/workdir/go/src/runtime/stack_test.go:141 +0x55a fp=0x5944df9c sp=0x5944deb4 pc=0x836e54a
testing.tRunner(0x595bf950, 0x843b45c)

— watchflakes

@gopherbot gopherbot reopened this Jan 16, 2023
@bcmills
Copy link
Contributor

bcmills commented Jan 17, 2023

#57585

@bcmills bcmills closed this as not planned Won't fix, can't repro, duplicate, stale Jan 17, 2023
@gopherbot gopherbot reopened this Apr 19, 2023
@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "runtime" && `panic: finalizer started .* ago .* and ran \d+ iterations, but did not return`
2023-04-19 14:12 linux-s390x-ibm go@8c2ff88c runtime.TestStackGrowth (log) 
panic: finalizer started 21.336333797s ago (14.44791ms after registration) and ran 167 iterations, but did not return

runtime.gopark(0x51e7e0, 0x7b20e0, 0x12, 0x19, 0x4)
	/data/golang/workdir/go/src/runtime/proc.go:386 +0x136 fp=0xc00088bda8 sp=0xc00088bd90 pc=0x5b446
runtime.goparkunlock(...)
	/data/golang/workdir/go/src/runtime/proc.go:392
runtime.semacquire1(0xc001743fd8, 0x0, 0x1, 0x0, 0x12)
	/data/golang/workdir/go/src/runtime/sema.go:160 +0x248 fp=0xc00088be00 sp=0xc00088bda8 pc=0x70df8
sync.runtime_Semacquire(0xc001743fd8)
	/data/golang/workdir/go/src/runtime/sema.go:62 +0x44 fp=0xc00088be30 sp=0xc00088be00 pc=0x9dba4
sync.(*WaitGroup).Wait(0xc001743fd0)
	/data/golang/workdir/go/src/sync/waitgroup.go:116 +0x6a fp=0xc00088be48 sp=0xc00088be30 pc=0xaaeca
runtime_test.TestStackGrowth(0xc0009cdba0)
	/data/golang/workdir/go/src/runtime/stack_test.go:142 +0x59c fp=0xc00088bf60 sp=0xc00088be48 pc=0x40a3ac
testing.tRunner(0xc0009cdba0, 0x520358)

— watchflakes

@mknyszek
Copy link
Contributor

CC @golang/s390x

@mknyszek mknyszek added this to the Go1.21 milestone Apr 19, 2023
@mknyszek
Copy link
Contributor

mknyszek commented Apr 19, 2023 •
edited

@cherrymui Points out that there are a few other recent timeouts with TestStackGrowth in the stack trace on the dashboard.

EDIT: All on the s390x builder.

@cherrymui
Copy link
Member

The failure is a timeout. The other two recent failures https://build.golang.org/log/2d9a742a943b0d7f50c911c513bf4c16b3ce058b and https://build.golang.org/log/a53fee808f7e6df733f45b19ee18a08d01a5fa5d are also timeout, and both have TestStackGrowth goroutines running when it timed out. They are in the non-finalizer case so they don't have the particular error message.

The test is expected to run 256 iterations. In the three failures they have run 167, 162, and 12 iterations, respectively. (The latter two seem the whole runtime.test timed out.)

Is there any recent change on the S390X builder that could make things slower?

@cherrymui
Copy link
Member

I tried to run this test (in isolation) at tip on the s390x gomote, and the test runs pretty fast, taking about 1 second. Maybe some other tests running concurrently interfering with it? (from the log https://build.golang.org/log/1ffec993ba92cffdbf302b85265475af6f18639e it doesn't seem to have other tests running, though, at least at the time of the timeout.)

Maybe we could try running the test not in parallel with other tests, to reduce interfering. For one, the test calls GC()(which is a global operation) quite a number of times.

@gopherbot
Copy link
Author

Change https://go.dev/cl/492715 mentions this issue: runtime: don't run TestStackGrowth in parallel with other tests

@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "runtime" && `panic: finalizer started .* ago .* and ran \d+ iterations, but did not return`
2023-05-03 18:47 linux-s390x-ibm go@ea9097c9 runtime.TestStackGrowth (log) 
panic: finalizer started 6.784933416s ago (504.862µs after registration) and ran 146 iterations, but did not return

runtime.gopark(0x520838, 0x7bc860, 0x12, 0x19, 0x4)
	/data/golang/workdir/go/src/runtime/proc.go:398 +0x136 fp=0xc00006bda8 sp=0xc00006bd90 pc=0x5c536
runtime.goparkunlock(...)
	/data/golang/workdir/go/src/runtime/proc.go:404
runtime.semacquire1(0xc001a12048, 0x0, 0x1, 0x0, 0x12)
	/data/golang/workdir/go/src/runtime/sema.go:160 +0x248 fp=0xc00006be00 sp=0xc00006bda8 pc=0x720e8
sync.runtime_Semacquire(0xc001a12048)
	/data/golang/workdir/go/src/runtime/sema.go:62 +0x44 fp=0xc00006be30 sp=0xc00006be00 pc=0x9f454
sync.(*WaitGroup).Wait(0xc001a12040)
	/data/golang/workdir/go/src/sync/waitgroup.go:116 +0x6a fp=0xc00006be48 sp=0xc00006be30 pc=0xac7da
runtime_test.TestStackGrowth(0xc00021cd00)
	/data/golang/workdir/go/src/runtime/stack_test.go:142 +0x59c fp=0xc00006bf60 sp=0xc00006be48 pc=0x40d8ec
testing.tRunner(0xc00021cd00, 0x520048)

— watchflakes

@gopherbot gopherbot reopened this Jun 26, 2023
@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "runtime" && `panic: finalizer started .* ago .* and ran \d+ iterations, but did not return`
2023-06-24 05:24 linux-s390x-ibm go@a031f4ef runtime.TestStackGrowth (log) 
panic: finalizer started 12.783675437s ago (541.707µs after registration) and ran 233 iterations, but did not return

runtime.gopark(0x5474f8, 0x7f6780, 0x12, 0x19, 0x4)
	/data/golang/workdir/go/src/runtime/proc.go:398 +0x136 fp=0xc000111db0 sp=0xc000111d98 pc=0x5fb76
runtime.goparkunlock(...)
	/data/golang/workdir/go/src/runtime/proc.go:404
runtime.semacquire1(0xc00280c068, 0x0, 0x1, 0x0, 0x12)
	/data/golang/workdir/go/src/runtime/sema.go:160 +0x244 fp=0xc000111e00 sp=0xc000111db0 pc=0x75e34
sync.runtime_Semacquire(0xc00280c068)
	/data/golang/workdir/go/src/runtime/sema.go:62 +0x44 fp=0xc000111e30 sp=0xc000111e00 pc=0xa3304
sync.(*WaitGroup).Wait(0xc00280c060)
	/data/golang/workdir/go/src/sync/waitgroup.go:116 +0x6a fp=0xc000111e48 sp=0xc000111e30 pc=0xb0f8a
runtime_test.TestStackGrowth(0xc00021a1a0)
	/data/golang/workdir/go/src/runtime/stack_test.go:140 +0x58a fp=0xc000111f60 sp=0xc000111e48 pc=0x42e8ba
testing.tRunner(0xc00021a1a0, 0x546c90)

— watchflakes

@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "runtime" && `panic: finalizer started .* ago .* and ran \d+ iterations, but did not return`
2023-06-24 02:06 linux-s390x-ibm go@65092835 runtime.TestStackGrowth (log) 
panic: finalizer started 2.525700556s ago (12.638776ms after registration) and ran 88 iterations, but did not return

runtime.gopark(0x4e4b70, 0x77bba0, 0x12, 0x19, 0x4)
	/data/golang/workdir/go/src/runtime/proc.go:381 +0x128 fp=0xc000211db8 sp=0xc000211da0 pc=0x5be98
runtime.goparkunlock(...)
	/data/golang/workdir/go/src/runtime/proc.go:387
runtime.semacquire1(0xc0005c4048, 0x0, 0x1, 0x0, 0x12)
	/data/golang/workdir/go/src/runtime/sema.go:160 +0x244 fp=0xc000211e08 sp=0xc000211db8 pc=0x71664
sync.runtime_Semacquire(0xc0005c4048)
	/data/golang/workdir/go/src/runtime/sema.go:62 +0x44 fp=0xc000211e38 sp=0xc000211e08 pc=0x9c834
sync.(*WaitGroup).Wait(0xc0005c4040)
	/data/golang/workdir/go/src/sync/waitgroup.go:116 +0x6a fp=0xc000211e50 sp=0xc000211e38 pc=0xa96da
runtime_test.TestStackGrowth(0xc000002ea0)
	/data/golang/workdir/go/src/runtime/stack_test.go:141 +0x600 fp=0xc000211f68 sp=0xc000211e50 pc=0x3e4130
testing.tRunner(0xc000002ea0, 0x4e65f0)

— watchflakes

@cherrymui
Copy link
Member

The new failures are all S390X and similar to #60413.

@cherrymui cherrymui closed this as not planned Won't fix, can't repro, duplicate, stale Jun 28, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@cherrymui cherrymui

Labels
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
Test Flakes
Status: Done
Milestone
Go1.21
Development

No branches or pull requests
4 participants
@mknyszek @bcmills @gopherbot @cherrymui