runtime: TestCgoPprof{,PIE} is flaky #37201

bcmills · 2020-02-12T20:08:34Z

2020-02-12T18:22:50-363bcd0/linux-ppc64le-power9osu
2020-02-07T18:08:01-b806182/linux-amd64-jessie

--- FAIL: TestCgoPprofPIE (8.17s)
    crash_cgo_test.go:311: [/workdir/go/bin/go tool pprof -traces /workdir/tmp/go-build499031835/testprogcgo_-buildmode=pie.exe /workdir/tmp/prof767840548]:
        File: testprogcgo_-buildmode=pie.exe
        Build ID: 8fb7f17909e63decefe761e095ce9dbd1c97e738
        Type: cpu
        Time: Feb 7, 2020 at 6:35pm (UTC)
        Duration: 200.51ms, Total samples = 0 
        -----------+-------------------------------------------------------
    crash_cgo_test.go:319: cpuHog traceback missing.
    crash_cgo_test.go:311: [/workdir/go/bin/go tool pprof -traces /workdir/tmp/prof767840548]:
        File: testprogcgo_-buildmode=pie.exe
        Build ID: 8fb7f17909e63decefe761e095ce9dbd1c97e738
        Type: cpu
        Time: Feb 7, 2020 at 6:35pm (UTC)
        Duration: 200.51ms, Total samples = 0 
        -----------+-------------------------------------------------------
    crash_cgo_test.go:319: cpuHog traceback missing.
FAIL
FAIL	runtime	33.607s

Given the timing of the logs, it's not clear to me whether this is a regression in Go 1.14 or simply an already-flaky test coming to the surface.

CC @mknyszek @aclements @hyangah @ianlancetaylor @mpx

The text was updated successfully, but these errors were encountered:

gopherbot · 2020-02-13T21:46:05Z

Change https://golang.org/cl/219417 mentions this issue: runtime: deflake CGO traceback tests

mpx · 2020-02-13T21:49:51Z

I suspect the test is flaky since it only collects 2+ cpuHog frames. I'm not familiar with how Pprof decides which samples to include in the profile, but it looks like in some rare cases cpuHog doesn't make the cut. The above log shows 0 samples reported in 200ms. That indicates the test loop exited early with at least 2 samples (since 200ms < 1 second loop timeout), but they weren't reported.

If so, collecting more samples should significantly reduce the likelihood of a flake.

I'm currently running a large number of tests to see if I can catch the flake. If that works, I should be able to confirm the above patch fixes the problem.

mpx · 2020-02-15T06:03:29Z

I couldn't reproduce the flake on an unloaded machine, but I managed to reproduce it after ~13000 on a reasonably heavily loaded machine (lots of IO, CPU load and scheduling keeping the cores 100% busy).

--- FAIL: TestCgoPprofPIE (0.22s)
    crash_cgo_test.go:311: [/home/mark/go-dev/bin/go tool pprof -traces /tmp/go-build052039209/testprogcgo_-buildmode=pie.exe /tmp/prof021439459]:
        File: testprogcgo_-buildmode=pie.exe
        Build ID: 57c37c1d4a6f0a6bb608c00c63c35c050438b0c3
        Type: cpu
        Time: Feb 15, 2020 at 4:02am (AEDT)
        Duration: 200.27ms, Total samples = 0 
        -----------+-------------------------------------------------------
    crash_cgo_test.go:319: cpuHog traceback missing.

Retrying with the patch now.

mpx · 2020-02-16T04:10:47Z

I was unable to reproduce the flake with the patch after ~200000 tests. Without the patch it typically fails within 5000-20000 tests (both tested from +123f7dd3e1).

I had a quick look through the profiling code and I can't see any good reason why frames should be dropped at all for this test. It's not clear to me why "2" frames were originally chosen.

Going in the other direction, waiting for only a single cpuHog frame appears reliable on go1.13.7, but fails easily on go1.14rc1 (usually <100 tests).

Running a bisect now to see where this test started failing intermittently.

mpx · 2020-02-16T06:13:44Z

The test is flaky from 177a36a (runtime: implement async scheduler preemption) onwards. The test is reliable with GODEBUG=asyncpreemptoff=1. @aclements

The CGO traceback is definitely called (as noted above, I also confirmed with a trace write separately). There is some bad interaction between signal pre-emption and profiling which causes the sample to be lost.

Perhaps this test should only use a single frame? That would have surfaced the issue much earlier.
Updated the earlier change to make it more sensitive rather than less.

mpx · 2020-02-21T03:12:28Z

@bcmills @aclements @ianlancetaylor

