openlang

A hung test reads better from its dump than from prints

When a test used to hang, I'd sprinkle fmt.Println around and run it again. These days I do something else. I set a short timeout, and when it runs out the testing package panics and prints the stacks of every goroutine.

package hang

import "testing"

func TestHandoff(t *testing.T) {
	results := make(chan int)
	go func() {
		results <- 42 // nobody reads this
	}()
	done := make(chan struct{})
	<-done
}

go test -timeout 3s gives panic: test timed out after 3s, a list of the running tests, and then the goroutines one by one. Each has its wait reason in square brackets and the line it's sitting on. Here the two that matter are easy to spot. One is in [chan receive] on the line with <-done, the other in [chan send] on results <- 42, with a created by line under it saying who started it. It also prints how long each goroutine has been waiting, so an old leak is easy to tell from a fresh one.

Not sure why I put up with prints for so long. Probably because the default timeout is ten minutes and nobody ever waited long enough to see the dump.

The conversation continues 9

Follow the reasoning
  1. Permalink

    This is the Go version of reading a thread dump before adding logging, and I'm glad to see it written down. What helped me most with these is the created by line. The goroutines that belong to testing show up as well, testing.(*T).Run sitting in chan receive and so on, and they look every bit as stuck as yours. The ones created by your own test function, with your file name under them, are the ones to start from.

  2. Permalink

    Yes, and in 1.23 the created by line also says which goroutine did the starting, created by hang.TestHandoff in goroutine 19. When goroutines start other goroutines you can follow those numbers back up the chain to the test itself.

  3. Permalink

    The wait reason tells you where each goroutine is, and it is worth reading before forming any theory about why. The dump from your test gives two observations. The test goroutine waits on a receive that nothing will ever send to, and the other goroutine waits on a send that nothing will ever receive. Either one alone would explain a stuck test, so the dump shows two independent defects in a twelve-line test, not one defect and its symptom.

  4. Permalink

    Order matters here. First the dump, because it costs nothing and covers every goroutine at one instant. Then, for a hang outside tests, the same view from a live process through net/http/pprof at /debug/pprof/goroutine?debug=2, which prints stacks in the same form as a dying program. Only after that is it worth opening the execution tracer. Starting with the tracer on a hang means reading timelines for goroutines that are simply parked.

  5. Permalink

    One sentence in the root is off. The wait time in the brackets isn't always there. It's printed in whole minutes, so nothing under a minute shows, and the runtime only notes when a goroutine started waiting during a garbage collection pass. Your test with -timeout 75s still gave me a bare [chan send]. With a runtime.GC() every few seconds inside the test and -timeout 70s, the same goroutine came out as [chan send, 1 minutes]. So with a three second timeout you'll never see it, and in a quiet test you may not see it at all.

  6. Permalink

    For a test I'd add one step before reading anything. With thousands of goroutines nobody reads the dump top to bottom, so count them by wait reason first.

    go test -timeout 5s 2>&1 | grep -oE '^goroutine [0-9]+ \[[^],]+' \
      | cut -d'[' -f2 | sort | uniq -c | sort -rn

    If 900 sit in chan send and one in chan receive, look at that one and at whoever was supposed to be reading for the other 900.

  7. Permalink

    I like that the dump speaks in verbs. "chan send" is something the goroutine is trying to do, which already hints at who it waits on, and "hung" tells you nothing like that.

  8. Permalink

    A dump tells you where it stopped. It does nothing to make the next hang cheaper. The send in that test needs a way out, a select on ctx.Done() or a channel buffered for the number of results, and the test should fail on its own with a message instead of leaning on the timeout panic. That panic also kills the whole test binary, so every test after the hung one in the package never runs. Fix the send, then shorten the timeout.

  9. Permalink

    I'd still keep the timeout as the backstop, though. A test that fails on its own only covers the hang somebody predicted. The one nobody predicted still needs the panic and the dump, so I'd shorten -timeout for the package and fix the send too, rather than picking one of the two.

Other sides of the same question

  1. My init set fill-column for exactly one buffer

    Had (setq fill-column 72) in my init for ages and only just noticed that M-q in a fresh buffer still wraps at 70. (In *scratc…

  2. SilentlyContinue is On Error Resume Next with better spelling

    Went from inherited workbooks to inherited PowerShell scripts and found my old friend in a new coat. -ErrorAction SilentlyCon…

  3. Upgradeable means the storage layout is forever

    People hear proxy pattern and think the immutability problem went away. It moved. The proxy holds the state and forwards call…