1// Copyright 2024 The Go Authors. All rights reserved. 2// Use of this source code is governed by a BSD-style 3// license that can be found in the LICENSE file. 4 5// This file implements conversion from old (Go 1.11–Go 1.21) traces to the Go 6// 1.22 format. 7// 8// Most events have direct equivalents in 1.22, at worst requiring arguments to 9// be reordered. Some events, such as GoWaiting need to look ahead for follow-up 10// events to determine the correct translation. GoSyscall, which is an 11// instantaneous event, gets turned into a 1 ns long pair of 12// GoSyscallStart+GoSyscallEnd, unless we observe a GoSysBlock, in which case we 13// emit a GoSyscallStart+GoSyscallEndBlocked pair with the correct duration 14// (i.e. starting at the original GoSyscall). 15// 16// The resulting trace treats the old trace as a single, large generation, 17// sharing a single evTable for all events. 18// 19// We use a new (compared to what was used for 'go tool trace' in earlier 20// versions of Go) parser for old traces that is optimized for speed, low memory 21// usage, and minimal GC pressure. It allocates events in batches so that even 22// though we have to load the entire trace into memory, the conversion process 23// shouldn't result in a doubling of memory usage, even if all converted events 24// are kept alive, as we free batches once we're done with them. 25// 26// The conversion process is lossless. 27 28package trace 29 30import ( 31 "errors" 32 "fmt" 33 "internal/trace/event" 34 "internal/trace/event/go122" 35 "internal/trace/internal/oldtrace" 36 "io" 37) 38 39type oldTraceConverter struct { 40 trace oldtrace.Trace 41 evt *evTable 42 preInit bool 43 createdPreInit map[GoID]struct{} 44 events oldtrace.Events 45 extra []Event 46 extraArr [3]Event 47 tasks map[TaskID]taskState 48 seenProcs map[ProcID]struct{} 49 lastTs Time 50 procMs map[ProcID]ThreadID 51 lastStwReason uint64 52 53 inlineToStringID []uint64 54 builtinToStringID []uint64 55} 56 57const ( 58 // Block reasons 59 sForever = iota 60 sPreempted 61 sGosched 62 sSleep 63 sChanSend 64 sChanRecv 65 sNetwork 66 sSync 67 sSyncCond 68 sSelect 69 sEmpty 70 sMarkAssistWait 71 72 // STW kinds 73 sSTWUnknown 74 sSTWGCMarkTermination 75 sSTWGCSweepTermination 76 sSTWWriteHeapDump 77 sSTWGoroutineProfile 78 sSTWGoroutineProfileCleanup 79 sSTWAllGoroutinesStackTrace 80 sSTWReadMemStats 81 sSTWAllThreadsSyscall 82 sSTWGOMAXPROCS 83 sSTWStartTrace 84 sSTWStopTrace 85 sSTWCountPagesInUse 86 sSTWReadMetricsSlow 87 sSTWReadMemStatsSlow 88 sSTWPageCachePagesLeaked 89 sSTWResetDebugLog 90 91 sLast 92) 93 94func (it *oldTraceConverter) init(pr oldtrace.Trace) error { 95 it.trace = pr 96 it.preInit = true 97 it.createdPreInit = make(map[GoID]struct{}) 98 it.evt = &evTable{pcs: make(map[uint64]frame)} 99 it.events = pr.Events 100 it.extra = it.extraArr[:0] 101 it.tasks = make(map[TaskID]taskState) 102 it.seenProcs = make(map[ProcID]struct{}) 103 it.procMs = make(map[ProcID]ThreadID) 104 it.lastTs = -1 105 106 evt := it.evt 107 108 // Convert from oldtracer's Strings map to our dataTable. 109 var max uint64 110 for id, s := range pr.Strings { 111 evt.strings.insert(stringID(id), s) 112 if id > max { 113 max = id 114 } 115 } 116 pr.Strings = nil 117 118 // Add all strings used for UserLog. In the old trace format, these were 119 // stored inline and didn't have IDs. We generate IDs for them. 120 if max+uint64(len(pr.InlineStrings)) < max { 121 return errors.New("trace contains too many strings") 122 } 123 var addErr error 124 add := func(id stringID, s string) { 125 if err := evt.strings.insert(id, s); err != nil && addErr == nil { 126 addErr = err 127 } 128 } 129 for id, s := range pr.InlineStrings { 130 nid := max + 1 + uint64(id) 131 it.inlineToStringID = append(it.inlineToStringID, nid) 132 add(stringID(nid), s) 133 } 134 max += uint64(len(pr.InlineStrings)) 135 pr.InlineStrings = nil 136 137 // Add strings that the converter emits explicitly. 138 if max+uint64(sLast) < max { 139 return errors.New("trace contains too many strings") 140 } 141 it.builtinToStringID = make([]uint64, sLast) 142 addBuiltin := func(c int, s string) { 143 nid := max + 1 + uint64(c) 144 it.builtinToStringID[c] = nid 145 add(stringID(nid), s) 146 } 147 addBuiltin(sForever, "forever") 148 addBuiltin(sPreempted, "preempted") 149 addBuiltin(sGosched, "runtime.Gosched") 150 addBuiltin(sSleep, "sleep") 151 addBuiltin(sChanSend, "chan send") 152 addBuiltin(sChanRecv, "chan receive") 153 addBuiltin(sNetwork, "network") 154 addBuiltin(sSync, "sync") 155 addBuiltin(sSyncCond, "sync.(*Cond).Wait") 156 addBuiltin(sSelect, "select") 157 addBuiltin(sEmpty, "") 158 addBuiltin(sMarkAssistWait, "GC mark assist wait for work") 159 addBuiltin(sSTWUnknown, "") 160 addBuiltin(sSTWGCMarkTermination, "GC mark termination") 161 addBuiltin(sSTWGCSweepTermination, "GC sweep termination") 162 addBuiltin(sSTWWriteHeapDump, "write heap dump") 163 addBuiltin(sSTWGoroutineProfile, "goroutine profile") 164 addBuiltin(sSTWGoroutineProfileCleanup, "goroutine profile cleanup") 165 addBuiltin(sSTWAllGoroutinesStackTrace, "all goroutine stack trace") 166 addBuiltin(sSTWReadMemStats, "read mem stats") 167 addBuiltin(sSTWAllThreadsSyscall, "AllThreadsSyscall") 168 addBuiltin(sSTWGOMAXPROCS, "GOMAXPROCS") 169 addBuiltin(sSTWStartTrace, "start trace") 170 addBuiltin(sSTWStopTrace, "stop trace") 171 addBuiltin(sSTWCountPagesInUse, "CountPagesInUse (test)") 172 addBuiltin(sSTWReadMetricsSlow, "ReadMetricsSlow (test)") 173 addBuiltin(sSTWReadMemStatsSlow, "ReadMemStatsSlow (test)") 174 addBuiltin(sSTWPageCachePagesLeaked, "PageCachePagesLeaked (test)") 175 addBuiltin(sSTWResetDebugLog, "ResetDebugLog (test)") 176 177 if addErr != nil { 178 // This should be impossible but let's be safe. 179 return fmt.Errorf("couldn't add strings: %w", addErr) 180 } 181 182 it.evt.strings.compactify() 183 184 // Convert stacks. 185 for id, stk := range pr.Stacks { 186 evt.stacks.insert(stackID(id), stack{pcs: stk}) 187 } 188 189 // OPT(dh): if we could share the frame type between this package and 190 // oldtrace we wouldn't have to copy the map. 191 for pc, f := range pr.PCs { 192 evt.pcs[pc] = frame{ 193 pc: pc, 194 funcID: stringID(f.Fn), 195 fileID: stringID(f.File), 196 line: uint64(f.Line), 197 } 198 } 199 pr.Stacks = nil 200 pr.PCs = nil 201 evt.stacks.compactify() 202 return nil 203} 204 205// next returns the next event, io.EOF if there are no more events, or a 206// descriptive error for invalid events. 207func (it *oldTraceConverter) next() (Event, error) { 208 if len(it.extra) > 0 { 209 ev := it.extra[0] 210 it.extra = it.extra[1:] 211 212 if len(it.extra) == 0 { 213 it.extra = it.extraArr[:0] 214 } 215 // Two events aren't allowed to fall on the same timestamp in the new API, 216 // but this may happen when we produce EvGoStatus events 217 if ev.base.time <= it.lastTs { 218 ev.base.time = it.lastTs + 1 219 } 220 it.lastTs = ev.base.time 221 return ev, nil 222 } 223 224 oev, ok := it.events.Pop() 225 if !ok { 226 return Event{}, io.EOF 227 } 228 229 ev, err := it.convertEvent(oev) 230 231 if err == errSkip { 232 return it.next() 233 } else if err != nil { 234 return Event{}, err 235 } 236 237 // Two events aren't allowed to fall on the same timestamp in the new API, 238 // but this may happen when we produce EvGoStatus events 239 if ev.base.time <= it.lastTs { 240 ev.base.time = it.lastTs + 1 241 } 242 it.lastTs = ev.base.time 243 return ev, nil 244} 245 246var errSkip = errors.New("skip event") 247 248// convertEvent converts an event from the old trace format to zero or more 249// events in the new format. Most events translate 1 to 1. Some events don't 250// result in an event right away, in which case convertEvent returns errSkip. 251// Some events result in more than one new event; in this case, convertEvent 252// returns the first event and stores additional events in it.extra. When 253// encountering events that oldtrace shouldn't be able to emit, ocnvertEvent 254// returns a descriptive error. 255func (it *oldTraceConverter) convertEvent(ev *oldtrace.Event) (OUT Event, ERR error) { 256 var mappedType event.Type 257 var mappedArgs timedEventArgs 258 copy(mappedArgs[:], ev.Args[:]) 259 260 switch ev.Type { 261 case oldtrace.EvGomaxprocs: 262 mappedType = go122.EvProcsChange 263 if it.preInit { 264 // The first EvGomaxprocs signals the end of trace initialization. At this point we've seen 265 // all goroutines that already existed at trace begin. 266 it.preInit = false 267 for gid := range it.createdPreInit { 268 // These are goroutines that already existed when tracing started but for which we 269 // received neither GoWaiting, GoInSyscall, or GoStart. These are goroutines that are in 270 // the states _Gidle or _Grunnable. 271 it.extra = append(it.extra, Event{ 272 ctx: schedCtx{ 273 // G: GoID(gid), 274 G: NoGoroutine, 275 P: NoProc, 276 M: NoThread, 277 }, 278 table: it.evt, 279 base: baseEvent{ 280 typ: go122.EvGoStatus, 281 time: Time(ev.Ts), 282 args: timedEventArgs{uint64(gid), ^uint64(0), uint64(go122.GoRunnable)}, 283 }, 284 }) 285 } 286 it.createdPreInit = nil 287 return Event{}, errSkip 288 } 289 case oldtrace.EvProcStart: 290 it.procMs[ProcID(ev.P)] = ThreadID(ev.Args[0]) 291 if _, ok := it.seenProcs[ProcID(ev.P)]; ok { 292 mappedType = go122.EvProcStart 293 mappedArgs = timedEventArgs{uint64(ev.P)} 294 } else { 295 it.seenProcs[ProcID(ev.P)] = struct{}{} 296 mappedType = go122.EvProcStatus 297 mappedArgs = timedEventArgs{uint64(ev.P), uint64(go122.ProcRunning)} 298 } 299 case oldtrace.EvProcStop: 300 if _, ok := it.seenProcs[ProcID(ev.P)]; ok { 301 mappedType = go122.EvProcStop 302 mappedArgs = timedEventArgs{uint64(ev.P)} 303 } else { 304 it.seenProcs[ProcID(ev.P)] = struct{}{} 305 mappedType = go122.EvProcStatus 306 mappedArgs = timedEventArgs{uint64(ev.P), uint64(go122.ProcIdle)} 307 } 308 case oldtrace.EvGCStart: 309 mappedType = go122.EvGCBegin 310 case oldtrace.EvGCDone: 311 mappedType = go122.EvGCEnd 312 case oldtrace.EvSTWStart: 313 sid := it.builtinToStringID[sSTWUnknown+it.trace.STWReason(ev.Args[0])] 314 it.lastStwReason = sid 315 mappedType = go122.EvSTWBegin 316 mappedArgs = timedEventArgs{uint64(sid)} 317 case oldtrace.EvSTWDone: 318 mappedType = go122.EvSTWEnd 319 mappedArgs = timedEventArgs{it.lastStwReason} 320 case oldtrace.EvGCSweepStart: 321 mappedType = go122.EvGCSweepBegin 322 case oldtrace.EvGCSweepDone: 323 mappedType = go122.EvGCSweepEnd 324 case oldtrace.EvGoCreate: 325 if it.preInit { 326 it.createdPreInit[GoID(ev.Args[0])] = struct{}{} 327 return Event{}, errSkip 328 } 329 mappedType = go122.EvGoCreate 330 case oldtrace.EvGoStart: 331 if it.preInit { 332 mappedType = go122.EvGoStatus 333 mappedArgs = timedEventArgs{ev.Args[0], ^uint64(0), uint64(go122.GoRunning)} 334 delete(it.createdPreInit, GoID(ev.Args[0])) 335 } else { 336 mappedType = go122.EvGoStart 337 } 338 case oldtrace.EvGoStartLabel: 339 it.extra = []Event{{ 340 ctx: schedCtx{ 341 G: GoID(ev.G), 342 P: ProcID(ev.P), 343 M: it.procMs[ProcID(ev.P)], 344 }, 345 table: it.evt, 346 base: baseEvent{ 347 typ: go122.EvGoLabel, 348 time: Time(ev.Ts), 349 args: timedEventArgs{ev.Args[2]}, 350 }, 351 }} 352 return Event{ 353 ctx: schedCtx{ 354 G: GoID(ev.G), 355 P: ProcID(ev.P), 356 M: it.procMs[ProcID(ev.P)], 357 }, 358 table: it.evt, 359 base: baseEvent{ 360 typ: go122.EvGoStart, 361 time: Time(ev.Ts), 362 args: mappedArgs, 363 }, 364 }, nil 365 case oldtrace.EvGoEnd: 366 mappedType = go122.EvGoDestroy 367 case oldtrace.EvGoStop: 368 mappedType = go122.EvGoBlock 369 mappedArgs = timedEventArgs{uint64(it.builtinToStringID[sForever]), uint64(ev.StkID)} 370 case oldtrace.EvGoSched: 371 mappedType = go122.EvGoStop 372 mappedArgs = timedEventArgs{uint64(it.builtinToStringID[sGosched]), uint64(ev.StkID)} 373 case oldtrace.EvGoPreempt: 374 mappedType = go122.EvGoStop 375 mappedArgs = timedEventArgs{uint64(it.builtinToStringID[sPreempted]), uint64(ev.StkID)} 376 case oldtrace.EvGoSleep: 377 mappedType = go122.EvGoBlock 378 mappedArgs = timedEventArgs{uint64(it.builtinToStringID[sSleep]), uint64(ev.StkID)} 379 case oldtrace.EvGoBlock: 380 mappedType = go122.EvGoBlock 381 mappedArgs = timedEventArgs{uint64(it.builtinToStringID[sEmpty]), uint64(ev.StkID)} 382 case oldtrace.EvGoUnblock: 383 mappedType = go122.EvGoUnblock 384 case oldtrace.EvGoBlockSend: 385 mappedType = go122.EvGoBlock 386 mappedArgs = timedEventArgs{uint64(it.builtinToStringID[sChanSend]), uint64(ev.StkID)} 387 case oldtrace.EvGoBlockRecv: 388 mappedType = go122.EvGoBlock 389 mappedArgs = timedEventArgs{uint64(it.builtinToStringID[sChanRecv]), uint64(ev.StkID)} 390 case oldtrace.EvGoBlockSelect: 391 mappedType = go122.EvGoBlock 392 mappedArgs = timedEventArgs{uint64(it.builtinToStringID[sSelect]), uint64(ev.StkID)} 393 case oldtrace.EvGoBlockSync: 394 mappedType = go122.EvGoBlock 395 mappedArgs = timedEventArgs{uint64(it.builtinToStringID[sSync]), uint64(ev.StkID)} 396 case oldtrace.EvGoBlockCond: 397 mappedType = go122.EvGoBlock 398 mappedArgs = timedEventArgs{uint64(it.builtinToStringID[sSyncCond]), uint64(ev.StkID)} 399 case oldtrace.EvGoBlockNet: 400 mappedType = go122.EvGoBlock 401 mappedArgs = timedEventArgs{uint64(it.builtinToStringID[sNetwork]), uint64(ev.StkID)} 402 case oldtrace.EvGoBlockGC: 403 mappedType = go122.EvGoBlock 404 mappedArgs = timedEventArgs{uint64(it.builtinToStringID[sMarkAssistWait]), uint64(ev.StkID)} 405 case oldtrace.EvGoSysCall: 406 // Look for the next event for the same G to determine if the syscall 407 // blocked. 408 blocked := false 409 it.events.All()(func(nev *oldtrace.Event) bool { 410 if nev.G != ev.G { 411 return true 412 } 413 // After an EvGoSysCall, the next event on the same G will either be 414 // EvGoSysBlock to denote a blocking syscall, or some other event 415 // (or the end of the trace) if the syscall didn't block. 416 if nev.Type == oldtrace.EvGoSysBlock { 417 blocked = true 418 } 419 return false 420 }) 421 if blocked { 422 mappedType = go122.EvGoSyscallBegin 423 mappedArgs = timedEventArgs{1: uint64(ev.StkID)} 424 } else { 425 // Convert the old instantaneous syscall event to a pair of syscall 426 // begin and syscall end and give it the shortest possible duration, 427 // 1ns. 428 out1 := Event{ 429 ctx: schedCtx{ 430 G: GoID(ev.G), 431 P: ProcID(ev.P), 432 M: it.procMs[ProcID(ev.P)], 433 }, 434 table: it.evt, 435 base: baseEvent{ 436 typ: go122.EvGoSyscallBegin, 437 time: Time(ev.Ts), 438 args: timedEventArgs{1: uint64(ev.StkID)}, 439 }, 440 } 441 442 out2 := Event{ 443 ctx: out1.ctx, 444 table: it.evt, 445 base: baseEvent{ 446 typ: go122.EvGoSyscallEnd, 447 time: Time(ev.Ts + 1), 448 args: timedEventArgs{}, 449 }, 450 } 451 452 it.extra = append(it.extra, out2) 453 return out1, nil 454 } 455 456 case oldtrace.EvGoSysExit: 457 mappedType = go122.EvGoSyscallEndBlocked 458 case oldtrace.EvGoSysBlock: 459 return Event{}, errSkip 460 case oldtrace.EvGoWaiting: 461 mappedType = go122.EvGoStatus 462 mappedArgs = timedEventArgs{ev.Args[0], ^uint64(0), uint64(go122.GoWaiting)} 463 delete(it.createdPreInit, GoID(ev.Args[0])) 464 case oldtrace.EvGoInSyscall: 465 mappedType = go122.EvGoStatus 466 // In the new tracer, GoStatus with GoSyscall knows what thread the 467 // syscall is on. In the old tracer, EvGoInSyscall doesn't contain that 468 // information and all we can do here is specify NoThread. 469 mappedArgs = timedEventArgs{ev.Args[0], ^uint64(0), uint64(go122.GoSyscall)} 470 delete(it.createdPreInit, GoID(ev.Args[0])) 471 case oldtrace.EvHeapAlloc: 472 mappedType = go122.EvHeapAlloc 473 case oldtrace.EvHeapGoal: 474 mappedType = go122.EvHeapGoal 475 case oldtrace.EvGCMarkAssistStart: 476 mappedType = go122.EvGCMarkAssistBegin 477 case oldtrace.EvGCMarkAssistDone: 478 mappedType = go122.EvGCMarkAssistEnd 479 case oldtrace.EvUserTaskCreate: 480 mappedType = go122.EvUserTaskBegin 481 parent := ev.Args[1] 482 if parent == 0 { 483 parent = uint64(NoTask) 484 } 485 mappedArgs = timedEventArgs{ev.Args[0], parent, ev.Args[2], uint64(ev.StkID)} 486 name, _ := it.evt.strings.get(stringID(ev.Args[2])) 487 it.tasks[TaskID(ev.Args[0])] = taskState{name: name, parentID: TaskID(ev.Args[1])} 488 case oldtrace.EvUserTaskEnd: 489 mappedType = go122.EvUserTaskEnd 490 // Event.Task expects the parent and name to be smuggled in extra args 491 // and as extra strings. 492 ts, ok := it.tasks[TaskID(ev.Args[0])] 493 if ok { 494 delete(it.tasks, TaskID(ev.Args[0])) 495 mappedArgs = timedEventArgs{ 496 ev.Args[0], 497 ev.Args[1], 498 uint64(ts.parentID), 499 uint64(it.evt.addExtraString(ts.name)), 500 } 501 } else { 502 mappedArgs = timedEventArgs{ev.Args[0], ev.Args[1], uint64(NoTask), uint64(it.evt.addExtraString(""))} 503 } 504 case oldtrace.EvUserRegion: 505 switch ev.Args[1] { 506 case 0: // start 507 mappedType = go122.EvUserRegionBegin 508 case 1: // end 509 mappedType = go122.EvUserRegionEnd 510 } 511 mappedArgs = timedEventArgs{ev.Args[0], ev.Args[2], uint64(ev.StkID)} 512 case oldtrace.EvUserLog: 513 mappedType = go122.EvUserLog 514 mappedArgs = timedEventArgs{ev.Args[0], ev.Args[1], it.inlineToStringID[ev.Args[3]], uint64(ev.StkID)} 515 case oldtrace.EvCPUSample: 516 mappedType = go122.EvCPUSample 517 // When emitted by the Go 1.22 tracer, CPU samples have 5 arguments: 518 // timestamp, M, P, G, stack. However, after they get turned into Event, 519 // they have the arguments stack, M, P, G. 520 // 521 // In Go 1.21, CPU samples did not have Ms. 522 mappedArgs = timedEventArgs{uint64(ev.StkID), ^uint64(0), uint64(ev.P), ev.G} 523 default: 524 return Event{}, fmt.Errorf("unexpected event type %v", ev.Type) 525 } 526 527 if oldtrace.EventDescriptions[ev.Type].Stack { 528 if stackIDs := go122.Specs()[mappedType].StackIDs; len(stackIDs) > 0 { 529 mappedArgs[stackIDs[0]-1] = uint64(ev.StkID) 530 } 531 } 532 533 m := NoThread 534 if ev.P != -1 && ev.Type != oldtrace.EvCPUSample { 535 if t, ok := it.procMs[ProcID(ev.P)]; ok { 536 m = ThreadID(t) 537 } 538 } 539 if ev.Type == oldtrace.EvProcStop { 540 delete(it.procMs, ProcID(ev.P)) 541 } 542 g := GoID(ev.G) 543 if g == 0 { 544 g = NoGoroutine 545 } 546 out := Event{ 547 ctx: schedCtx{ 548 G: GoID(g), 549 P: ProcID(ev.P), 550 M: m, 551 }, 552 table: it.evt, 553 base: baseEvent{ 554 typ: mappedType, 555 time: Time(ev.Ts), 556 args: mappedArgs, 557 }, 558 } 559 return out, nil 560} 561 562// convertOldFormat takes a fully loaded trace in the old trace format and 563// returns an iterator over events in the new format. 564func convertOldFormat(pr oldtrace.Trace) *oldTraceConverter { 565 it := &oldTraceConverter{} 566 it.init(pr) 567 return it 568} 569