cmd/trace: TestAnalyzeAnnotationGC flaky

[aclements]

TestAnalyzeAnnotationGC has been flaky on Windows and Solaris since it was introduced.

On Windows it fails with:

--- FAIL: TestAnalyzeAnnotationGC (0.03s)
	annotations_test.go:243: taskWithGC reported 29.721802ms as overlapping GC time; want (0, 29.2968ms): task 6:	taskWithGC
			start: 16015 end: 30223063 complete: true
			2 goroutines
			2 spans:
				taskWithGC.span1(goid=30)
				taskWithGC.span2(goid=32)
			0 children:

On Solaris it fails with:

--- FAIL: TestAnalyzeAnnotations (0.00s)
	annotations_test.go:70: failed to analyzeAnnotations: failed to parse trace: failed to open trace file: open : no such file or directory

$ greplogs -dashboard -E TestAnalyzeAnnotationGC -l | findflakes -paths
First observed cacf812 21 Feb 19:48 2018 (29 commits ago)
Last observed  fceaa2e 23 Feb 16:48 2018 (5 commits ago)
13% chance failure is still happening
33% failure probability (9 of 25 commits)
Likely culprits:
   33% cacf812 cmd/trace: present the GC time in the usertask view
   22% 438a757 cmd/compile/internal: reuse more memory
   15% ac81c5c cmd/compile/internal/ssa: refactor buildLocationLists
   10% e181852 cmd/compile/internal: use sparseSet, optimize isSynthetic
    7% 108efc7 cmd/compile/internal/ssa: shrink commonly-used structs
    4% ebeea20 cmd/compile: use | in the most repetitive ppc64 rules
No known past failures

$ greplogs -dashboard -E TestAnalyzeAnnotationGC -l -md
2018-02-21T19:48:35-cacf812/windows-386-2008
2018-02-21T19:48:35-cacf812/windows-amd64-2016
2018-02-21T20:14:30-3e1ac1b/windows-amd64-2008
2018-02-21T20:32:35-ed1959c/windows-amd64-2016
2018-02-21T21:04:09-e02d6bb/windows-amd64-2012
2018-02-22T04:10:07-f4c3072/solaris-amd64-smartosbuildlet
2018-02-22T15:17:52-ef3ab3f/solaris-amd64-smartosbuildlet
2018-02-22T16:28:38-2465ae6/windows-386-2008
2018-02-23T13:49:55-9ee78af/windows-386-2008
2018-02-23T16:48:01-fceaa2e/solaris-amd64-smartosbuildlet
2018-02-23T16:48:01-fceaa2e/windows-386-2008

/cc @hyangah

[gopherbot]

Change https://golang.org/cl/96855 mentions this issue: cmd/trace: trace error check and more logging in annotations test

[mvdan]

Another one: https://storage.googleapis.com/go-build-log/95ddc0ea/windows-386-2008_fa97bd6c.log

[gopherbot]

Change https://golang.org/cl/97555 mentions this issue: cmd/trace: fix overlappingDuration

[hyangah]

I sent a cl to fix an obvious bug. But the CL doesn't eliminate the flakiness completely. I guess it surfaced issues with timestamps or trace logging on Windows. I captured a trace from a failed test run on gomote buildlet, where the user code reports 977us for debug.FreeOSMemory call, but the corresponding GCDone-GCStart timestamps report 1.383112ms (also the UI too)

$ go tool trace -d TestAnalyzeAnnotationGC.trace.failed  | egrep "GCStart|GCDone"
2018/02/27 18:45:35 Parsing trace...
68810 GCStart p=1000004 g=0 off=403 seq=0
1451922 GCDone p=1 g=0 off=449

TestAnalyzeAnnotationGC.trace.failed.gz

[alexbrainman]

I captured a trace from a failed test run on gomote buildlet, where the user code reports 977us for debug.FreeOSMemory call, but the corresponding GCDone-GCStart timestamps report 1.383112ms (also the UI too)

@hyangah I did not look into this problem. But just a general comment - you cannot sleep for less than 1ms on Windows.

Alex

[hyangah]

Thanks @alexbrainman
I think this is related to #8976, #16755. @dvyukov
Execution tracer uses runtime.cputicks and computes timestamps based on them. The time package measures time based on the monotonic clock value (runtime.nanotime), which returns different value.
I see occasional jumps in the cputicks values in the trace.

I don't know why we saw this in only windows buildlets so far. Given #16755, I think this can happen in unix systems.

I will skip this test in -short mode for now.

Will take a look at the Solaris case separately.

[hyangah]

Solaris: Indeed duplicate of #16755

https://build.golang.org/log/844551cc3c0f145093b6a58286e7a9f81edccec0

--- FAIL: TestAnalyzeAnnotations (0.00s)
annotations_test.go:94: failed to trace the program: time stamps out of order
--- FAIL: TestAnalyzeAnnotationTaskTree (0.00s)
annotations_test.go:159: failed to trace the program: time stamps out of order
--- FAIL: TestAnalyzeAnnotationGC (0.00s)
annotations_test.go:249: failed to trace the program: time stamps out of order

[gopherbot]

Change https://golang.org/cl/97757 mentions this issue: cmd/trace: skip tests if parsing fails with timestamp error