1
2
3
4
5 package trace
6
7 import (
8 "cmp"
9 "slices"
10 "strings"
11 "time"
12 )
13
14
15 type Summary struct {
16 Goroutines map[GoID]*GoroutineSummary
17 Tasks map[TaskID]*UserTaskSummary
18 }
19
20
21
22 type GoroutineSummary struct {
23 ID GoID
24 Name string
25 PC uint64
26 CreationTime Time
27 StartTime Time
28 EndTime Time
29
30
31 Regions []*UserRegionSummary
32
33
34 GoroutineExecStats
35
36
37
38
39
40
41 *goroutineSummary
42 }
43
44
45 type UserTaskSummary struct {
46 ID TaskID
47 Name string
48 Parent *UserTaskSummary
49 Children []*UserTaskSummary
50
51
52 Start *Event
53
54
55 End *Event
56
57
58 Logs []*Event
59
60
61 Regions []*UserRegionSummary
62
63
64 Goroutines map[GoID]*GoroutineSummary
65 }
66
67
68
69 func (s *UserTaskSummary) Complete() bool {
70 return s.Start != nil && s.End != nil
71 }
72
73
74
75 func (s *UserTaskSummary) Descendents() []*UserTaskSummary {
76 descendents := []*UserTaskSummary{s}
77 for _, child := range s.Children {
78 descendents = append(descendents, child.Descendents()...)
79 }
80 return descendents
81 }
82
83
84
85 type UserRegionSummary struct {
86 TaskID TaskID
87 Name string
88
89
90
91
92
93 Start *Event
94
95
96
97
98 End *Event
99
100 GoroutineExecStats
101 }
102
103
104
105 type GoroutineExecStats struct {
106
107 ExecTime time.Duration
108 SchedWaitTime time.Duration
109 BlockTimeByReason map[string]time.Duration
110 SyscallTime time.Duration
111 SyscallBlockTime time.Duration
112
113
114
115 TotalTime time.Duration
116
117
118
119 RangeTime map[string]time.Duration
120 }
121
122 func (s GoroutineExecStats) NonOverlappingStats() map[string]time.Duration {
123 stats := map[string]time.Duration{
124 "Execution time": s.ExecTime,
125 "Sched wait time": s.SchedWaitTime,
126 "Syscall execution time": s.SyscallTime,
127 "Block time (syscall)": s.SyscallBlockTime,
128 "Unknown time": s.UnknownTime(),
129 }
130 for reason, dt := range s.BlockTimeByReason {
131 stats["Block time ("+reason+")"] += dt
132 }
133
134
135 return stats
136 }
137
138
139 func (s GoroutineExecStats) UnknownTime() time.Duration {
140 sum := s.ExecTime + s.SchedWaitTime + s.SyscallTime +
141 s.SyscallBlockTime
142 for _, dt := range s.BlockTimeByReason {
143 sum += dt
144 }
145
146
147 if sum < s.TotalTime {
148 return s.TotalTime - sum
149 }
150 return 0
151 }
152
153
154 func (s GoroutineExecStats) sub(v GoroutineExecStats) (r GoroutineExecStats) {
155 r = s.clone()
156 r.ExecTime -= v.ExecTime
157 r.SchedWaitTime -= v.SchedWaitTime
158 for reason := range s.BlockTimeByReason {
159 r.BlockTimeByReason[reason] -= v.BlockTimeByReason[reason]
160 }
161 r.SyscallTime -= v.SyscallTime
162 r.SyscallBlockTime -= v.SyscallBlockTime
163 r.TotalTime -= v.TotalTime
164 for name := range s.RangeTime {
165 r.RangeTime[name] -= v.RangeTime[name]
166 }
167 return r
168 }
169
170 func (s GoroutineExecStats) clone() (r GoroutineExecStats) {
171 r = s
172 r.BlockTimeByReason = make(map[string]time.Duration)
173 for reason, dt := range s.BlockTimeByReason {
174 r.BlockTimeByReason[reason] = dt
175 }
176 r.RangeTime = make(map[string]time.Duration)
177 for name, dt := range s.RangeTime {
178 r.RangeTime[name] = dt
179 }
180 return r
181 }
182
183
184
185
186 func (g *GoroutineSummary) snapshotStat(lastTs Time) (ret GoroutineExecStats) {
187 ret = g.GoroutineExecStats.clone()
188
189 if g.goroutineSummary == nil {
190 return ret
191 }
192
193
194 if g.TotalTime == 0 {
195 ret.TotalTime = lastTs.Sub(g.CreationTime)
196 }
197
198
199 if g.lastStartTime != 0 {
200 ret.ExecTime += lastTs.Sub(g.lastStartTime)
201 }
202 if g.lastRunnableTime != 0 {
203 ret.SchedWaitTime += lastTs.Sub(g.lastRunnableTime)
204 }
205 if g.lastBlockTime != 0 {
206 ret.BlockTimeByReason[g.lastBlockReason] += lastTs.Sub(g.lastBlockTime)
207 }
208 if g.lastSyscallTime != 0 {
209 ret.SyscallTime += lastTs.Sub(g.lastSyscallTime)
210 }
211 if g.lastSyscallBlockTime != 0 {
212 ret.SchedWaitTime += lastTs.Sub(g.lastSyscallBlockTime)
213 }
214 for name, ts := range g.lastRangeTime {
215 ret.RangeTime[name] += lastTs.Sub(ts)
216 }
217 return ret
218 }
219
220
221
222
223 func (g *GoroutineSummary) finalize(lastTs Time, trigger *Event) {
224 if trigger != nil {
225 g.EndTime = trigger.Time()
226 }
227 finalStat := g.snapshotStat(lastTs)
228
229 g.GoroutineExecStats = finalStat
230
231
232
233
234
235 if !IsSystemGoroutine(g.Name) {
236 for _, s := range g.activeRegions {
237 s.End = trigger
238 s.GoroutineExecStats = finalStat.sub(s.GoroutineExecStats)
239 g.Regions = append(g.Regions, s)
240 }
241 }
242 *(g.goroutineSummary) = goroutineSummary{}
243 }
244
245
246 type goroutineSummary struct {
247 lastStartTime Time
248 lastRunnableTime Time
249 lastBlockTime Time
250 lastBlockReason string
251 lastSyscallTime Time
252 lastSyscallBlockTime Time
253 lastRangeTime map[string]Time
254 activeRegions []*UserRegionSummary
255 }
256
257
258 type Summarizer struct {
259
260 gs map[GoID]*GoroutineSummary
261
262
263 tasks map[TaskID]*UserTaskSummary
264
265
266
267 syscallingP map[ProcID]GoID
268 syscallingG map[GoID]ProcID
269
270
271
272
273
274 rangesP map[rangeP]GoID
275
276 lastTs Time
277 syncTs Time
278 }
279
280
281 func NewSummarizer() *Summarizer {
282 return &Summarizer{
283 gs: make(map[GoID]*GoroutineSummary),
284 tasks: make(map[TaskID]*UserTaskSummary),
285 syscallingP: make(map[ProcID]GoID),
286 syscallingG: make(map[GoID]ProcID),
287 rangesP: make(map[rangeP]GoID),
288 }
289 }
290
291 type rangeP struct {
292 id ProcID
293 name string
294 }
295
296
297 func (s *Summarizer) Event(ev *Event) {
298 if s.syncTs == 0 {
299 s.syncTs = ev.Time()
300 }
301 s.lastTs = ev.Time()
302
303 switch ev.Kind() {
304
305 case EventSync:
306 s.syncTs = ev.Time()
307
308
309 case EventStateTransition:
310 st := ev.StateTransition()
311 switch st.Resource.Kind {
312
313 case ResourceGoroutine:
314 id := st.Resource.Goroutine()
315 old, new := st.Goroutine()
316 if old == new {
317
318 break
319 }
320
321
322 g := s.gs[id]
323 switch old {
324 case GoUndetermined, GoNotExist:
325 g = &GoroutineSummary{ID: id, goroutineSummary: &goroutineSummary{}}
326
327
328 if old == GoUndetermined {
329 g.CreationTime = s.syncTs
330 } else {
331 g.CreationTime = ev.Time()
332 }
333
334 g.lastRangeTime = make(map[string]Time)
335 g.BlockTimeByReason = make(map[string]time.Duration)
336 g.RangeTime = make(map[string]time.Duration)
337
338
339
340
341
342
343
344
345
346
347
348 if creatorG := s.gs[ev.Goroutine()]; creatorG != nil && len(creatorG.activeRegions) > 0 {
349 regions := creatorG.activeRegions
350 s := regions[len(regions)-1]
351 g.activeRegions = []*UserRegionSummary{{TaskID: s.TaskID, Start: ev}}
352 }
353 s.gs[g.ID] = g
354 case GoRunning:
355
356 g.ExecTime += ev.Time().Sub(g.lastStartTime)
357 g.lastStartTime = 0
358 case GoWaiting:
359
360 if g.lastBlockTime != 0 {
361 g.BlockTimeByReason[g.lastBlockReason] += ev.Time().Sub(g.lastBlockTime)
362 g.lastBlockTime = 0
363 }
364 case GoRunnable:
365
366 if g.lastRunnableTime != 0 {
367 g.SchedWaitTime += ev.Time().Sub(g.lastRunnableTime)
368 g.lastRunnableTime = 0
369 }
370 case GoSyscall:
371
372 if g.lastSyscallTime != 0 {
373 if g.lastSyscallBlockTime != 0 {
374 g.SyscallBlockTime += ev.Time().Sub(g.lastSyscallBlockTime)
375 g.SyscallTime += g.lastSyscallBlockTime.Sub(g.lastSyscallTime)
376 } else {
377 g.SyscallTime += ev.Time().Sub(g.lastSyscallTime)
378 }
379 g.lastSyscallTime = 0
380 g.lastSyscallBlockTime = 0
381
382
383 delete(s.syscallingP, s.syscallingG[id])
384 delete(s.syscallingG, id)
385 }
386 }
387
388
389
390
391
392 if g.Name == "" {
393 for frame := range st.Stack.Frames() {
394
395
396
397
398
399 g.PC = frame.PC
400 g.Name = frame.Func
401 }
402 }
403
404
405 switch new {
406 case GoRunning:
407
408 g.lastStartTime = ev.Time()
409 if g.StartTime == 0 {
410 g.StartTime = ev.Time()
411 }
412 case GoRunnable:
413 g.lastRunnableTime = ev.Time()
414 case GoWaiting:
415 if st.Reason != "forever" {
416 g.lastBlockTime = ev.Time()
417 g.lastBlockReason = st.Reason
418 break
419 }
420
421 fallthrough
422 case GoNotExist:
423 g.finalize(ev.Time(), ev)
424 case GoSyscall:
425 s.syscallingP[ev.Proc()] = id
426 s.syscallingG[id] = ev.Proc()
427 g.lastSyscallTime = ev.Time()
428 }
429
430
431
432 case ResourceProc:
433 id := st.Resource.Proc()
434 old, new := st.Proc()
435 if old != new && new == ProcIdle {
436 if goid, ok := s.syscallingP[id]; ok {
437 g := s.gs[goid]
438 g.lastSyscallBlockTime = ev.Time()
439 delete(s.syscallingP, id)
440 }
441 }
442 }
443
444
445 case EventRangeBegin, EventRangeActive:
446 r := ev.Range()
447 var g *GoroutineSummary
448 switch r.Scope.Kind {
449 case ResourceGoroutine:
450
451
452
453
454
455 g = s.gs[r.Scope.Goroutine()]
456 case ResourceProc:
457
458
459
460 g = s.gs[ev.Goroutine()]
461 if g != nil {
462 s.rangesP[rangeP{id: r.Scope.Proc(), name: r.Name}] = ev.Goroutine()
463 }
464 }
465 if g == nil {
466 break
467 }
468 if ev.Kind() == EventRangeActive {
469 if ts := g.lastRangeTime[r.Name]; ts != 0 {
470 g.RangeTime[r.Name] += s.syncTs.Sub(ts)
471 }
472 g.lastRangeTime[r.Name] = s.syncTs
473 } else {
474 g.lastRangeTime[r.Name] = ev.Time()
475 }
476 case EventRangeEnd:
477 r := ev.Range()
478 var g *GoroutineSummary
479 switch r.Scope.Kind {
480 case ResourceGoroutine:
481 g = s.gs[r.Scope.Goroutine()]
482 case ResourceProc:
483 rp := rangeP{id: r.Scope.Proc(), name: r.Name}
484 if goid, ok := s.rangesP[rp]; ok {
485 if goid == ev.Goroutine() {
486
487
488 g = s.gs[goid]
489 }
490 delete(s.rangesP, rp)
491 }
492 }
493 if g == nil {
494 break
495 }
496 ts := g.lastRangeTime[r.Name]
497 if ts == 0 {
498 break
499 }
500 g.RangeTime[r.Name] += ev.Time().Sub(ts)
501 delete(g.lastRangeTime, r.Name)
502
503
504 case EventRegionBegin:
505 g := s.gs[ev.Goroutine()]
506 r := ev.Region()
507 region := &UserRegionSummary{
508 Name: r.Type,
509 TaskID: r.Task,
510 Start: ev,
511 GoroutineExecStats: g.snapshotStat(ev.Time()),
512 }
513 g.activeRegions = append(g.activeRegions, region)
514
515 task := s.getOrAddTask(r.Task)
516 task.Regions = append(task.Regions, region)
517 task.Goroutines[g.ID] = g
518 case EventRegionEnd:
519 g := s.gs[ev.Goroutine()]
520 r := ev.Region()
521 var sd *UserRegionSummary
522 if regionStk := g.activeRegions; len(regionStk) > 0 {
523
524 n := len(regionStk)
525 sd = regionStk[n-1]
526 regionStk = regionStk[:n-1]
527 g.activeRegions = regionStk
528
529 } else {
530
531 sd = &UserRegionSummary{Name: r.Type, TaskID: r.Task}
532
533 task := s.getOrAddTask(r.Task)
534 task.Goroutines[g.ID] = g
535 task.Regions = append(task.Regions, sd)
536 }
537 sd.GoroutineExecStats = g.snapshotStat(ev.Time()).sub(sd.GoroutineExecStats)
538 sd.End = ev
539 g.Regions = append(g.Regions, sd)
540
541
542 case EventTaskBegin, EventTaskEnd:
543
544 t := ev.Task()
545 task := s.getOrAddTask(t.ID)
546 task.Name = t.Type
547 task.Goroutines[ev.Goroutine()] = s.gs[ev.Goroutine()]
548 if ev.Kind() == EventTaskBegin {
549 task.Start = ev
550 } else {
551 task.End = ev
552 }
553
554
555
556 if t.Parent != NoTask && task.Parent == nil {
557 parent := s.getOrAddTask(t.Parent)
558 task.Parent = parent
559 parent.Children = append(parent.Children, task)
560 }
561 case EventLog:
562 log := ev.Log()
563
564
565 task := s.getOrAddTask(log.Task)
566 task.Goroutines[ev.Goroutine()] = s.gs[ev.Goroutine()]
567 task.Logs = append(task.Logs, ev)
568 }
569 }
570
571 func (s *Summarizer) getOrAddTask(id TaskID) *UserTaskSummary {
572 task := s.tasks[id]
573 if task == nil {
574 task = &UserTaskSummary{ID: id, Goroutines: make(map[GoID]*GoroutineSummary)}
575 s.tasks[id] = task
576 }
577 return task
578 }
579
580
581
582 func (s *Summarizer) Finalize() *Summary {
583 for _, g := range s.gs {
584 g.finalize(s.lastTs, nil)
585
586
587 slices.SortFunc(g.Regions, func(a, b *UserRegionSummary) int {
588 x := a.Start
589 y := b.Start
590 if x == nil {
591 if y == nil {
592 return 0
593 }
594 return -1
595 }
596 if y == nil {
597 return +1
598 }
599 return cmp.Compare(x.Time(), y.Time())
600 })
601 g.goroutineSummary = nil
602 }
603 return &Summary{
604 Goroutines: s.gs,
605 Tasks: s.tasks,
606 }
607 }
608
609
610
611
612 func RelatedGoroutinesV2(events []Event, goid GoID) map[GoID]struct{} {
613
614
615
616
617 type unblockEdge struct {
618 operator GoID
619 operand GoID
620 }
621 var unblockEdges []unblockEdge
622 for _, ev := range events {
623 if ev.Goroutine() == NoGoroutine {
624 continue
625 }
626 if ev.Kind() != EventStateTransition {
627 continue
628 }
629 st := ev.StateTransition()
630 if st.Resource.Kind != ResourceGoroutine {
631 continue
632 }
633 id := st.Resource.Goroutine()
634 old, new := st.Goroutine()
635 if old == new || old != GoWaiting {
636 continue
637 }
638 unblockEdges = append(unblockEdges, unblockEdge{
639 operator: ev.Goroutine(),
640 operand: id,
641 })
642 }
643
644
645 gmap := make(map[GoID]struct{})
646 gmap[goid] = struct{}{}
647 for i := 0; i < 2; i++ {
648
649 gmap1 := make(map[GoID]struct{})
650 for g := range gmap {
651 gmap1[g] = struct{}{}
652 }
653 for _, edge := range unblockEdges {
654 if _, ok := gmap[edge.operand]; ok {
655 gmap1[edge.operator] = struct{}{}
656 }
657 }
658 gmap = gmap1
659 }
660 return gmap
661 }
662
663 func IsSystemGoroutine(entryFn string) bool {
664
665
666
667 return entryFn == "" || entryFn != "runtime.main" && strings.HasPrefix(entryFn, "runtime.")
668 }
669
View as plain text