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 stk := st.Stack
394 if stk != NoStack {
395 var frame StackFrame
396 var ok bool
397 stk.Frames(func(f StackFrame) bool {
398 frame = f
399 ok = true
400 return true
401 })
402 if ok {
403
404
405
406
407
408 g.PC = frame.PC
409 g.Name = frame.Func
410 }
411 }
412 }
413
414
415 switch new {
416 case GoRunning:
417
418 g.lastStartTime = ev.Time()
419 if g.StartTime == 0 {
420 g.StartTime = ev.Time()
421 }
422 case GoRunnable:
423 g.lastRunnableTime = ev.Time()
424 case GoWaiting:
425 if st.Reason != "forever" {
426 g.lastBlockTime = ev.Time()
427 g.lastBlockReason = st.Reason
428 break
429 }
430
431 fallthrough
432 case GoNotExist:
433 g.finalize(ev.Time(), ev)
434 case GoSyscall:
435 s.syscallingP[ev.Proc()] = id
436 s.syscallingG[id] = ev.Proc()
437 g.lastSyscallTime = ev.Time()
438 }
439
440
441
442 case ResourceProc:
443 id := st.Resource.Proc()
444 old, new := st.Proc()
445 if old != new && new == ProcIdle {
446 if goid, ok := s.syscallingP[id]; ok {
447 g := s.gs[goid]
448 g.lastSyscallBlockTime = ev.Time()
449 delete(s.syscallingP, id)
450 }
451 }
452 }
453
454
455 case EventRangeBegin, EventRangeActive:
456 r := ev.Range()
457 var g *GoroutineSummary
458 switch r.Scope.Kind {
459 case ResourceGoroutine:
460
461
462
463
464
465 g = s.gs[r.Scope.Goroutine()]
466 case ResourceProc:
467
468
469
470 g = s.gs[ev.Goroutine()]
471 if g != nil {
472 s.rangesP[rangeP{id: r.Scope.Proc(), name: r.Name}] = ev.Goroutine()
473 }
474 }
475 if g == nil {
476 break
477 }
478 if ev.Kind() == EventRangeActive {
479 if ts := g.lastRangeTime[r.Name]; ts != 0 {
480 g.RangeTime[r.Name] += s.syncTs.Sub(ts)
481 }
482 g.lastRangeTime[r.Name] = s.syncTs
483 } else {
484 g.lastRangeTime[r.Name] = ev.Time()
485 }
486 case EventRangeEnd:
487 r := ev.Range()
488 var g *GoroutineSummary
489 switch r.Scope.Kind {
490 case ResourceGoroutine:
491 g = s.gs[r.Scope.Goroutine()]
492 case ResourceProc:
493 rp := rangeP{id: r.Scope.Proc(), name: r.Name}
494 if goid, ok := s.rangesP[rp]; ok {
495 if goid == ev.Goroutine() {
496
497
498 g = s.gs[goid]
499 }
500 delete(s.rangesP, rp)
501 }
502 }
503 if g == nil {
504 break
505 }
506 ts := g.lastRangeTime[r.Name]
507 if ts == 0 {
508 break
509 }
510 g.RangeTime[r.Name] += ev.Time().Sub(ts)
511 delete(g.lastRangeTime, r.Name)
512
513
514 case EventRegionBegin:
515 g := s.gs[ev.Goroutine()]
516 r := ev.Region()
517 region := &UserRegionSummary{
518 Name: r.Type,
519 TaskID: r.Task,
520 Start: ev,
521 GoroutineExecStats: g.snapshotStat(ev.Time()),
522 }
523 g.activeRegions = append(g.activeRegions, region)
524
525 task := s.getOrAddTask(r.Task)
526 task.Regions = append(task.Regions, region)
527 task.Goroutines[g.ID] = g
528 case EventRegionEnd:
529 g := s.gs[ev.Goroutine()]
530 r := ev.Region()
531 var sd *UserRegionSummary
532 if regionStk := g.activeRegions; len(regionStk) > 0 {
533
534 n := len(regionStk)
535 sd = regionStk[n-1]
536 regionStk = regionStk[:n-1]
537 g.activeRegions = regionStk
538
539 } else {
540
541 sd = &UserRegionSummary{Name: r.Type, TaskID: r.Task}
542
543 task := s.getOrAddTask(r.Task)
544 task.Goroutines[g.ID] = g
545 task.Regions = append(task.Regions, sd)
546 }
547 sd.GoroutineExecStats = g.snapshotStat(ev.Time()).sub(sd.GoroutineExecStats)
548 sd.End = ev
549 g.Regions = append(g.Regions, sd)
550
551
552 case EventTaskBegin, EventTaskEnd:
553
554 t := ev.Task()
555 task := s.getOrAddTask(t.ID)
556 task.Name = t.Type
557 task.Goroutines[ev.Goroutine()] = s.gs[ev.Goroutine()]
558 if ev.Kind() == EventTaskBegin {
559 task.Start = ev
560 } else {
561 task.End = ev
562 }
563
564
565
566 if t.Parent != NoTask && task.Parent == nil {
567 parent := s.getOrAddTask(t.Parent)
568 task.Parent = parent
569 parent.Children = append(parent.Children, task)
570 }
571 case EventLog:
572 log := ev.Log()
573
574
575 task := s.getOrAddTask(log.Task)
576 task.Goroutines[ev.Goroutine()] = s.gs[ev.Goroutine()]
577 task.Logs = append(task.Logs, ev)
578 }
579 }
580
581 func (s *Summarizer) getOrAddTask(id TaskID) *UserTaskSummary {
582 task := s.tasks[id]
583 if task == nil {
584 task = &UserTaskSummary{ID: id, Goroutines: make(map[GoID]*GoroutineSummary)}
585 s.tasks[id] = task
586 }
587 return task
588 }
589
590
591
592 func (s *Summarizer) Finalize() *Summary {
593 for _, g := range s.gs {
594 g.finalize(s.lastTs, nil)
595
596
597 slices.SortFunc(g.Regions, func(a, b *UserRegionSummary) int {
598 x := a.Start
599 y := b.Start
600 if x == nil {
601 if y == nil {
602 return 0
603 }
604 return -1
605 }
606 if y == nil {
607 return +1
608 }
609 return cmp.Compare(x.Time(), y.Time())
610 })
611 g.goroutineSummary = nil
612 }
613 return &Summary{
614 Goroutines: s.gs,
615 Tasks: s.tasks,
616 }
617 }
618
619
620
621
622 func RelatedGoroutinesV2(events []Event, goid GoID) map[GoID]struct{} {
623
624
625
626
627 type unblockEdge struct {
628 operator GoID
629 operand GoID
630 }
631 var unblockEdges []unblockEdge
632 for _, ev := range events {
633 if ev.Goroutine() == NoGoroutine {
634 continue
635 }
636 if ev.Kind() != EventStateTransition {
637 continue
638 }
639 st := ev.StateTransition()
640 if st.Resource.Kind != ResourceGoroutine {
641 continue
642 }
643 id := st.Resource.Goroutine()
644 old, new := st.Goroutine()
645 if old == new || old != GoWaiting {
646 continue
647 }
648 unblockEdges = append(unblockEdges, unblockEdge{
649 operator: ev.Goroutine(),
650 operand: id,
651 })
652 }
653
654
655 gmap := make(map[GoID]struct{})
656 gmap[goid] = struct{}{}
657 for i := 0; i < 2; i++ {
658
659 gmap1 := make(map[GoID]struct{})
660 for g := range gmap {
661 gmap1[g] = struct{}{}
662 }
663 for _, edge := range unblockEdges {
664 if _, ok := gmap[edge.operand]; ok {
665 gmap1[edge.operator] = struct{}{}
666 }
667 }
668 gmap = gmap1
669 }
670 return gmap
671 }
672
673 func IsSystemGoroutine(entryFn string) bool {
674
675
676
677 return entryFn == "" || entryFn != "runtime.main" && strings.HasPrefix(entryFn, "runtime.")
678 }
679
View as plain text