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