From: Hana Kim Date: Thu, 25 Jan 2018 20:38:09 +0000 (-0500) Subject: cmd/trace: present the GC time in the usertask view X-Git-Tag: go1.11beta1~1505 X-Git-Url: http://www.git.cypherpunks.su/?a=commitdiff_plain;h=cacf8127e3ce1b0a69df66bec68dbd80126aac87;p=gostls13.git cmd/trace: present the GC time in the usertask view The GC time for a task is defined by the sum of GC duration overlapping with the task's duration. Also, grey out non-overlapping slices in the task-oriented trace view. R=go1.11 Change-Id: I42def0eb520f5d9bd07edd265e558706f6fab552 Reviewed-on: https://go-review.googlesource.com/90219 Reviewed-by: Heschi Kreinick --- diff --git a/src/cmd/trace/annotations.go b/src/cmd/trace/annotations.go index b9c14b140c..3b853cc7f2 100644 --- a/src/cmd/trace/annotations.go +++ b/src/cmd/trace/annotations.go @@ -84,6 +84,7 @@ func httpUserTask(w http.ResponseWriter, r *http.Request) { Complete bool Events []event Start, End time.Duration // Time since the beginning of the trace + GCTime time.Duration } base := time.Duration(firstTimestamp()) * time.Nanosecond // trace start @@ -104,14 +105,18 @@ func httpUserTask(w http.ResponseWriter, r *http.Request) { elapsed = 0 } - events = append(events, event{ - WhenString: fmt.Sprintf("%2.9f", when.Seconds()), - Elapsed: elapsed, - What: describeEvent(ev), - Go: ev.G, - }) - last = time.Duration(ev.Ts) * time.Nanosecond + what := describeEvent(ev) + if what != "" { + events = append(events, event{ + WhenString: fmt.Sprintf("%2.9f", when.Seconds()), + Elapsed: elapsed, + What: what, + Go: ev.G, + }) + last = time.Duration(ev.Ts) * time.Nanosecond + } } + data = append(data, entry{ WhenString: fmt.Sprintf("%2.9fs", (time.Duration(task.firstTimestamp())*time.Nanosecond - base).Seconds()), Duration: task.duration(), @@ -120,6 +125,7 @@ func httpUserTask(w http.ResponseWriter, r *http.Request) { Events: events, Start: time.Duration(task.firstTimestamp()) * time.Nanosecond, End: time.Duration(task.lastTimestamp()) * time.Nanosecond, + GCTime: task.overlappingGCDuration(res.gcEvents), }) } sort.Slice(data, func(i, j int) bool { @@ -215,15 +221,25 @@ func analyzeAnnotations() (annotationAnalysisResult, error) { gcEvents = append(gcEvents, ev) } } + // sort spans based on the timestamps. + for _, task := range tasks { + sort.Slice(task.spans, func(i, j int) bool { + si, sj := task.spans[i].firstTimestamp(), task.spans[j].firstTimestamp() + if si != sj { + return si < sj + } + return task.spans[i].lastTimestamp() < task.spans[i].lastTimestamp() + }) + } return annotationAnalysisResult{tasks: tasks, gcEvents: gcEvents}, nil } // taskDesc represents a task. type taskDesc struct { - name string // user-provided task name - id uint64 // internal task id - events []*trace.Event - spans []*spanDesc // associated spans + name string // user-provided task name + id uint64 // internal task id + events []*trace.Event // sorted based on timestamp. + spans []*spanDesc // associated spans, sorted based on the start timestamp and then the last timestamp. goroutines map[uint64][]*trace.Event // Events grouped by goroutine id create *trace.Event // Task create event @@ -376,6 +392,86 @@ func (task *taskDesc) duration() time.Duration { return time.Duration(task.lastTimestamp()-task.firstTimestamp()) * time.Nanosecond } +// overlappingGCDuration returns the sum of GC period overlapping with the task's lifetime. +func (task *taskDesc) overlappingGCDuration(evs []*trace.Event) (overlapping time.Duration) { + for _, ev := range evs { + // make sure we only consider the global GC events. + if typ := ev.Type; typ != trace.EvGCStart && typ != trace.EvGCSTWStart { + continue + } + + if o, overlapped := task.overlappingDuration(ev); overlapped { + overlapping += o + } + } + return overlapping +} + +// overlappingDuration returns whether the durational event, ev, overlaps with +// any of the task's span if ev is a goroutine-local event, or overlaps with +// the task's lifetime if ev is a global event. It returns the overlapping time +// as well. +func (task *taskDesc) overlappingDuration(ev *trace.Event) (time.Duration, bool) { + // TODO: check whether ev is a 'durational' event. + start := ev.Ts + end := lastTimestamp() + if ev.Link != nil { + end = ev.Link.Ts + } + + if start > end { + return 0, false + } + + goid := ev.G + + // This event is a global event (G=0) + if goid == 0 { + taskStart := task.firstTimestamp() + taskEnd := task.lastTimestamp() + o := overlappingDuration(taskStart, taskEnd, start, end) + return o, o > 0 + } + + // Goroutine local event. Check whether there are spans overlapping with the event. + var overlapping time.Duration + var lastSpanEnd int64 // the end of previous overlapping span + for _, span := range task.spans { + if span.goid != goid { + continue + } + spanStart, spanEnd := span.firstTimestamp(), span.lastTimestamp() + if spanStart < lastSpanEnd { // skip nested spans + continue + } + + if o := overlappingDuration(spanStart, spanEnd, start, end); o > 0 { + // overlapping. + lastSpanEnd = spanEnd + overlapping += o + } + } + return overlapping, overlapping > 0 +} + +// overlappingDuration returns the overlapping time duration between +// two time intervals [start1, end1] and [start2, end2] where +// start, end parameters are all int64 representing nanoseconds. +func overlappingDuration(start1, end1, start2, end2 int64) time.Duration { + // assume start1 <= end1 and start2 <= end2 + if end1 < start2 || end2 < start1 { + return 0 + } + + if start1 > start2 { + start1 = start2 + } + if end1 > end2 { + end1 = end2 + } + return time.Duration(end1 - start1) +} + func (task *taskDesc) lastEvent() *trace.Event { if task == nil { return nil @@ -718,6 +814,11 @@ var templUserTaskType = template.Must(template.New("userTask").Funcs(template.Fu {{.What}} {{end}} + + + + + GC:{{$el.GCTime}} {{end}} @@ -752,7 +853,7 @@ func asMillisecond(d time.Duration) float64 { func describeEvent(ev *trace.Event) string { switch ev.Type { case trace.EvGoCreate: - return fmt.Sprintf("created a new goroutine %d", ev.Args[0]) + return fmt.Sprintf("new goroutine %d", ev.Args[0]) case trace.EvGoEnd, trace.EvGoStop: return "goroutine stopped" case trace.EvUserLog: diff --git a/src/cmd/trace/annotations_test.go b/src/cmd/trace/annotations_test.go index 131e1f4741..e67e02b2db 100644 --- a/src/cmd/trace/annotations_test.go +++ b/src/cmd/trace/annotations_test.go @@ -8,9 +8,11 @@ import ( traceparser "internal/trace" "io/ioutil" "reflect" + "runtime/debug" "runtime/trace" "sync" "testing" + "time" ) var saveTraces = flag.Bool("savetraces", false, "save traces collected by tests") @@ -128,7 +130,7 @@ func TestAnalyzeAnnotationTaskTree(t *testing.T) { res, err := analyzeAnnotations() if err != nil { - t.Fatalf("failed to analyzeAnnotation: %v", err) + t.Fatalf("failed to analyzeAnnotations: %v", err) } tasks := res.tasks @@ -177,6 +179,77 @@ func TestAnalyzeAnnotationTaskTree(t *testing.T) { } } +// prog2 starts two tasks; "taskWithGC" that overlaps with GC +// and "taskWithoutGC" that doesn't. In order to run this reliably, +// the caller needs to set up to prevent GC from running automatically. +// prog2 returns the upper-bound gc time that overlaps with the first task. +func prog2() (gcTime time.Duration) { + ch := make(chan bool) + ctx1, done := trace.NewContext(context.Background(), "taskWithGC") + trace.WithSpan(ctx1, "taskWithGC.span1", func(ctx context.Context) { + go func() { + defer trace.StartSpan(ctx, "taskWithGC.span2")() + <-ch + }() + s := time.Now() + debug.FreeOSMemory() // task1 affected by gc + gcTime = time.Since(s) + close(ch) + }) + done() + + ctx2, done2 := trace.NewContext(context.Background(), "taskWithoutGC") + trace.WithSpan(ctx2, "taskWithoutGC.span1", func(ctx context.Context) { + // do nothing. + }) + done2() + return gcTime +} + +func TestAnalyzeAnnotationGC(t *testing.T) { + var gcTime time.Duration + traceProgram(func() { + oldGC := debug.SetGCPercent(10000) // gc, and effectively disable GC + defer debug.SetGCPercent(oldGC) + + gcTime = prog2() + }, "TestAnalyzeAnnotationGC") + + res, err := analyzeAnnotations() + if err != nil { + t.Fatalf("failed to analyzeAnnotations: %v", err) + } + + // Check collected GC Start events are all sorted and non-overlapping. + lastTS := int64(0) + for i, ev := range res.gcEvents { + if ev.Type != traceparser.EvGCStart { + t.Errorf("unwanted event in gcEvents: %v", ev) + } + if i > 0 && lastTS > ev.Ts { + t.Errorf("overlapping GC events:\n%d: %v\n%d: %v", i-1, res.gcEvents[i-1], i, res.gcEvents[i]) + } + if ev.Link != nil { + lastTS = ev.Link.Ts + } + } + + // Check whether only taskWithGC reports overlapping duration. + for _, task := range res.tasks { + got := task.overlappingGCDuration(res.gcEvents) + switch task.name { + case "taskWithGC": + if got <= 0 || got >= gcTime { + t.Errorf("%s reported %v as overlapping GC time; want (0, %v): %v", task.name, got, gcTime, task) + } + case "taskWithoutGC": + if got != 0 { + t.Errorf("%s reported %v as overlapping GC time; want 0: %v", task.name, got, task) + } + } + } +} + // traceProgram runs the provided function while tracing is enabled, // parses the captured trace, and sets the global trace loader to // point to the parsed trace. diff --git a/src/cmd/trace/trace.go b/src/cmd/trace/trace.go index 716d4a99f2..bf5fde508c 100644 --- a/src/cmd/trace/trace.go +++ b/src/cmd/trace/trace.go @@ -710,6 +710,19 @@ func (ctx *traceContext) emitSlice(ev *trace.Event, name string) *ViewerEvent { Stack: ctx.stack(ev.Stk), EndStack: ctx.stack(ev.Link.Stk), } + // grey out non-overlapping events if the event is not a global event (ev.G == 0) + if ctx.mode == taskTraceview && ev.G != 0 { + overlapping := false + for _, task := range ctx.tasks { + if _, overlapped := task.overlappingDuration(ev); overlapped { + overlapping = true + break + } + } + if !overlapping { + sl.Cname = "grey" + } + } ctx.emit(sl) return sl }