runtime: emit STW events for all pauses, not just those for the GC

Currently STW events are only emitted for GC STWs. There's little reason
why the trace can't contain events for every STW: they're rare so don't
take up much space in the trace, yet being able to see when the world
was stopped is often critical to debugging certain latency issues,
especially when they stem from user-level APIs.

This change adds new "kinds" to the EvGCSTWStart event, renames the
GCSTW events to just "STW," and lets the parser deal with unknown STW
kinds for future backwards compatibility.

But, this change must break trace compatibility, so it bumps the trace
version to Go 1.21.

This change also includes a small cleanup in the trace command, which
previously checked for STW events when deciding whether user tasks
overlapped with a GC. Looking at the source, I don't see a way for STW
events to ever enter the stream that that code looks at, so that
condition has been deleted.

Change-Id: I9a5dc144092c53e92eb6950e9a5504a790ac00cf
Reviewed-on: https://go-review.googlesource.com/c/go/+/494495
Reviewed-by: Michael Pratt <mpratt@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Michael Knyszek <mknyszek@google.com>

10 files changed, 105 insertions, 43 deletions

diff --git a/src/runtime/debug.go b/src/runtime/debug.go
index 669c36f0d5..9a92b45ff3 100644
--- a/src/runtime/debug.go
+++ b/src/runtime/debug.go
@@ -25,7 +25,7 @@ func GOMAXPROCS(n int) int {
 		return ret
 	}
 
-	stopTheWorldGC("GOMAXPROCS")
+	stopTheWorldGC(stwGOMAXPROCS)
 
 	// newprocs will be processed by startTheWorld
 	newprocs = int32(n)
diff --git a/src/runtime/export_debuglog_test.go b/src/runtime/export_debuglog_test.go
index c9dfdcb393..f12aab00de 100644
--- a/src/runtime/export_debuglog_test.go
+++ b/src/runtime/export_debuglog_test.go
@@ -35,7 +35,7 @@ func DumpDebugLog() string {
 }
 
 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
