func (task *taskDesc) overlappingGCDuration(evs []*trace.Event) (overlapping time.Duration) {
for _, ev := range evs {
// make sure we only consider the global GC events.
- if typ := ev.Type; typ != trace.EvGCStart && typ != trace.EvGCSTWStart {
+ if typ := ev.Type; typ != trace.EvGCStart {
continue
}
case trace.EvGCStart:
ctx.emitSlice(ev, "GC")
case trace.EvGCDone:
- case trace.EvGCSTWStart:
+ case trace.EvSTWStart:
if ctx.mode&modeGoroutineOriented != 0 {
continue
}
ctx.emitSlice(ev, fmt.Sprintf("STW (%s)", ev.SArgs[0]))
- case trace.EvGCSTWDone:
+ case trace.EvSTWDone:
case trace.EvGCMarkAssistStart:
// Mark assists can continue past preemptions, so truncate to the
// whichever comes first. We'll synthesize another slice if
const (
// UtilSTW means utilization should account for STW events.
+ // This includes non-GC STW events, which are typically user-requested.
UtilSTW UtilFlags = 1 << iota
// UtilBackground means utilization should account for
// background mark workers.
}
ps = append(ps, perP{series: series})
}
- case EvGCSTWStart:
+ case EvSTWStart:
if flags&UtilSTW != 0 {
stw++
}
- case EvGCSTWDone:
+ case EvSTWDone:
if flags&UtilSTW != 0 {
stw--
}
return
}
switch ver {
- case 1005, 1007, 1008, 1009, 1010, 1011, 1019:
+ case 1005, 1007, 1008, 1009, 1010, 1011, 1019, 1021:
// Note: When adding a new version, confirm that canned traces from the
// old version are part of the test suite. Add them using mkcanned.bash.
break
if raw.typ == EvGoStartLabel {
e.SArgs = []string{strings[e.Args[2]]}
}
- case EvGCSTWStart:
+ case EvSTWStart:
e.G = 0
- switch e.Args[0] {
- case 0:
- e.SArgs = []string{"mark termination"}
- case 1:
- e.SArgs = []string{"sweep termination"}
- default:
- err = fmt.Errorf("unknown STW kind %d", e.Args[0])
- return
+ if ver < 1021 {
+ switch e.Args[0] {
+ case 0:
+ e.SArgs = []string{"mark termination"}
+ case 1:
+ e.SArgs = []string{"sweep termination"}
+ default:
+ err = fmt.Errorf("unknown STW kind %d", e.Args[0])
+ return
+ }
+ } else if ver == 1021 {
+ if kind := e.Args[0]; kind < uint64(len(stwReasonStringsGo121)) {
+ e.SArgs = []string{stwReasonStringsGo121[kind]}
+ } else {
+ e.SArgs = []string{"unknown"}
+ }
+ } else {
+ // Can't make any assumptions.
+ e.SArgs = []string{"unknown"}
}
- case EvGCStart, EvGCDone, EvGCSTWDone:
+ case EvGCStart, EvGCDone, EvSTWDone:
e.G = 0
case EvGoEnd, EvGoStop, EvGoSched, EvGoPreempt,
EvGoSleep, EvGoBlock, EvGoBlockSend, EvGoBlockRecv,
}
evGC.Link = ev
evGC = nil
- case EvGCSTWStart:
+ case EvSTWStart:
evp := &evSTW
if ver < 1010 {
- // Before 1.10, EvGCSTWStart was per-P.
+ // Before 1.10, EvSTWStart was per-P.
evp = &p.evSTW
}
if *evp != nil {
return fmt.Errorf("previous STW is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts)
}
*evp = ev
- case EvGCSTWDone:
+ case EvSTWDone:
evp := &evSTW
if ver < 1010 {
- // Before 1.10, EvGCSTWDone was per-P.
+ // Before 1.10, EvSTWDone was per-P.
evp = &p.evSTW
}
if *evp == nil {
if ver < 1007 {
narg-- // 1.7 added an additional seq arg
}
- case EvGCSTWStart:
+ case EvSTWStart:
if ver < 1010 {
narg-- // 1.10 added an argument
}
EvProcStop = 6 // stop of P [timestamp]
EvGCStart = 7 // GC start [timestamp, seq, stack id]
EvGCDone = 8 // GC done [timestamp]
- EvGCSTWStart = 9 // GC mark termination start [timestamp, kind]
- EvGCSTWDone = 10 // GC mark termination done [timestamp]
+ EvSTWStart = 9 // GC mark termination start [timestamp, kind]
+ EvSTWDone = 10 // GC mark termination done [timestamp]
EvGCSweepStart = 11 // GC sweep start [timestamp, stack id]
EvGCSweepDone = 12 // GC sweep done [timestamp, swept, reclaimed]
EvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, new stack id, stack id]
EvProcStop: {"ProcStop", 1005, false, []string{}, nil},
EvGCStart: {"GCStart", 1005, true, []string{"seq"}, nil}, // in 1.5 format it was {}
EvGCDone: {"GCDone", 1005, false, []string{}, nil},
- EvGCSTWStart: {"GCSTWStart", 1005, false, []string{"kindid"}, []string{"kind"}}, // <= 1.9, args was {} (implicitly {0})
- EvGCSTWDone: {"GCSTWDone", 1005, false, []string{}, nil},
+ EvSTWStart: {"STWStart", 1005, false, []string{"kindid"}, []string{"kind"}}, // <= 1.9, args was {} (implicitly {0})
+ EvSTWDone: {"STWDone", 1005, false, []string{}, nil},
EvGCSweepStart: {"GCSweepStart", 1005, true, []string{}, nil},
EvGCSweepDone: {"GCSweepDone", 1005, false, []string{"swept", "reclaimed"}, nil}, // before 1.9, format was {}
EvGoCreate: {"GoCreate", 1005, true, []string{"g", "stack"}, nil},
EvUserLog: {"UserLog", 1011, true, []string{"id", "keyid"}, []string{"category", "message"}},
EvCPUSample: {"CPUSample", 1019, true, []string{"ts", "p", "g"}, nil},
}
+
+// Copied from src/runtime/proc.go:stwReasonStrings in Go 1.21.
+var stwReasonStringsGo121 = [...]string{
+ "unknown",
+ "GC mark termination",
+ "GC sweep termination",
+ "write heap dump",
+ "goroutine profile",
+ "goroutine profile cleanup",
+ "all goroutines stack trace",
+ "read mem stats",
+ "AllThreadsSyscall",
+ "GOMAXPROCS",
+ "start trace",
+ "stop trace",
+ "CountPagesInUse (test)",
+ "ReadMetricsSlow (test)",
+ "ReadMemStatsSlow (test)",
+ "PageCachePagesLeaked (test)",
+ "ResetDebugLog (test)",
+}
}
// Instead of Parse that requires a proper binary name for old traces,
// we use 'parse' that omits symbol lookup if an empty string is given.
- _, _, err = parse(bytes.NewReader(data), "")
+ ver, res, err := parse(bytes.NewReader(data), "")
switch {
case strings.HasSuffix(f.Name(), "_good"):
if err != nil {
t.Errorf("failed to parse good trace %v: %v", f.Name(), err)
}
+ checkTrace(t, ver, res)
case strings.HasSuffix(f.Name(), "_unordered"):
if err != ErrTimeOrder {
t.Errorf("unordered trace is not detected %v: %v", f.Name(), err)
}
}
+// checkTrace walks over a good trace and makes a bunch of additional checks
+// that may not cause the parser to outright fail.
+func checkTrace(t *testing.T, ver int, res ParseResult) {
+ for _, ev := range res.Events {
+ if ver >= 1021 {
+ if ev.Type == EvSTWStart && ev.SArgs[0] == "unknown" {
+ t.Errorf("found unknown STW event; update stwReasonStrings?")
+ }
+ }
+ }
+}
+
func TestParseVersion(t *testing.T) {
tests := map[string]int{
"go 1.5 trace\x00\x00\x00\x00": 1005,
return ret
}
- stopTheWorldGC("GOMAXPROCS")
+ stopTheWorldGC(stwGOMAXPROCS)
// newprocs will be processed by startTheWorld
newprocs = int32(n)
}
func ResetDebugLog() {
- stopTheWorld("ResetDebugLog")
+ stopTheWorld(stwForTestResetDebugLog)
for l := allDloggers; l != nil; l = l.allLink {
l.w.write = 0
l.w.tick, l.w.nano = 0, 0
var ReadUnaligned64 = readUnaligned64
func CountPagesInUse() (pagesInUse, counted uintptr) {
- stopTheWorld("CountPagesInUse")
+ stopTheWorld(stwForTestCountPagesInUse)
pagesInUse = uintptr(mheap_.pagesInUse.Load())
}
func ReadMetricsSlow(memStats *MemStats, samplesp unsafe.Pointer, len, cap int) {
- stopTheWorld("ReadMetricsSlow")
+ stopTheWorld(stwForTestReadMetricsSlow)
// Initialize the metrics beforehand because this could
// allocate and skew the stats.
// ReadMemStatsSlow returns both the runtime-computed MemStats and
// MemStats accumulated by scanning the heap.
func ReadMemStatsSlow() (base, slow MemStats) {
- stopTheWorld("ReadMemStatsSlow")
+ stopTheWorld(stwForTestReadMemStatsSlow)
// Run on the system stack to avoid stack growth allocation.
systemstack(func() {
}
func PageCachePagesLeaked() (leaked uintptr) {
- stopTheWorld("PageCachePagesLeaked")
+ stopTheWorld(stwForTestPageCachePagesLeaked)
// Walk over destroyed Ps and look for unflushed caches.
deadp := allp[len(allp):cap(allp)]
//go:linkname runtime_debug_WriteHeapDump runtime/debug.WriteHeapDump
func runtime_debug_WriteHeapDump(fd uintptr) {
- stopTheWorld("write heap dump")
+ stopTheWorld(stwWriteHeapDump)
// Keep m on this G's stack instead of the system stack.
// Both readmemstats_m and writeheapdump_m have pretty large
now := nanotime()
work.tSweepTerm = now
work.pauseStart = now
- if traceEnabled() {
- traceGCSTWStart(1)
- }
- systemstack(stopTheWorldWithSema)
+ systemstack(func() { stopTheWorldWithSema(stwGCSweepTerm) })
// Finish sweep before we start concurrent scan.
systemstack(func() {
finishsweep_m()
// Concurrent mark.
systemstack(func() {
- now = startTheWorldWithSema(traceEnabled())
+ now = startTheWorldWithSema()
work.pauseNS += now - work.pauseStart
work.tMark = now
memstats.gcPauseDist.record(now - work.pauseStart)
work.tMarkTerm = now
work.pauseStart = now
getg().m.preemptoff = "gcing"
- if traceEnabled() {
- traceGCSTWStart(0)
- }
- systemstack(stopTheWorldWithSema)
+ systemstack(func() { stopTheWorldWithSema(stwGCMarkTerm) })
// The gcphase is _GCmark, it will transition to _GCmarktermination
// below. The important thing is that the wb remains active until
// all marking is complete. This includes writes made by the GC.
if restart {
getg().m.preemptoff = ""
systemstack(func() {
- now := startTheWorldWithSema(traceEnabled())
+ now := startTheWorldWithSema()
work.pauseNS += now - work.pauseStart
memstats.gcPauseDist.record(now - work.pauseStart)
})
throw("failed to set sweep barrier")
}
- systemstack(func() { startTheWorldWithSema(traceEnabled()) })
+ systemstack(func() { startTheWorldWithSema() })
// Flush the heap profile so we can start a new cycle next GC.
// This is relatively expensive, so we don't do it with the
ourg := getg()
- stopTheWorld("profile")
+ stopTheWorld(stwGoroutineProfile)
// Using gcount while the world is stopped should give us a consistent view
// of the number of live goroutines, minus the number of goroutines that are
// alive and permanently marked as "system". But to make this count agree
tryRecordGoroutineProfile(gp1, Gosched)
})
- stopTheWorld("profile cleanup")
+ stopTheWorld(stwGoroutineProfileCleanup)
endOffset := goroutineProfile.offset.Swap(0)
goroutineProfile.active = false
goroutineProfile.records = nil
return gp1 != gp && readgstatus(gp1) != _Gdead && !isSystemGoroutine(gp1, false)
}
- stopTheWorld("profile")
+ stopTheWorld(stwGoroutineProfile)
// World is stopped, no locking required.
n = 1
// into buf after the trace for the current goroutine.
func Stack(buf []byte, all bool) int {
if all {
- stopTheWorld("stack trace")
+ stopTheWorld(stwAllGoroutinesStack)
}
n := 0
// which is a snapshot as of the most recently completed garbage
// collection cycle.
func ReadMemStats(m *MemStats) {
- stopTheWorld("read mem stats")
+ stopTheWorld(stwReadMemStats)
systemstack(func() {
readmemstats_m(m)
// N.B. Internally, this function does not depend on STW to
// successfully change every thread. It is only needed for user
// expectations, per above.
- stopTheWorld("doAllThreadsSyscall")
+ stopTheWorld(stwAllThreadsSyscall)
// This function depends on several properties:
//
return gp.atomicstatus.CompareAndSwap(_Gpreempted, _Gwaiting)
}
+// stwReason is an enumeration of reasons the world is stopping.
+type stwReason uint8
+
+// Reasons to stop-the-world.
+//
+// Avoid reusing reasons and add new ones instead.
+const (
+ stwUnknown stwReason = iota // "unknown"
+ stwGCMarkTerm // "GC mark termination"
+ stwGCSweepTerm // "GC sweep termination"
+ stwWriteHeapDump // "write heap dump"
+ stwGoroutineProfile // "goroutine profile"
+ stwGoroutineProfileCleanup // "goroutine profile cleanup"
+ stwAllGoroutinesStack // "all goroutines stack trace"
+ stwReadMemStats // "read mem stats"
+ stwAllThreadsSyscall // "AllThreadsSyscall"
+ stwGOMAXPROCS // "GOMAXPROCS"
+ stwStartTrace // "start trace"
+ stwStopTrace // "stop trace"
+ stwForTestCountPagesInUse // "CountPagesInUse (test)"
+ stwForTestReadMetricsSlow // "ReadMetricsSlow (test)"
+ stwForTestReadMemStatsSlow // "ReadMemStatsSlow (test)"
+ stwForTestPageCachePagesLeaked // "PageCachePagesLeaked (test)"
+ stwForTestResetDebugLog // "ResetDebugLog (test)"
+)
+
+func (r stwReason) String() string {
+ return stwReasonStrings[r]
+}
+
+// If you add to this list, also add it to src/internal/trace/parser.go.
+// If you change the values of any of the stw* constants, bump the trace
+// version number and make a copy of this.
+var stwReasonStrings = [...]string{
+ stwUnknown: "unknown",
+ stwGCMarkTerm: "GC mark termination",
+ stwGCSweepTerm: "GC sweep termination",
+ stwWriteHeapDump: "write heap dump",
+ stwGoroutineProfile: "goroutine profile",
+ stwGoroutineProfileCleanup: "goroutine profile cleanup",
+ stwAllGoroutinesStack: "all goroutines stack trace",
+ stwReadMemStats: "read mem stats",
+ stwAllThreadsSyscall: "AllThreadsSyscall",
+ stwGOMAXPROCS: "GOMAXPROCS",
+ stwStartTrace: "start trace",
+ stwStopTrace: "stop trace",
+ stwForTestCountPagesInUse: "CountPagesInUse (test)",
+ stwForTestReadMetricsSlow: "ReadMetricsSlow (test)",
+ stwForTestReadMemStatsSlow: "ReadMemStatsSlow (test)",
+ stwForTestPageCachePagesLeaked: "PageCachePagesLeaked (test)",
+ stwForTestResetDebugLog: "ResetDebugLog (test)",
+}
+
// stopTheWorld stops all P's from executing goroutines, interrupting
// all goroutines at GC safe points and records reason as the reason
// for the stop. On return, only the current goroutine's P is running.
// This is also used by routines that do stack dumps. If the system is
// in panic or being exited, this may not reliably stop all
// goroutines.
-func stopTheWorld(reason string) {
+func stopTheWorld(reason stwReason) {
semacquire(&worldsema)
gp := getg()
- gp.m.preemptoff = reason
+ gp.m.preemptoff = reason.String()
systemstack(func() {
// Mark the goroutine which called stopTheWorld preemptible so its
// stack may be scanned.
// have already completed by the time we exit.
// Don't provide a wait reason because we're still executing.
casGToWaiting(gp, _Grunning, waitReasonStoppingTheWorld)
- stopTheWorldWithSema()
+ stopTheWorldWithSema(reason)
casgstatus(gp, _Gwaiting, _Grunning)
})
}
// startTheWorld undoes the effects of stopTheWorld.
func startTheWorld() {
- systemstack(func() { startTheWorldWithSema(false) })
+ systemstack(func() { startTheWorldWithSema() })
// worldsema must be held over startTheWorldWithSema to ensure
// gomaxprocs cannot change while worldsema is held.
// stopTheWorldGC has the same effect as stopTheWorld, but blocks
// until the GC is not running. It also blocks a GC from starting
// until startTheWorldGC is called.
-func stopTheWorldGC(reason string) {
+func stopTheWorldGC(reason stwReason) {
semacquire(&gcsema)
stopTheWorld(reason)
}
// startTheWorldWithSema and stopTheWorldWithSema.
// Holding worldsema causes any other goroutines invoking
// stopTheWorld to block.
-func stopTheWorldWithSema() {
+func stopTheWorldWithSema(reason stwReason) {
+ if traceEnabled() {
+ traceSTWStart(reason)
+ }
gp := getg()
// If we hold a lock, then we won't be able to stop another M
worldStopped()
}
-func startTheWorldWithSema(emitTraceEvent bool) int64 {
+func startTheWorldWithSema() int64 {
assertWorldStopped()
mp := acquirem() // disable preemption because it can be holding p in a local var
// Capture start-the-world time before doing clean-up tasks.
startTime := nanotime()
- if emitTraceEvent {
- traceGCSTWDone()
+ if traceEnabled() {
+ traceSTWDone()
}
// Wakeup an additional proc in case we have excessive runnable goroutines
traceEvProcStop = 6 // stop of P [timestamp]
traceEvGCStart = 7 // GC start [timestamp, seq, stack id]
traceEvGCDone = 8 // GC done [timestamp]
- traceEvGCSTWStart = 9 // GC STW start [timestamp, kind]
- traceEvGCSTWDone = 10 // GC STW done [timestamp]
+ traceEvSTWStart = 9 // STW start [timestamp, kind]
+ traceEvSTWDone = 10 // STW done [timestamp]
traceEvGCSweepStart = 11 // GC sweep start [timestamp, stack id]
traceEvGCSweepDone = 12 // GC sweep done [timestamp, swept, reclaimed]
traceEvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, new stack id, stack id]
// mTraceState is per-M state for the tracer.
type mTraceState struct {
- startingTrace bool // this M is in TraceStart, potentially before traceEnabled is true
+ startingTrace bool // this M is in TraceStart, potentially before traceEnabled is true
+ tracedSTWStart bool // this M traced a STW start, so it should trace an end
}
// pTraceState is per-P state for the tracer.
// Do not stop the world during GC so we ensure we always see
// a consistent view of GC-related events (e.g. a start is always
// paired with an end).
- stopTheWorldGC("start tracing")
+ stopTheWorldGC(stwStartTrace)
// Prevent sysmon from running any code that could generate events.
lock(&sched.sysmonlock)
func StopTrace() {
// Stop the world so that we can collect the trace buffers from all p's below,
// and also to avoid races with traceEvent.
- stopTheWorldGC("stop tracing")
+ stopTheWorldGC(stwStopTrace)
// See the comment in StartTrace.
lock(&sched.sysmonlock)
trace.headerWritten = true
trace.lockOwner = nil
unlock(&trace.lock)
- return []byte("go 1.19 trace\x00\x00\x00"), false
+ return []byte("go 1.21 trace\x00\x00\x00"), false
}
// Optimistically look for CPU profile samples. This may write new stack
// records, and may write new tracing buffers.
traceEvent(traceEvGCDone, -1)
}
-func traceGCSTWStart(kind int) {
- traceEvent(traceEvGCSTWStart, -1, uint64(kind))
+func traceSTWStart(reason stwReason) {
+ // Don't trace if this STW is for trace start/stop, since traceEnabled
+ // switches during a STW.
+ if reason == stwStartTrace || reason == stwStopTrace {
+ return
+ }
+ getg().m.trace.tracedSTWStart = true
+ traceEvent(traceEvSTWStart, -1, uint64(reason))
}
-func traceGCSTWDone() {
- traceEvent(traceEvGCSTWDone, -1)
+func traceSTWDone() {
+ mp := getg().m
+ if !mp.trace.tracedSTWStart {
+ return
+ }
+ mp.trace.tracedSTWStart = false
+ traceEvent(traceEvSTWDone, -1)
}
// traceGCSweepStart prepares to trace a sweep loop. This does not