testing: call (*M).after on signal or internal-generated panic

[codesenberg]

What version of Go are you using (go version)?

go version go1.8 windows/amd64

What operating system and processor architecture are you using (go env)?

set GOARCH=amd64
set GOBIN=
set GOEXE=.exe
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOOS=windows
set GOPATH=C:\Users\frei\Documents\Go\Workspaces\Default
set GORACE=
set GOROOT=C:\Go
set GOTOOLDIR=C:\Go\pkg\tool\windows_amd64
set GCCGO=gccgo
set CC=gcc
set GOGCCFLAGS=-m64 -mthreads -fmessage-length=0 -fdebug-prefix-map=C:\Users\frei\AppData\Local\Temp\go-build564910375=/tmp/go-build -gno-record-gcc-switches
set CXX=g++
set CGO_ENABLED=1
set PKG_CONFIG=pkg-config
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2

What did you do?

Ran go test -cpuprofile cpu.pprof -memprofile mem.pprof -timeout 10s in a folder with the following test file:

package main

import (
	"flag"
	"runtime"
	"testing"
	"time"
)

var (
	testDuration = flag.Duration(
		"duration", 30*time.Second, "how long to run tests",
	)
	workers = flag.Uint("workers", 10, "number of workers")
)

func TestDummy(t *testing.T) {
	for i := uint(0); i < *workers; i++ {
		go func() {
			counter := 0
			for {
				counter++
				runtime.Gosched()
			}
		}()
	}
	time.Sleep(*testDuration)
}

What did you expect to see?

Tests to end with a panic and non-empty profiles in cpu.pprof and mem.pprof.

What did you see instead?

Tests ended with a panic, but cpu.pprof was empty and mem.pprof wasn't created at all.

Previous discussion on #golang-nuts: link.

/cc @ianlancetaylor

[ALTree]

As I see it, running with a timeout set means "this shouldn't take more than 10 seconds, abort the program if it does". It's not meant to be used as a knob to control benchmarking duration; and you shouldn't use it this way. Your program was aborted because you started it with a flag set that means: "this should never take more than 10 seconds, please panic if it does".

So the question here is: should we guarantee that partial profiles are written to file if the program is killed/aborted because an invalid condition / unrecoverable problem occurred?

I don't think we should.

[josharian]

The reason I would like to write partial profiles if the program is killed (at least internally) is that sometimes I start a large benchmarking run (e.g. math/big with -count=20) and forget to bump up the timeout, and the test gets killed, and I lose 10 minutes worth of profiling efforts.

[ALTree]

@josharian to solve that problem maybe we could ignore the default timeout value (10m) when go test detects we're running benchmarks. Or make -count N multiply the timeout by N.

[randall77]

I've been bitten by this before. Having -count N multiply the timeout by N sounds like a good fix.

[codesenberg]

@ALTree, nah, this program is just for the ease of reproduction. I discovered this issue in a context unrelated to benchmarking and thought that I should report it. How you resolve it is up to you guys. I, personally, would like to see that "partial" profile, because of the time wasted. Also, maybe, those profiles could help to resolve the issues with the code that led to this timeout. Just my 2 cents.

[josharian]

Related: #12446. This just bit me again. The fix appears to be trivial: add *timeout *= len(cpuList) to the end of parseCpuList. But documenting it got hard, and I started worrying about whether anyone might really depend on -timeout being a hard timeout. Thoughts?

[ALTree]

We're deep in the freeze with no consensus about what should be done and no CL implementing generation of partial profiles, so I'm moving this to the go1.10 milestone.

[rsc]

I don't see how to fix this without adding atexit, which we've worked hard to avoid.

[rsc]

I see the argument for multiplying timeout by count but on the other hand -count=100 turning into 1000m timeout might not be what you want.

[rsc]

If we only care about the specific case of a signal arriving, or the internal panic generated by a timeout - that is, the intersection of the two things I just replied to - then we could arrange to call m.after() carefully ourselves before exiting. That seems OK to try at least if anyone is interested in preparing a CL.

[gopherbot]

CL https://golang.org/cl/48491 mentions this issue.

[meirf]

My fix was only partial but bot closed this. I used Fixes in CL, which was probably the wrong thing to do.