It might be worth investigating this issue further before Go 1.14 is released to confirm the damage is limited to loss of some profile samples (and not something more fundamental).

ianlancetaylor · 2020-02-21T03:32:24Z

The test doesn't count the number of profiling samples that are taken. It counts the number of times the pprofCgoTraceback function is called. That function is called any time a signal occurs while executing in non-Go code. Before we started using signal based preemption, the only signal that would occur in non-Go code was SIGPROF. Now we can also see SIGURG. That is not a bug. But it means that this test is flaky: if we see two SIGURG signals in non-Go code before we see any SIGPROF signals in non-Go code, the test will fail.

So I don't think there is a fundamental problem here. It's a problem with the way that the test is written. It's not a problem that would happen with real code.

Unfortunately I don't see a simple fix off hand, other than disabling signal based preemption for the test.

mpx · 2020-02-21T04:06:30Z

Ah, great. Thanks for confirming it is expected that pprofCgoTraceback is called outside of profile samples, I missed that.

I've reverted my change so it waits for more pprofCgoTraceback calls since it is extremely unlikely that every one of them will not result in a sample. That should effectively deflake the test until a better test is desired/written.

ianlancetaylor · 2020-02-21T14:22:54Z

Maybe we should simply disable signal-based preemption when running the test. The point of the test is just to see that we pick up a stack trace for SIGPROF, disabling signal-based preemption doesn't invalidate what we are testing for.

mpx · 2020-03-01T08:38:36Z

Sorry, missed that suggestion earlier - much better idea. I've updated the deflake change. Given this flake was only noticed after signal preemption, it should more or less make it disappear again. I haven't been able to reproduce it after disabling preemption.

The CGO traceback function is called whenever CGO code is executing and a signal is received. This occurs much more frequently now SIGURG is used for preemption. Disable signal preemption to significantly increase the likelihood that a signal results in a profile sample during the test. Updates #37201 Change-Id: Icb1a33ab0754d1a74882a4ee265b4026abe30bdc Reviewed-on: https://go-review.googlesource.com/c/go/+/219417 Run-TryBot: Emmanuel Odeke <emm.odeke@gmail.com> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Ian Lance Taylor <iant@golang.org>

mpx · 2020-03-08T02:49:32Z

FYI, I left this issue open in case this issue should track fixing the test approach and/or runtime.

bcmills · 2020-05-12T15:32:04Z

Still flaky after CL 219417:
2020-05-12T15:01:56-a0698a6/linux-amd64-jessie

danscales · 2020-05-12T23:27:46Z

I also got the failure with a recently rebased changed:

https://storage.googleapis.com/go-build-log/3d4facca/linux-amd64-race_bb62fb2a.log

bcmills · 2020-05-14T19:12:57Z

2020-05-13T11:59:26-810c27e/linux-amd64-race

bcmills · 2020-05-21T03:44:29Z

Including both TestCgoPprofPIE and TestCgoPprof, it looks like this got quite a bit worse around 2020-05-11:
2020-05-20T21:52:34-567556d/linux-amd64-fedora
2020-05-13T11:59:26-810c27e/linux-amd64-race
2020-05-12T15:01:56-a0698a6/linux-amd64-jessie
2020-05-11T22:38:32-8c1db77/linux-amd64-race
2020-02-12T18:22:50-363bcd0/linux-ppc64le-power9osu
2020-02-07T18:08:01-b806182/linux-amd64-jessie

I've also seen it in quite a few TryBot results recently.

Marking as release-blocker for Go 1.15 due to the likelihood of a regression here.

cagedmantis · 2020-05-21T21:39:16Z

@bcmills Can I make this a non-beta1 blocking issue?

bcmills · 2020-05-21T21:47:58Z

Yep, that seems fine.

odeke-em · 2020-05-29T10:05:20Z

I just got a failure at https://storage.googleapis.com/go-build-log/9b94d0b5/linux-amd64-race_d785929a.log

--- FAIL: TestCgoPprof (3.47s)
    crash_cgo_test.go:317: [/workdir/go/bin/go tool pprof -traces /workdir/tmp/go-build787198486/testprogcgo_.exe /workdir/tmp/prof847643684]:
        File: testprogcgo_.exe
        Build ID: a25028f2fff69a0864f81c4cca9180f2f354c52b
        Type: cpu
        Time: May 29, 2020 at 10:00am (UTC)
        Duration: 200.66ms, Total samples = 0 
        -----------+-------------------------------------------------------
    crash_cgo_test.go:325: cpuHog traceback missing.
    crash_cgo_test.go:317: [/workdir/go/bin/go tool pprof -traces /workdir/tmp/prof847643684]:
        File: testprogcgo_.exe
        Build ID: a25028f2fff69a0864f81c4cca9180f2f354c52b
        Type: cpu
        Time: May 29, 2020 at 10:00am (UTC)
        Duration: 200.66ms, Total samples = 0 
        -----------+-------------------------------------------------------
    crash_cgo_test.go:325: cpuHog traceback missing.
