Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

cmd/trace: TestAnalyzeAnnotationGC flaky #24081

Closed
aclements opened this issue Feb 23, 2018 · 8 comments
Closed

cmd/trace: TestAnalyzeAnnotationGC flaky #24081

aclements opened this issue Feb 23, 2018 · 8 comments
Labels
FrozenDueToAge
Milestone
Go1.11

Comments

@aclements
Copy link
Member

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
@aclements aclements added this to the Go1.11 milestone Feb 23, 2018
@gopherbot
Copy link

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

gopherbot pushed a commit that referenced this issue Feb 26, 2018
@hyangah
cmd/trace: trace error check and more logging in annotations test
a5c987f 
This is for debugging the reported flaky tests.

Update #24081

Change-Id: Ica046928f675d69e38251a47a6f225efedce920c
Reviewed-on: https://go-review.googlesource.com/96855
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Heschi Kreinick <heschi@google.com>
@mvdan
Copy link
Member

mvdan commented Feb 27, 2018

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

@gopherbot
Copy link

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

@hyangah
Copy link
Contributor

hyangah commented Feb 27, 2018 •
edited

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

@hyangah hyangah self-assigned this Feb 27, 2018
gopherbot pushed a commit that referenced this issue Feb 28, 2018
@hyangah
cmd/trace: fix overlappingDuration
b5bd5bf 
Update #24081

Change-Id: Ieccfb03c51e86f35d4629a42959c80570bd93c33
Reviewed-on: https://go-review.googlesource.com/97555
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
@alexbrainman
Copy link
Member

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
Copy link
Contributor

hyangah commented Feb 28, 2018

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
Copy link
Contributor

hyangah commented Feb 28, 2018

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
Copy link

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

@golang golang locked and limited conversation to collaborators Feb 28, 2019
@rsc rsc unassigned hyangah Jun 23, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge
Projects
None yet
Milestone
Go1.11
Development

No branches or pull requests
5 participants
@aclements @mvdan @hyangah @gopherbot @alexbrainman