Skip to content

internal/trace/v2: TestTraceAnnotations failures #65181

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
Closed
gopherbot opened this issue Jan 19, 2024 · 4 comments
Closed

internal/trace/v2: TestTraceAnnotations failures #65181

gopherbot opened this issue Jan 19, 2024 · 4 comments
Assignees
@mknyszek
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Backlog

Comments

@gopherbot
Copy link
Contributor 

#!watchflakes
default <- pkg == "internal/trace/v2" && test == "TestTraceAnnotations"

Issue created automatically to collect these failures.

Example (log):

--- FAIL: TestTraceAnnotations (0.28s)
    --- FAIL: TestTraceAnnotations/Default (0.27s)
        reader_test.go:112: unexpected error while reading the trace: broken trace: failed to advance: frontier:
            [gen=1]

            M 3 [ProcStart time=469650455296 p=4 p_seq=1]

            G 3 [status=Waiting seq=0 (gen=1)]
            G 4 [status=Waiting seq=0 (gen=1)]
            G 5 [status=Waiting seq=0 (gen=1)]
...
            String id=65
            	data="internal/poll.(*FD).Write"
            String id=66
            	data="os.(*File).write"
            String id=67
            	data="/tmp/workdir/go/src/os/file_posix.go"
            String id=68
            	data="os.(*File).Write"
            String id=69
            	data="/tmp/workdir/go/src/os/file.go"

— watchflakes
@gopherbot gopherbot added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jan 19, 2024
@gopherbot
Copy link
Contributor Author

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "internal/trace/v2" && test == "TestTraceAnnotations"
2024-01-19 21:39 dragonfly-amd64-622 go@7cb98c1d internal/trace/v2.TestTraceAnnotations (log) 
--- FAIL: TestTraceAnnotations (0.28s)
    --- FAIL: TestTraceAnnotations/Default (0.27s)
        reader_test.go:112: unexpected error while reading the trace: broken trace: failed to advance: frontier:
            [gen=1]

            M 3 [ProcStart time=469650455296 p=4 p_seq=1]

            G 3 [status=Waiting seq=0 (gen=1)]
            G 4 [status=Waiting seq=0 (gen=1)]
            G 5 [status=Waiting seq=0 (gen=1)]
...
            String id=65
            	data="internal/poll.(*FD).Write"
            String id=66
            	data="os.(*File).write"
            String id=67
            	data="/tmp/workdir/go/src/os/file_posix.go"
            String id=68
            	data="os.(*File).Write"
            String id=69
            	data="/tmp/workdir/go/src/os/file.go"

— watchflakes

@bcmills bcmills added the compiler/runtime Issues related to the Go compiler and/or runtime. label Jan 22, 2024
@mknyszek mknyszek self-assigned this Jan 24, 2024
@mknyszek mknyszek added this to the Backlog milestone Jan 24, 2024
@mknyszek
Copy link
Contributor

I see the problem. There's a missing ProcSteal event here. The strange part is that the runtime ended the trace before emitting it, which shouldn't be possible. It's either that, or the GoSyscallBegin was actually blocking to start with and failed to emit a ProcStop event.

@mknyszek mknyszek moved this from Todo to In Progress in Go Compiler / Runtime Jan 25, 2024
@gopherbot
Copy link
Contributor Author

Change https://go.dev/cl/560235 mentions this issue: runtime: traceAcquire and traceRelease across all P steals

@github-project-automation github-project-automation bot moved this from In Progress to Done in Go Compiler / Runtime Feb 1, 2024
@gopherbot
Copy link
Contributor Author

Change https://go.dev/cl/559958 mentions this issue: [release-branch.go1.22] runtime: traceAcquire and traceRelease across all P steals

gopherbot pushed a commit that referenced this issue Feb 1, 2024
@mknyszek @gopherbot
[release-branch.go1.22] runtime: traceAcquire and traceRelease across…
58a35fe 
… all P steals

Currently there are a few places where a P can get stolen where the
runtime doesn't traceAcquire and traceRelease across the steal itself.
What can happen then is the following scenario:
- Thread 1 enters a syscall and writes an event about it.
- Thread 2 steals Thread 1's P.
- Thread 1 exits the syscall and writes one or more events about it.
- Tracing ends (trace.gen is set to 0).
- Thread 2 checks to see if it should write an event for the P it just
  stole, sees that tracing is disabled, and doesn't.

This results in broken traces, because there's a missing ProcSteal
event. The parser always waits for a ProcSteal to advance a
GoSyscallEndBlocked event, and in this case, it never comes.

Fixes #65181.

Change-Id: I437629499bb7669bf7fe2fc6fc4f64c53002916b
Reviewed-on: https://go-review.googlesource.com/c/go/+/560235
Reviewed-by: Michael Pratt <[email protected]>
LUCI-TryBot-Result: Go LUCI <[email protected]>
(cherry picked from commit c9d88ea)
Reviewed-on: https://go-review.googlesource.com/c/go/+/559958
Auto-Submit: Michael Knyszek <[email protected]>
ezz-no pushed a commit to ezz-no/go-ezzno that referenced this issue Feb 18, 2024
@mknyszek @ezz-no
runtime: traceAcquire and traceRelease across all P steals
e17dd1a 
Currently there are a few places where a P can get stolen where the
runtime doesn't traceAcquire and traceRelease across the steal itself.
What can happen then is the following scenario:
- Thread 1 enters a syscall and writes an event about it.
- Thread 2 steals Thread 1's P.
- Thread 1 exits the syscall and writes one or more events about it.
- Tracing ends (trace.gen is set to 0).
- Thread 2 checks to see if it should write an event for the P it just
  stole, sees that tracing is disabled, and doesn't.

This results in broken traces, because there's a missing ProcSteal
event. The parser always waits for a ProcSteal to advance a
GoSyscallEndBlocked event, and in this case, it never comes.

Fixes golang#65181.

Change-Id: I437629499bb7669bf7fe2fc6fc4f64c53002916b
Reviewed-on: https://go-review.googlesource.com/c/go/+/560235
Reviewed-by: Michael Pratt <[email protected]>
LUCI-TryBot-Result: Go LUCI <[email protected]>
@gabyhelp gabyhelp mentioned this issue Jun 19, 2024
Open
@golang golang locked and limited conversation to collaborators Jan 31, 2025
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@mknyszek mknyszek

Labels
compiler/runtime Issues related to the Go compiler and/or runtime. FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
Test Flakes
Archived in project
Milestone
Backlog
Development

No branches or pull requests
3 participants
@mknyszek @bcmills @gopherbot