diff --git a/src/runtime/export_test.go b/src/runtime/export_test.go
index c04b76ee44..db91bc650d 100644
--- a/src/runtime/export_test.go
+++ b/src/runtime/export_test.go
@@ -276,7 +276,7 @@ var ReadUnaligned32 = readUnaligned32
 var ReadUnaligned64 = readUnaligned64
 
 func CountPagesInUse() (pagesInUse, counted uintptr) {
-	stopTheWorld("CountPagesInUse")
+	stopTheWorld(stwForTestCountPagesInUse)
 
 	pagesInUse = uintptr(mheap_.pagesInUse.Load())
 
@@ -319,7 +319,7 @@ func (p *ProfBuf) Close() {
 }
 
 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.
@@ -347,7 +347,7 @@ func ReadMetricsSlow(memStats *MemStats, samplesp unsafe.Pointer, len, cap int)
 // 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() {
@@ -1193,7 +1193,7 @@ func CheckScavengedBitsCleared(mismatches []BitsMismatch) (n int, ok bool) {
 }
 
 func PageCachePagesLeaked() (leaked uintptr) {
-	stopTheWorld("PageCachePagesLeaked")
+	stopTheWorld(stwForTestPageCachePagesLeaked)
 
 	// Walk over destroyed Ps and look for unflushed caches.
 	deadp := allp[len(allp):cap(allp)]
diff --git a/src/runtime/heapdump.go b/src/runtime/heapdump.go
index e3f801129e..8ddec8b2d5 100644
--- a/src/runtime/heapdump.go
+++ b/src/runtime/heapdump.go
@@ -19,7 +19,7 @@ import (
 
 //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
diff --git a/src/runtime/mgc.go b/src/runtime/mgc.go
index bb60a3c447..599f688e6f 100644
--- a/src/runtime/mgc.go
+++ b/src/runtime/mgc.go
@@ -658,10 +658,7 @@ func gcStart(trigger gcTrigger) {
 	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()
@@ -726,7 +723,7 @@ func gcStart(trigger gcTrigger) {
 
 	// Concurrent mark.
 	systemstack(func() {
-		now = startTheWorldWithSema(traceEnabled())
+		now = startTheWorldWithSema()
 		work.pauseNS += now - work.pauseStart
 		work.tMark = now
 		memstats.gcPauseDist.record(now - work.pauseStart)
@@ -848,10 +845,7 @@ top:
 	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.
@@ -878,7 +872,7 @@ top:
 	if restart {
 		getg().m.preemptoff = ""
 		systemstack(func() {
-			now := startTheWorldWithSema(traceEnabled())
+			now := startTheWorldWithSema()
 			work.pauseNS += now - work.pauseStart
 			memstats.gcPauseDist.record(now - work.pauseStart)
 		})
@@ -1092,7 +1086,7 @@ func gcMarkTermination() {
 		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
diff --git a/src/runtime/mprof.go b/src/runtime/mprof.go
index 174ceb0a1f..308ebaebe6 100644
--- a/src/runtime/mprof.go
+++ b/src/runtime/mprof.go
@@ -901,7 +901,7 @@ func goroutineProfileWithLabelsConcurrent(p []StackRecord, labels []unsafe.Point
 
 	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
@@ -966,7 +966,7 @@ func goroutineProfileWithLabelsConcurrent(p []StackRecord, labels []unsafe.Point
 		tryRecordGoroutineProfile(gp1, Gosched)
 	})
 
-	stopTheWorld("profile cleanup")
+	stopTheWorld(stwGoroutineProfileCleanup)
 	endOffset := goroutineProfile.offset.Swap(0)
 	goroutineProfile.active = false
 	goroutineProfile.records = nil
@@ -1101,7 +1101,7 @@ func goroutineProfileWithLabelsSync(p []StackRecord, labels []unsafe.Pointer) (n
 		return gp1 != gp && readgstatus(gp1) != _Gdead && !isSystemGoroutine(gp1, false)
 	}
 
-	stopTheWorld("profile")
+	stopTheWorld(stwGoroutineProfile)
 
 	// World is stopped, no locking required.
 	n = 1
@@ -1187,7 +1187,7 @@ func saveg(pc, sp uintptr, gp *g, r *StackRecord) {
 // 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
diff --git a/src/runtime/mstats.go b/src/runtime/mstats.go
index 3a5273f361..3c17c0b29e 100644
--- a/src/runtime/mstats.go
+++ b/src/runtime/mstats.go
@@ -347,7 +347,7 @@ func init() {
 // 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)
diff --git a/src/runtime/os_linux.go b/src/runtime/os_linux.go
index b0246e5c9f..f407e6a707 100644
--- a/src/runtime/os_linux.go
+++ b/src/runtime/os_linux.go
@@ -739,7 +739,7 @@ func syscall_runtime_doAllThreadsSyscall(trap, a1, a2, a3, a4, a5, a6 uintptr) (
 	// 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:
 	//
diff --git a/src/runtime/proc.go b/src/runtime/proc.go
index 35aeb2d1ac..845e25da6e 100644
--- a/src/runtime/proc.go
+++ b/src/runtime/proc.go
@@ -1157,6 +1157,59 @@ func casGFromPreempted(gp *g, old, new uint32) bool {
 	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.
@@ -1171,10 +1224,10 @@ func casGFromPreempted(gp *g, old, new uint32) bool {
 // 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.
@@ -1188,14 +1241,14 @@ func stopTheWorld(reason string) {
 		// 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.
@@ -1221,7 +1274,7 @@ func startTheWorld() {
 // 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)
 }
@@ -1265,7 +1318,10 @@ var gcsema uint32 = 1
 // 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
@@ -1344,7 +1400,7 @@ func stopTheWorldWithSema() {
 	worldStopped()
 }
 
-func startTheWorldWithSema(emitTraceEvent bool) int64 {
+func startTheWorldWithSema() int64 {
 	assertWorldStopped()
 
 	mp := acquirem() // disable preemption because it can be holding p in a local var
@@ -1388,8 +1444,8 @@ func startTheWorldWithSema(emitTraceEvent bool) int64 {
 
 	// 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
diff --git a/src/runtime/trace.go b/src/runtime/trace.go
index 45a066e7a2..2fe6d2d13f 100644
--- a/src/runtime/trace.go
+++ b/src/runtime/trace.go
@@ -31,8 +31,8 @@ const (
 	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]
@@ -171,7 +171,8 @@ type gTraceState struct {
 
 // 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.
@@ -247,7 +248,7 @@ func StartTrace() error {
 	// 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)
@@ -377,7 +378,7 @@ func StartTrace() error {
 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)
@@ -560,7 +561,7 @@ func readTrace0() (buf []byte, park bool) {
 		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.
@@ -1485,12 +1486,23 @@ func traceGCDone() {
 	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