go/printer: TestFiles failures with running too slowly

[gopherbot]

#!watchflakes
post <- pkg == "go/printer" && test == "TestFiles" && `running too slowly`

Issue created automatically to collect these failures.

Example (log):

--- FAIL: TestFiles (0.00s)
    --- FAIL: TestFiles/empty.input (10.01s)
        printer_test.go:160: testdata/empty.input: running too slowly

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "go/printer" && test == "TestFiles"

2022-11-10 18:51 openbsd-mips64-jsing go@79d9b395 go/printer.TestFiles (log)

--- FAIL: TestFiles (0.00s)
    --- FAIL: TestFiles/empty.input (10.01s)
        printer_test.go:160: testdata/empty.input: running too slowly

— watchflakes

[bcmills]

This is the regression test for #1628, and it uses an arbitrary 10-second timeout:
https://cs.opensource.google/go/go/+/master:src/go/printer/printer_test.go;l=158;drc=078cc6a04f1dc0ef46f1bd5c27dc20a6fcfbabcf

@griesemer, is the arbitrary timeout still useful? I see that #1628 was fixing an exponential-time algorithm — would the regression test time out naturally without this artificial limit?

[bcmills]

(CC @mvdan as a secondary owner of go/printer)

[mvdan]

It seems like the original test without the fix took over a minute, so it might not trigger default timeouts like 10m. I agree that the mechanism of using a 10s timeout isn't great, because a sufficiently busy or slow machine can still lead to timing flakes.

Perhaps we could instead have the tests count the number of calls to Fprint. Before the fix, that number was exponential, so we should be able to pin down an expected number or range of Fprint calls per test case. That shouldn't cause flakes or change from machine to machine.

It does require a tiny bit of extra bookkeeping, but full calls to Fprint shouldn't be too frequent thanks to the memoization. And the test would have to poke at the printer internals to get the resulting count, but I don't see a better way to tell if the printer is being exponential or not - without using timeouts.

[bcmills]

I don't see a better way to tell if the printer is being exponential or not - without using timeouts

The usual way to detect an exponential function is to fit a curve to a lot of samples. But “a lot of samples” sounds expensive and nearly as prone to noise. 😅

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "go/printer" && test == "TestFiles"

2023-09-13 23:32 linux-s390x-ibm-race go@fccd0b9b go/printer.TestFiles (log)

--- FAIL: TestFiles (0.00s)
    --- FAIL: TestFiles/expressions.input (10.29s)
        printer_test.go:160: testdata/expressions.input: running too slowly

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "go/printer" && test == "TestFiles"

2023-10-24 13:47 linux-s390x-ibm-race go@6f87db50 go/printer.TestFiles (log)

--- FAIL: TestFiles (0.01s)
    --- FAIL: TestFiles/slow.input (11.21s)
        printer_test.go:160: testdata/slow.input: running too slowly
    --- FAIL: TestFiles/expressions.input (10.07s)
        printer_test.go:160: testdata/expressions.input: running too slowly
    --- FAIL: TestFiles/declarations.input (10.06s)
        printer_test.go:160: testdata/declarations.input: running too slowly
    --- FAIL: TestFiles/expressions.input#01 (10.03s)
        printer_test.go:160: testdata/expressions.input: running too slowly

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "go/printer" && test == "TestFiles" && `running too slowly`

2023-11-07 21:13 linux-s390x-ibm-race go@9e90a15b go/printer.TestFiles (log)

--- FAIL: TestFiles (0.00s)
    --- FAIL: TestFiles/generics.input (10.01s)
        printer_test.go:160: testdata/generics.input: running too slowly
    --- FAIL: TestFiles/go2numbers.input (10.01s)
        printer_test.go:160: testdata/go2numbers.input: running too slowly
    --- FAIL: TestFiles/declarations.input (10.09s)
        printer_test.go:160: testdata/declarations.input: running too slowly

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "go/printer" && test == "TestFiles" && `running too slowly`

2023-12-06 23:34 linux-s390x-ibm-race go@2b442575 go/printer.TestFiles (log)

--- FAIL: TestFiles (0.03s)
    --- FAIL: TestFiles/linebreaks.input (10.40s)
        printer_test.go:160: testdata/linebreaks.input: running too slowly

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "go/printer" && test == "TestFiles" && `running too slowly`

2024-01-30 14:41 gotip-linux-ppc64le go@b89ad464 go/printer.TestFiles (log)

=== RUN   TestFiles/expressions.input#01
=== PAUSE TestFiles/expressions.input#01
=== CONT  TestFiles/expressions.input#01
    printer_test.go:160: testdata/expressions.input: running too slowly
--- FAIL: TestFiles/expressions.input#01 (10.00s)

— watchflakes