From b1aadd034c1feb6ac8409aca5f0efd10ef442950 Mon Sep 17 00:00:00 2001 From: Michael Anthony Knyszek Date: Thu, 11 May 2023 21:09:10 +0000 Subject: 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 TryBot-Result: Gopher Robot Run-TryBot: Michael Knyszek --- src/internal/trace/parser.go | 72 ++++++++++++++++++++++++++++++++------------ 1 file changed, 52 insertions(+), 20 deletions(-) (limited to 'src/internal/trace/parser.go') diff --git a/src/internal/trace/parser.go b/src/internal/trace/parser.go index 0376e914b1..67fa60b8fb 100644 --- a/src/internal/trace/parser.go +++ b/src/internal/trace/parser.go @@ -151,7 +151,7 @@ func readTrace(r io.Reader) (ver int, events []rawEvent, strings map[uint64]stri 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 @@ -420,18 +420,29 @@ func parseEvents(ver int, rawEvents []rawEvent, strings map[uint64]string) (even 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, @@ -653,20 +664,20 @@ func postProcessTrace(ver int, events []*Event) error { } 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 { @@ -1015,7 +1026,7 @@ func argNum(raw rawEvent, ver int) int { if ver < 1007 { narg-- // 1.7 added an additional seq arg } - case EvGCSTWStart: + case EvSTWStart: if ver < 1010 { narg-- // 1.10 added an argument } @@ -1038,8 +1049,8 @@ const ( 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] @@ -1098,8 +1109,8 @@ var EventDescriptions = [EvCount]struct { 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}, @@ -1140,3 +1151,24 @@ var EventDescriptions = [EvCount]struct { 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)", +} -- cgit v1.3