qbit/go
1
0
Fork 0
mirror of https://github.com/golang/go synced 2024-09-28 20:14:28 -06:00
Code Releases Activity

internal/trace/v2: resolve syscall parsing ambiguity

Browse Source 
After landing the new execution tracer, the Windows builders failed with
some new errors.

Currently the GoSyscallBegin event has no indicator that its the target
of a ProcSteal event. This can lead to an ambiguous situation that is
unresolvable if timestamps are broken. For instance, if the tracer sees
the ProcSteal event while a goroutine has been observed to be in a
syscall (one that, for instance, did not actually lose its P), it will
proceed with the ProcSteal incorrectly.

This is a little abstract. For a more concrete example, see the
go122-syscall-steal-proc-ambiguous test.

This change resolves this ambiguity by interleaving GoSyscallBegin
events into how Ps are sequenced. Because a ProcSteal has a sequence
number (it has to, it's stopping a P from a distance) it necessarily
has to synchronize with a precise ProcStart event. This change basically
just extends this synchronization to GoSyscallBegin, so the ProcSteal
can't advance until _exactly the right_ syscall has been entered.

This change removes the test skip, since it and CL 541695 fix the two
main issues observed on Windows platforms.

For #60773.
Fixes #64061.

Change-Id: I069389cd7fe1ea903edf42d79912f6e2bcc23f62
Reviewed-on: https://go-review.googlesource.com/c/go/+/541696
Auto-Submit: Michael Knyszek <mknyszek@google.com>
Reviewed-by: Michael Pratt <mpratt@google.com>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
This commit is contained in:
Michael Anthony Knyszek 2023-11-10 22:46:47 +00:00 committed by Gopher Robot
parent 859c13a5ad
commit c06beb9eff
19 changed files with 4393 additions and 2518 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

5
src/internal/trace/goroutinesv2_test.go
View File

@ -211,8 +211,9 @@ func TestRelatedGoroutinesV2Trace(t *testing.T) {
}
want := map[tracev2.GoID]struct{}{
tracev2.GoID(86): struct{}{}, // N.B. Result includes target.
tracev2.GoID(85): struct{}{},
tracev2.GoID(111): struct{}{},
tracev2.GoID(71): struct{}{},
tracev2.GoID(25): struct{}{},
tracev2.GoID(122): struct{}{},
}
for goid := range got {
if _, ok := want[goid]; ok {

6
src/internal/trace/v2/event/go122/event.go
View File

@ -38,7 +38,7 @@ const (
EvGoStop // goroutine yields its time, but is runnable [timestamp, reason, stack ID]
EvGoBlock // goroutine blocks [timestamp, reason, stack ID]
EvGoUnblock // goroutine is unblocked [timestamp, goroutine ID, goroutine seq, stack ID]
EvGoSyscallBegin // syscall enter [timestamp, stack ID]
EvGoSyscallBegin // syscall enter [timestamp, P seq, stack ID]
EvGoSyscallEnd // syscall exit [timestamp]
EvGoSyscallEndBlocked // syscall exit and it blocked at some point [timestamp]
EvGoStatus // goroutine status at the start of a generation [timestamp, goroutine ID, status]
@ -193,9 +193,9 @@ var specs = [...]event.Spec{
},
EvGoSyscallBegin: event.Spec{
Name: "GoSyscallBegin",
Args: []string{"dt", "stack"},
Args: []string{"dt", "p_seq", "stack"},
IsTimedEvent: true,
StackIDs: []int{1},
StackIDs: []int{2},
},
EvGoSyscallEnd: event.Spec{
Name: "GoSyscallEnd",

32
src/internal/trace/v2/internal/testgen/go122/trace.go
View File

@ -50,11 +50,12 @@ func Main(f func(*Trace)) {
// Otherwise, it performs no validation on the trace at all.
type Trace struct {
// Trace data state.
ver version.Version
names map[string]event.Type
specs []event.Spec
events []raw.Event
gens []*Generation
ver version.Version
names map[string]event.Type
specs []event.Spec
events []raw.Event
gens []*Generation
validTimestamps bool
// Expectation state.
bad bool
@ -65,8 +66,9 @@ type Trace struct {
func NewTrace() *Trace {
ver := version.Go122
return &Trace{
names: event.Names(ver.Specs()),
specs: ver.Specs(),
names: event.Names(ver.Specs()),
specs: ver.Specs(),
validTimestamps: true,
}
}
@ -89,6 +91,13 @@ func (t *Trace) RawEvent(typ event.Type, data []byte, args ...uint64) {
t.events = append(t.events, t.createEvent(typ, data, args...))
}
// DisableTimestamps makes the timestamps for all events generated after
// this call zero. Raw events are exempted from this because the caller
// has to pass their own timestamp into those events anyway.
func (t *Trace) DisableTimestamps() {
t.validTimestamps = false
}
// Generation creates a new trace generation.
//
// This provides more structure than Event to allow for more easily
@ -180,6 +189,9 @@ type Generation struct {
//
// This is convenience function for generating correct batches.
func (g *Generation) Batch(thread trace.ThreadID, time Time) *Batch {
if !g.trace.validTimestamps {
time = 0
}
b := &Batch{
gen: g,
thread: thread,
@ -297,7 +309,11 @@ func (b *Batch) Event(name string, args ...any) {
var uintArgs []uint64
argOff := 0
if b.gen.trace.specs[ev].IsTimedEvent {
uintArgs = []uint64{1}
if b.gen.trace.validTimestamps {
uintArgs = []uint64{1}
} else {
uintArgs = []uint64{0}
}
argOff = 1
}
spec := b.gen.trace.specs[ev]

47
src/internal/trace/v2/order.go
View File

@ -306,7 +306,7 @@ func (o *ordering) advance(ev *baseEvent, evt *evTable, m ThreadID, gen uint64)
}
o.gStates[newgid] = &gState{id: newgid, status: go122.GoRunnable, seq: makeSeq(gen, 0)}
return curCtx, true, nil
case go122.EvGoDestroy, go122.EvGoStop, go122.EvGoBlock, go122.EvGoSyscallBegin:
case go122.EvGoDestroy, go122.EvGoStop, go122.EvGoBlock:
// These are goroutine events that all require an active running
// goroutine on some thread. They must *always* be advance-able,
// since running goroutines are bound to their M.
@ -335,14 +335,6 @@ func (o *ordering) advance(ev *baseEvent, evt *evTable, m ThreadID, gen uint64)
// Goroutine blocked. It's waiting now and not running on this M.
state.status = go122.GoWaiting
newCtx.G = NoGoroutine
case go122.EvGoSyscallBegin:
// Goroutine entered a syscall. It's still running on this P and M.
state.status = go122.GoSyscall
pState, ok := o.pStates[curCtx.P]
if !ok {
return curCtx, false, fmt.Errorf("uninitialized proc %d found during %s", curCtx.P, go122.EventString(typ))
}
pState.status = go122.ProcSyscall
}
return curCtx, true, nil
case go122.EvGoStart:
@ -380,6 +372,43 @@ func (o *ordering) advance(ev *baseEvent, evt *evTable, m ThreadID, gen uint64)
// N.B. No context to validate. Basically anything can unblock
// a goroutine (e.g. sysmon).
return curCtx, true, nil
case go122.EvGoSyscallBegin:
// Entering a syscall requires an active running goroutine with a
// proc on some thread. It is always advancable.
if err := validateCtx(curCtx, event.UserGoReqs); err != nil {
return curCtx, false, err
}
state, ok := o.gStates[curCtx.G]
if !ok {
return curCtx, false, fmt.Errorf("event %s for goroutine (%v) that doesn't exist", go122.EventString(typ), curCtx.G)
}
if state.status != go122.GoRunning {
return curCtx, false, fmt.Errorf("%s event for goroutine that's not %s", go122.EventString(typ), GoRunning)
}
// Goroutine entered a syscall. It's still running on this P and M.
state.status = go122.GoSyscall
pState, ok := o.pStates[curCtx.P]
if !ok {
return curCtx, false, fmt.Errorf("uninitialized proc %d found during %s", curCtx.P, go122.EventString(typ))
}
pState.status = go122.ProcSyscall
// Validate the P sequence number on the event and advance it.
//
// We have a P sequence number for what is supposed to be a goroutine event
// so that we can correctly model P stealing. Without this sequence number here,
// the syscall from which a ProcSteal event is stealing can be ambiguous in the
// face of broken timestamps. See the go122-syscall-steal-proc-ambiguous test for
// more details.
//
// Note that because this sequence number only exists as a tool for disambiguation,
// we can enforce that we have the right sequence number at this point; we don't need
// to back off and see if any other events will advance. This is a running P.
pSeq := makeSeq(gen, ev.args[0])
if !pSeq.succeeds(pState.seq) {
return curCtx, false, fmt.Errorf("failed to advance %s: can't make sequence: %s -> %s", go122.EventString(typ), pState.seq, pSeq)
}
pState.seq = pSeq
return curCtx, true, nil
case go122.EvGoSyscallEnd:
// This event is always advance-able because it happens on the same
// thread that EvGoSyscallStart happened, and the goroutine can't leave

46
src/internal/trace/v2/testdata/generators/go122-syscall-steal-proc-ambiguous.go vendored Normal file
View File

@ -0,0 +1,46 @@
// Copyright 2023 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
// Tests syscall P stealing.
//
// Specifically, it tests a scenerio wherein, without a
// P sequence number of GoSyscallBegin, the syscall that
// a ProcSteal applies to is ambiguous. This only happens in
// practice when the events aren't already properly ordered
// by timestamp, since the ProcSteal won't be seen until after
// the correct GoSyscallBegin appears on the frontier.
package main
import (
"internal/trace/v2"
"internal/trace/v2/event/go122"
testgen "internal/trace/v2/internal/testgen/go122"
)
func main() {
testgen.Main(gen)
}
func gen(t *testgen.Trace) {
t.DisableTimestamps()
g := t.Generation(1)
// One goroutine does a syscall without blocking, then another one where
// it's P gets stolen.
b0 := g.Batch(trace.ThreadID(0), 0)
b0.Event("ProcStatus", trace.ProcID(0), go122.ProcRunning)
b0.Event("GoStatus", trace.GoID(1), trace.ThreadID(0), go122.GoRunning)
b0.Event("GoSyscallBegin", testgen.Seq(1), testgen.NoStack)
b0.Event("GoSyscallEnd")
b0.Event("GoSyscallBegin", testgen.Seq(2), testgen.NoStack)
b0.Event("GoSyscallEndBlocked")
// A running goroutine steals proc 0.
b1 := g.Batch(trace.ThreadID(1), 0)
b1.Event("ProcStatus", trace.ProcID(2), go122.ProcRunning)
b1.Event("GoStatus", trace.GoID(2), trace.ThreadID(1), go122.GoRunning)
b1.Event("ProcSteal", trace.ProcID(0), testgen.Seq(3), trace.ThreadID(0))
}

4
src/internal/trace/v2/testdata/generators/go122-syscall-steal-proc-reacquire-new-proc-bare-m.go vendored
View File

@ -24,11 +24,11 @@ func gen(t *testgen.Trace) {
b0.Event("ProcStatus", trace.ProcID(1), go122.ProcIdle)
b0.Event("ProcStatus", trace.ProcID(0), go122.ProcRunning)
b0.Event("GoStatus", trace.GoID(1), trace.ThreadID(0), go122.GoRunning)
b0.Event("GoSyscallBegin", testgen.NoStack)
b0.Event("GoSyscallBegin", testgen.Seq(1), testgen.NoStack)
b0.Event("ProcStart", trace.ProcID(1), testgen.Seq(1))
b0.Event("GoSyscallEndBlocked")
// A bare M steals the goroutine's P.
b1 := g.Batch(trace.ThreadID(1), 0)
b1.Event("ProcSteal", trace.ProcID(0), testgen.Seq(1), trace.ThreadID(0))
b1.Event("ProcSteal", trace.ProcID(0), testgen.Seq(2), trace.ThreadID(0))
}

4
src/internal/trace/v2/testdata/generators/go122-syscall-steal-proc-reacquire-new-proc.go vendored
View File

@ -24,7 +24,7 @@ func gen(t *testgen.Trace) {
b0.Event("ProcStatus", trace.ProcID(1), go122.ProcIdle)
b0.Event("ProcStatus", trace.ProcID(0), go122.ProcRunning)
b0.Event("GoStatus", trace.GoID(1), trace.ThreadID(0), go122.GoRunning)
b0.Event("GoSyscallBegin", testgen.NoStack)
b0.Event("GoSyscallBegin", testgen.Seq(1), testgen.NoStack)
b0.Event("ProcStart", trace.ProcID(1), testgen.Seq(1))
b0.Event("GoSyscallEndBlocked")
@ -32,5 +32,5 @@ func gen(t *testgen.Trace) {
b1 := g.Batch(trace.ThreadID(1), 0)
b1.Event("ProcStatus", trace.ProcID(2), go122.ProcRunning)
b1.Event("GoStatus", trace.GoID(2), trace.ThreadID(1), go122.GoRunning)
b1.Event("ProcSteal", trace.ProcID(0), testgen.Seq(1), trace.ThreadID(0))
b1.Event("ProcSteal", trace.ProcID(0), testgen.Seq(2), trace.ThreadID(0))
}

4
src/internal/trace/v2/testdata/generators/go122-syscall-steal-proc-simple-bare-m.go vendored
View File

@ -23,10 +23,10 @@ func gen(t *testgen.Trace) {
b0 := g.Batch(trace.ThreadID(0), 0)
b0.Event("ProcStatus", trace.ProcID(0), go122.ProcRunning)
b0.Event("GoStatus", trace.GoID(1), trace.ThreadID(0), go122.GoRunning)
b0.Event("GoSyscallBegin", testgen.NoStack)
b0.Event("GoSyscallBegin", testgen.Seq(1), testgen.NoStack)
b0.Event("GoSyscallEndBlocked")
// A bare M steals the goroutine's P.
b1 := g.Batch(trace.ThreadID(1), 0)
b1.Event("ProcSteal", trace.ProcID(0), testgen.Seq(1), trace.ThreadID(0))
b1.Event("ProcSteal", trace.ProcID(0), testgen.Seq(2), trace.ThreadID(0))
}

4
src/internal/trace/v2/testdata/generators/go122-syscall-steal-proc-simple.go vendored
View File

@ -23,12 +23,12 @@ func gen(t *testgen.Trace) {
b0 := g.Batch(trace.ThreadID(0), 0)
b0.Event("ProcStatus", trace.ProcID(0), go122.ProcRunning)
b0.Event("GoStatus", trace.GoID(1), trace.ThreadID(0), go122.GoRunning)
b0.Event("GoSyscallBegin", testgen.NoStack)
b0.Event("GoSyscallBegin", testgen.Seq(1), testgen.NoStack)
b0.Event("GoSyscallEndBlocked")
// A running goroutine steals proc 0.
b1 := g.Batch(trace.ThreadID(1), 0)
b1.Event("ProcStatus", trace.ProcID(2), go122.ProcRunning)
b1.Event("GoStatus", trace.GoID(2), trace.ThreadID(1), go122.GoRunning)
b1.Event("ProcSteal", trace.ProcID(0), testgen.Seq(1), trace.ThreadID(0))
b1.Event("ProcSteal", trace.ProcID(0), testgen.Seq(2), trace.ThreadID(0))
}

346
src/internal/trace/v2/testdata/tests/go122-annotations.test vendored
View File

@ -2,30 +2,28 @@
SUCCESS
-- trace --
Trace Go1.22
EventBatch gen=1 m=18446744073709551615 time=23991883811065 size=5
EventBatch gen=1 m=18446744073709551615 time=28113086279559 size=5
Frequency freq=15625000
EventBatch gen=1 m=1331278 time=23991883808413 size=16
ProcStart dt=297 p=2 p_seq=1
GoStart dt=162 g=7 g_seq=1
HeapAlloc dt=267 heapalloc_value=1908736
EventBatch gen=1 m=1331277 time=23991883807353 size=28
ProcStart dt=472 p=1 p_seq=1
GoStart dt=309 g=6 g_seq=1
HeapAlloc dt=533 heapalloc_value=1892352
HeapAlloc dt=47 heapalloc_value=1900544
GoBlock dt=2071 reason_string=12 stack=23
ProcStop dt=54
EventBatch gen=1 m=1331276 time=23991883809162 size=10
ProcStart dt=426 p=3 p_seq=1
HeapAlloc dt=108 heapalloc_value=1916928
EventBatch gen=1 m=1331274 time=23991883805418 size=325
ProcStatus dt=241 p=0 pstatus=1
GoStatus dt=5 g=1 m=1331274 gstatus=2
ProcsChange dt=486 procs_value=48 stack=1
STWBegin dt=80 kind_string=21 stack=2
HeapGoal dt=3 heapgoal_value=4194304
ProcStatus dt=3 p=1 pstatus=2
ProcStatus dt=2 p=2 pstatus=2
EventBatch gen=1 m=167930 time=28113086277797 size=41
ProcStart dt=505 p=1 p_seq=1
GoStart dt=303 g=7 g_seq=1
HeapAlloc dt=646 heapalloc_value=1892352
HeapAlloc dt=149 heapalloc_value=1900544
GoBlock dt=146 reason_string=12 stack=24
GoStart dt=14 g=6 g_seq=1
HeapAlloc dt=16 heapalloc_value=1908736
GoBlock dt=347 reason_string=12 stack=25
EventBatch gen=1 m=167928 time=28113086279032 size=10
ProcStart dt=451 p=2 p_seq=1
GoStart dt=188 g=8 g_seq=1
EventBatch gen=1 m=167926 time=28113086275999 size=324
ProcStatus dt=295 p=0 pstatus=1
GoStatus dt=5 g=1 m=167926 gstatus=2
ProcsChange dt=405 procs_value=48 stack=1
STWBegin dt=65 kind_string=21 stack=2
HeapGoal dt=2 heapgoal_value=4194304
ProcStatus dt=4 p=1 pstatus=2
ProcStatus dt=1 p=2 pstatus=2
ProcStatus dt=1 p=3 pstatus=2
ProcStatus dt=1 p=4 pstatus=2
ProcStatus dt=1 p=5 pstatus=2
@ -71,113 +69,117 @@ ProcStatus dt=1 p=44 pstatus=2
ProcStatus dt=1 p=45 pstatus=2
ProcStatus dt=1 p=46 pstatus=2
ProcStatus dt=1 p=47 pstatus=2
ProcsChange dt=9 procs_value=48 stack=3
STWEnd dt=209
GoCreate dt=376 new_g=6 new_stack=4 stack=5
GoCreate dt=96 new_g=7 new_stack=6 stack=7
GoCreate dt=574 new_g=8 new_stack=8 stack=9
UserTaskBegin dt=19 task=1 parent_task=0 name_string=22 stack=10
UserRegionBegin dt=19 task=1 name_string=23 stack=11
HeapAlloc dt=27 heapalloc_value=1884160
GoCreate dt=578 new_g=9 new_stack=12 stack=13
GoBlock dt=67 reason_string=10 stack=14
GoStart dt=13 g=9 g_seq=1
UserRegionBegin dt=61 task=1 name_string=24 stack=15
UserRegionBegin dt=8 task=1 name_string=25 stack=16
ProcsChange dt=1 procs_value=48 stack=3
STWEnd dt=184
GoCreate dt=252 new_g=6 new_stack=4 stack=5
GoCreate dt=78 new_g=7 new_stack=6 stack=7
GoCreate dt=73 new_g=8 new_stack=8 stack=9
UserTaskBegin dt=71 task=1 parent_task=0 name_string=22 stack=10
UserRegionBegin dt=535 task=1 name_string=23 stack=11
HeapAlloc dt=26 heapalloc_value=1884160
GoCreate dt=8 new_g=9 new_stack=12 stack=13
GoBlock dt=249 reason_string=10 stack=14
GoStart dt=8 g=9 g_seq=1
UserRegionBegin dt=286 task=1 name_string=24 stack=15
UserRegionBegin dt=244 task=1 name_string=25 stack=16
UserRegionBegin dt=6 task=1 name_string=26 stack=17
UserLog dt=780 task=1 key_string=27 value_string=28 stack=18
UserRegionEnd dt=9 task=1 name_string=26 stack=19
UserRegionEnd dt=504 task=1 name_string=25 stack=20
UserTaskEnd dt=425 task=1 stack=21
GoUnblock dt=503 g=1 g_seq=1 stack=22
GoDestroy dt=7
GoStart dt=13 g=1 g_seq=2
UserRegionBegin dt=367 task=0 name_string=29 stack=24
EventBatch gen=1 m=18446744073709551615 time=23991883811600 size=57
GoStatus dt=358 g=2 m=18446744073709551615 gstatus=4
UserLog dt=6 task=1 key_string=27 value_string=28 stack=18
UserRegionEnd dt=4 task=1 name_string=26 stack=19
UserRegionEnd dt=315 task=1 name_string=25 stack=20
UserTaskEnd dt=5 task=1 stack=21
GoUnblock dt=11 g=1 g_seq=1 stack=22
GoDestroy dt=6
GoStart dt=10 g=1 g_seq=2
UserRegionBegin dt=278 task=0 name_string=29 stack=23
EventBatch gen=1 m=18446744073709551615 time=28113086280061 size=57
GoStatus dt=318 g=2 m=18446744073709551615 gstatus=4
GoStatus dt=3 g=3 m=18446744073709551615 gstatus=4
GoStatus dt=2 g=4 m=18446744073709551615 gstatus=4
GoStatus dt=1 g=4 m=18446744073709551615 gstatus=4
GoStatus dt=1 g=5 m=18446744073709551615 gstatus=4
EventBatch gen=1 m=18446744073709551615 time=23991883812197 size=461
EventBatch gen=1 m=18446744073709551615 time=28113086280852 size=488
Stacks
Stack id=8 nframes=1
pc=4812576 func=30 file=31 line=128
Stack id=13 nframes=1
pc=4813540 func=32 file=33 line=37
Stack id=3 nframes=4
pc=4421156 func=34 file=35 line=1360
pc=4537289 func=36 file=37 line=246
pc=4812325 func=38 file=31 line=125
pc=4813276 func=32 file=33 line=27
Stack id=2 nframes=3
pc=4537037 func=36 file=37 line=229
pc=4812325 func=38 file=31 line=125
pc=4813276 func=32 file=33 line=27
Stack id=16 nframes=1
pc=4813956 func=39 file=33 line=43
Stack id=19 nframes=3
pc=4814128 func=40 file=33 line=45
pc=4811708 func=41 file=42 line=141
pc=4813956 func=39 file=33 line=43
Stack id=10 nframes=1
pc=4813380 func=32 file=33 line=33
Stack id=1 nframes=4
pc=4551915 func=43 file=44 line=248
pc=4537017 func=36 file=37 line=228
pc=4812325 func=38 file=31 line=125
pc=4813276 func=32 file=33 line=27
Stack id=7 nframes=4
pc=4543253 func=45 file=37 line=831
pc=4537306 func=36 file=37 line=249
pc=4812325 func=38 file=31 line=125
pc=4813276 func=32 file=33 line=27
Stack id=11 nframes=1
pc=4813412 func=32 file=33 line=34
Stack id=4 nframes=1
pc=4545952 func=46 file=47 line=42
Stack id=5 nframes=4
pc=4545861 func=48 file=47 line=42
pc=4537294 func=36 file=37 line=248
pc=4812325 func=38 file=31 line=125
pc=4813276 func=32 file=33 line=27
Stack id=17 nframes=3
pc=4814128 func=40 file=33 line=45
pc=4811708 func=41 file=42 line=141
pc=4813956 func=39 file=33 line=43
Stack id=24 nframes=1
pc=4813616 func=32 file=33 line=54
Stack id=21 nframes=2
pc=4814276 func=49 file=42 line=80
pc=4813974 func=39 file=33 line=50
Stack id=12 nframes=1
pc=4813728 func=39 file=33 line=37
Stack id=14 nframes=2
pc=4640519 func=50 file=51 line=116
pc=4813550 func=32 file=33 line=51
pc=4816080 func=30 file=31 line=45
pc=4813660 func=32 file=33 line=141
pc=4815908 func=34 file=31 line=43
Stack id=8 nframes=1
pc=4814528 func=35 file=36 line=128
Stack id=9 nframes=2
pc=4812399 func=38 file=31 line=128
pc=4813276 func=32 file=33 line=27
pc=4814351 func=37 file=36 line=128
pc=4815228 func=38 file=31 line=27
Stack id=24 nframes=3
pc=4217457 func=39 file=40 line=442
pc=4544973 func=41 file=42 line=918
pc=4544806 func=43 file=42 line=871
Stack id=7 nframes=4
pc=4544740 func=44 file=42 line=868
pc=4538792 func=45 file=42 line=258
pc=4814277 func=37 file=36 line=125
pc=4815228 func=38 file=31 line=27
Stack id=22 nframes=3
pc=4640260 func=52 file=51 line=81
pc=4814374 func=53 file=51 line=87
pc=4813989 func=39 file=33 line=50
Stack id=20 nframes=1
pc=4813956 func=39 file=33 line=43
pc=4642148 func=46 file=47 line=81
pc=4816326 func=48 file=47 line=87
pc=4815941 func=34 file=31 line=50
Stack id=11 nframes=1
pc=4815364 func=38 file=31 line=34
Stack id=5 nframes=4
pc=4547349 func=49 file=50 line=42
pc=4538780 func=45 file=42 line=257
pc=4814277 func=37 file=36 line=125
pc=4815228 func=38 file=31 line=27
Stack id=23 nframes=1
pc=4815568 func=38 file=31 line=54
Stack id=3 nframes=4
pc=4421860 func=51 file=52 line=1360
pc=4538775 func=45 file=42 line=255
pc=4814277 func=37 file=36 line=125
pc=4815228 func=38 file=31 line=27
Stack id=21 nframes=2
pc=4816228 func=53 file=33 line=80
pc=4815926 func=34 file=31 line=50
Stack id=1 nframes=4
pc=4553515 func=54 file=55 line=255
pc=4538503 func=45 file=42 line=237
pc=4814277 func=37 file=36 line=125
pc=4815228 func=38 file=31 line=27
Stack id=12 nframes=1
pc=4815680 func=34 file=31 line=37
Stack id=6 nframes=1
pc=4543296 func=54 file=37 line=831
Stack id=15 nframes=1
pc=4813886 func=39 file=33 line=41
pc=4544768 func=43 file=42 line=868
Stack id=2 nframes=3
pc=4538523 func=45 file=42 line=238
pc=4814277 func=37 file=36 line=125
pc=4815228 func=38 file=31 line=27
Stack id=13 nframes=1
pc=4815492 func=38 file=31 line=37
Stack id=4 nframes=1
pc=4547456 func=56 file=50 line=42
Stack id=14 nframes=2
pc=4642407 func=57 file=47 line=116
pc=4815502 func=38 file=31 line=51
Stack id=18 nframes=5
pc=4814195 func=55 file=33 line=46
pc=4811708 func=41 file=42 line=141
pc=4814128 func=40 file=33 line=45
pc=4811708 func=41 file=42 line=141
pc=4813956 func=39 file=33 line=43
Stack id=23 nframes=3
pc=4217457 func=56 file=57 line=442
pc=4543501 func=58 file=37 line=881
pc=4546010 func=46 file=47 line=54
EventBatch gen=1 m=18446744073709551615 time=23991883804190 size=1620
pc=4816147 func=58 file=31 line=46
pc=4813660 func=32 file=33 line=141
pc=4816080 func=30 file=31 line=45
pc=4813660 func=32 file=33 line=141
pc=4815908 func=34 file=31 line=43
Stack id=20 nframes=1
pc=4815908 func=34 file=31 line=43
Stack id=25 nframes=3
pc=4217457 func=39 file=40 line=442
pc=4544973 func=41 file=42 line=918
pc=4547514 func=56 file=50 line=54
Stack id=16 nframes=1
pc=4815908 func=34 file=31 line=43
Stack id=15 nframes=1
pc=4815838 func=34 file=31 line=41
Stack id=19 nframes=3
pc=4816080 func=30 file=31 line=45
pc=4813660 func=32 file=33 line=141
pc=4815908 func=34 file=31 line=43
Stack id=10 nframes=1
pc=4815332 func=38 file=31 line=33
EventBatch gen=1 m=18446744073709551615 time=28113086274600 size=1620
Strings
String id=1
data="Not worker"
@ -238,60 +240,60 @@ String id=28
String id=29
data="post-existing region"
String id=30
data="runtime/trace.Start.func1"
String id=31
data="/usr/local/google/home/mknyszek/work/go-1/src/runtime/trace/trace.go"
String id=32
data="main.main"
String id=33
data="/usr/local/google/home/mknyszek/work/go-1/src/internal/trace/v2/testdata/testprog/annotations.go"
String id=34
data="runtime.startTheWorld"
String id=35
data="/usr/local/google/home/mknyszek/work/go-1/src/runtime/proc.go"
String id=36
data="runtime.StartTrace"
String id=37
data="/usr/local/google/home/mknyszek/work/go-1/src/runtime/trace2.go"
String id=38
data="runtime/trace.Start"
String id=39
data="main.main.func1"
String id=40
data="main.main.func1.1"
String id=41
String id=31
data="/usr/local/google/home/mknyszek/work/go-1/src/internal/trace/v2/testdata/testprog/annotations.go"
String id=32
data="runtime/trace.WithRegion"
String id=42
String id=33
data="/usr/local/google/home/mknyszek/work/go-1/src/runtime/trace/annotation.go"
String id=43
data="runtime.traceLocker.Gomaxprocs"
String id=44
data="/usr/local/google/home/mknyszek/work/go-1/src/runtime/trace2runtime.go"
String id=45
data="runtime.(*traceAdvancerState).start"
String id=46
data="runtime.traceStartReadCPU.func1"
String id=47
data="/usr/local/google/home/mknyszek/work/go-1/src/runtime/trace2cpu.go"
String id=48
data="runtime.traceStartReadCPU"
String id=49
data="runtime/trace.(*Task).End"
String id=50
data="sync.(*WaitGroup).Wait"
String id=51
data="/usr/local/google/home/mknyszek/work/go-1/src/sync/waitgroup.go"
String id=52
data="sync.(*WaitGroup).Add"
String id=53
data="sync.(*WaitGroup).Done"
String id=54
data="runtime.(*traceAdvancerState).start.func1"
String id=55
data="main.main.func1.1.1"
String id=56
String id=34
data="main.main.func1"
String id=35
data="runtime/trace.Start.func1"
String id=36
data="/usr/local/google/home/mknyszek/work/go-1/src/runtime/trace/trace.go"
String id=37
data="runtime/trace.Start"
String id=38
data="main.main"
String id=39
data="runtime.chanrecv1"
String id=57
String id=40
data="/usr/local/google/home/mknyszek/work/go-1/src/runtime/chan.go"
String id=58
String id=41
data="runtime.(*wakeableSleep).sleep"
String id=42
data="/usr/local/google/home/mknyszek/work/go-1/src/runtime/trace2.go"
String id=43
data="runtime.(*traceAdvancerState).start.func1"
String id=44
data="runtime.(*traceAdvancerState).start"
String id=45
data="runtime.StartTrace"
String id=46
data="sync.(*WaitGroup).Add"
String id=47
data="/usr/local/google/home/mknyszek/work/go-1/src/sync/waitgroup.go"
String id=48
data="sync.(*WaitGroup).Done"
String id=49
data="runtime.traceStartReadCPU"
String id=50
data="/usr/local/google/home/mknyszek/work/go-1/src/runtime/trace2cpu.go"
String id=51
data="runtime.startTheWorld"
String id=52
data="/usr/local/google/home/mknyszek/work/go-1/src/runtime/proc.go"
String id=53
data="runtime/trace.(*Task).End"
String id=54
data="runtime.traceLocker.Gomaxprocs"
String id=55
data="/usr/local/google/home/mknyszek/work/go-1/src/runtime/trace2runtime.go"
String id=56
data="runtime.traceStartReadCPU.func1"
String id=57
data="sync.(*WaitGroup).Wait"
String id=58
data="main.main.func1.1.1"

6357
src/internal/trace/v2/testdata/tests/go122-gc-stress.test vendored
View File

File diff suppressed because it is too large Load Diff

21
src/internal/trace/v2/testdata/tests/go122-syscall-steal-proc-ambiguous.test vendored Normal file
View File

@ -0,0 +1,21 @@
-- expect --
SUCCESS
-- trace --
Trace Go1.22
EventBatch gen=1 m=0 time=0 size=21
ProcStatus dt=0 p=0 pstatus=1
GoStatus dt=0 g=1 m=0 gstatus=2
GoSyscallBegin dt=0 p_seq=1 stack=0
GoSyscallEnd dt=0
GoSyscallBegin dt=0 p_seq=2 stack=0
GoSyscallEndBlocked dt=0
EventBatch gen=1 m=1 time=0 size=14
ProcStatus dt=0 p=2 pstatus=1
GoStatus dt=0 g=2 m=1 gstatus=2
ProcSteal dt=0 p=0 p_seq=3 m=0
EventBatch gen=1 m=18446744073709551615 time=0 size=5
Frequency freq=15625000
EventBatch gen=1 m=18446744073709551615 time=0 size=1
Stacks
EventBatch gen=1 m=18446744073709551615 time=0 size=1
Strings

6
src/internal/trace/v2/testdata/tests/go122-syscall-steal-proc-reacquire-new-proc-bare-m.test vendored
View File

@ -2,15 +2,15 @@
SUCCESS
-- trace --
Trace Go1.22
EventBatch gen=1 m=0 time=0 size=22
EventBatch gen=1 m=0 time=0 size=23
ProcStatus dt=1 p=1 pstatus=2
ProcStatus dt=1 p=0 pstatus=1
GoStatus dt=1 g=1 m=0 gstatus=2
GoSyscallBegin dt=1 stack=0
GoSyscallBegin dt=1 p_seq=1 stack=0
ProcStart dt=1 p=1 p_seq=1
GoSyscallEndBlocked dt=1
EventBatch gen=1 m=1 time=0 size=5
ProcSteal dt=1 p=0 p_seq=1 m=0
ProcSteal dt=1 p=0 p_seq=2 m=0
EventBatch gen=1 m=18446744073709551615 time=0 size=5
Frequency freq=15625000
EventBatch gen=1 m=18446744073709551615 time=0 size=1

6
src/internal/trace/v2/testdata/tests/go122-syscall-steal-proc-reacquire-new-proc.test vendored
View File

@ -2,17 +2,17 @@
SUCCESS
-- trace --
Trace Go1.22
EventBatch gen=1 m=0 time=0 size=22
EventBatch gen=1 m=0 time=0 size=23
ProcStatus dt=1 p=1 pstatus=2
ProcStatus dt=1 p=0 pstatus=1
GoStatus dt=1 g=1 m=0 gstatus=2
GoSyscallBegin dt=1 stack=0
GoSyscallBegin dt=1 p_seq=1 stack=0
ProcStart dt=1 p=1 p_seq=1
GoSyscallEndBlocked dt=1
EventBatch gen=1 m=1 time=0 size=14
ProcStatus dt=1 p=2 pstatus=1
GoStatus dt=1 g=2 m=1 gstatus=2
ProcSteal dt=1 p=0 p_seq=1 m=0
ProcSteal dt=1 p=0 p_seq=2 m=0
EventBatch gen=1 m=18446744073709551615 time=0 size=5
Frequency freq=15625000
EventBatch gen=1 m=18446744073709551615 time=0 size=1

6
src/internal/trace/v2/testdata/tests/go122-syscall-steal-proc-simple-bare-m.test vendored
View File

@ -2,13 +2,13 @@
SUCCESS
-- trace --
Trace Go1.22
EventBatch gen=1 m=0 time=0 size=14
EventBatch gen=1 m=0 time=0 size=15
ProcStatus dt=1 p=0 pstatus=1
GoStatus dt=1 g=1 m=0 gstatus=2
GoSyscallBegin dt=1 stack=0
GoSyscallBegin dt=1 p_seq=1 stack=0
GoSyscallEndBlocked dt=1
EventBatch gen=1 m=1 time=0 size=5
ProcSteal dt=1 p=0 p_seq=1 m=0
ProcSteal dt=1 p=0 p_seq=2 m=0
EventBatch gen=1 m=18446744073709551615 time=0 size=5
Frequency freq=15625000
EventBatch gen=1 m=18446744073709551615 time=0 size=1

6
src/internal/trace/v2/testdata/tests/go122-syscall-steal-proc-simple.test vendored
View File

@ -2,15 +2,15 @@
SUCCESS
-- trace --
Trace Go1.22
EventBatch gen=1 m=0 time=0 size=14
EventBatch gen=1 m=0 time=0 size=15
ProcStatus dt=1 p=0 pstatus=1
GoStatus dt=1 g=1 m=0 gstatus=2
GoSyscallBegin dt=1 stack=0
GoSyscallBegin dt=1 p_seq=1 stack=0
GoSyscallEndBlocked dt=1
EventBatch gen=1 m=1 time=0 size=14
ProcStatus dt=1 p=2 pstatus=1
GoStatus dt=1 g=2 m=1 gstatus=2
ProcSteal dt=1 p=0 p_seq=1 m=0
ProcSteal dt=1 p=0 p_seq=2 m=0
EventBatch gen=1 m=18446744073709551615 time=0 size=5
Frequency freq=15625000
EventBatch gen=1 m=18446744073709551615 time=0 size=1

4
src/internal/trace/v2/trace_test.go
View File

@ -524,10 +524,6 @@ func TestTraceManyStartStop(t *testing.T) {
func testTraceProg(t *testing.T, progName string, extra func(t *testing.T, trace, stderr []byte, stress bool)) {
testenv.MustHaveGoRun(t)
if runtime.GOOS == "windows" {
t.Skip("temporarily disabled on Windows for #64061")
}
// Check if we're on a builder.
onBuilder := testenv.Builder() != ""

2
src/runtime/trace2event.go
View File

@ -52,7 +52,7 @@ const (
traceEvGoStop // goroutine yields its time, but is runnable [timestamp, reason, stack ID]
traceEvGoBlock // goroutine blocks [timestamp, reason, stack ID]
traceEvGoUnblock // goroutine is unblocked [timestamp, goroutine ID, goroutine seq, stack ID]
traceEvGoSyscallBegin // syscall enter [timestamp, stack ID]
traceEvGoSyscallBegin // syscall enter [timestamp, P seq, stack ID]
traceEvGoSyscallEnd // syscall exit [timestamp]
traceEvGoSyscallEndBlocked // syscall exit and it blocked at some point [timestamp]
traceEvGoStatus // goroutine status at the start of a generation [timestamp, goroutine ID, M ID, status]

5
src/runtime/trace2runtime.go
View File

@ -465,8 +465,9 @@ func (tl traceLocker) GoSysCall() {
skip = 4
}
// Scribble down the M that the P is currently attached to.
tl.mp.p.ptr().trace.mSyscallID = int64(tl.mp.procid)
tl.eventWriter(traceGoRunning, traceProcRunning).commit(traceEvGoSyscallBegin, tl.stack(skip))
pp := tl.mp.p.ptr()
pp.trace.mSyscallID = int64(tl.mp.procid)
tl.eventWriter(traceGoRunning, traceProcRunning).commit(traceEvGoSyscallBegin, pp.trace.nextSeq(tl.gen), tl.stack(skip))
}
// GoSysExit emits a GoSyscallEnd event, possibly along with a GoSyscallBlocked event