FAIL
FAIL	runtime	54.956s
FAIL
go tool dist: Failed: exit status 1

cherrymui · 2020-05-29T19:26:59Z

Could this be similar to #39021 , in that the program gets signaled with SIGWINCH that sent to the the process group, and triggered pprofCgoTraceback to run too early?

cherrymui · 2020-05-29T22:29:27Z

I think CL https://golang.org/cl/235557 also fixes this. On my machine it was ~10% failure rate (running runtime test in a loop), after applying that CL it doesn't fail with 100+ iterations.

ianlancetaylor · 2020-06-16T02:49:29Z

This hasn't happened since CL 235557 was committed, and findflakes estimates a 0.00% probability that this is still broken. Closing.

bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Feb 12, 2020

bcmills added this to the Backlog milestone Feb 12, 2020

bcmills mentioned this issue May 14, 2020

runtime: "unexpected result from waitpid" in TestGdbPython #39021

Closed

bcmills added the release-blocker label May 21, 2020

bcmills modified the milestones: Backlog, Go1.15 May 21, 2020

bcmills changed the title ~~runtime: TestCgoPprofPIE is flaky~~ runtime: TestCgoPprof{,PIE} is flaky May 21, 2020

cagedmantis added the okay-after-beta1 Used by release team to mark a release-blocker issue as okay to resolve either before or after beta1 label May 21, 2020

toothrot removed the okay-after-beta1 Used by release team to mark a release-blocker issue as okay to resolve either before or after beta1 label Jun 10, 2020

ianlancetaylor closed this as completed Jun 16, 2020

bcmills mentioned this issue Sep 9, 2020

all: Go 1.14.9 release status #41293

Closed

golang locked and limited conversation to collaborators Jun 16, 2021

gopherbot added the FrozenDueToAge label Jun 16, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

runtime: TestCgoPprof{,PIE} is flaky #37201

runtime: TestCgoPprof{,PIE} is flaky #37201

bcmills commented Feb 12, 2020

gopherbot commented Feb 13, 2020

mpx commented Feb 13, 2020 •

edited

Loading

mpx commented Feb 15, 2020

mpx commented Feb 16, 2020

mpx commented Feb 16, 2020 •

edited

Loading

mpx commented Feb 21, 2020

ianlancetaylor commented Feb 21, 2020

mpx commented Feb 21, 2020 •

edited

Loading

ianlancetaylor commented Feb 21, 2020

mpx commented Mar 1, 2020

mpx commented Mar 8, 2020

bcmills commented May 12, 2020

danscales commented May 12, 2020

bcmills commented May 14, 2020

bcmills commented May 21, 2020

cagedmantis commented May 21, 2020

bcmills commented May 21, 2020

odeke-em commented May 29, 2020

cherrymui commented May 29, 2020

cherrymui commented May 29, 2020

ianlancetaylor commented Jun 16, 2020

runtime: TestCgoPprof{,PIE} is flaky #37201

runtime: TestCgoPprof{,PIE} is flaky #37201

Comments

bcmills commented Feb 12, 2020

gopherbot commented Feb 13, 2020

mpx commented Feb 13, 2020 • edited Loading

mpx commented Feb 15, 2020

mpx commented Feb 16, 2020

mpx commented Feb 16, 2020 • edited Loading

mpx commented Feb 21, 2020

ianlancetaylor commented Feb 21, 2020

mpx commented Feb 21, 2020 • edited Loading

ianlancetaylor commented Feb 21, 2020

mpx commented Mar 1, 2020

mpx commented Mar 8, 2020

bcmills commented May 12, 2020

danscales commented May 12, 2020

bcmills commented May 14, 2020

bcmills commented May 21, 2020

cagedmantis commented May 21, 2020

bcmills commented May 21, 2020

odeke-em commented May 29, 2020

cherrymui commented May 29, 2020

cherrymui commented May 29, 2020

ianlancetaylor commented Jun 16, 2020

mpx commented Feb 13, 2020 •

edited

Loading

mpx commented Feb 16, 2020 •

edited

Loading

mpx commented Feb 21, 2020 •

edited

Loading