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
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(),
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 {
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
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
<td>{{.What}}</td>
</tr>
{{end}}
+ <tr>
+ <td></td>
+ <td></td>
+ <td></td>
+ <td>GC:{{$el.GCTime}}</td>
{{end}}
</body>
</html>
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:
traceparser "internal/trace"
"io/ioutil"
"reflect"
+ "runtime/debug"
"runtime/trace"
"sync"
"testing"
+ "time"
)
var saveTraces = flag.Bool("savetraces", false, "save traces collected by tests")
res, err := analyzeAnnotations()
if err != nil {
- t.Fatalf("failed to analyzeAnnotation: %v", err)
+ t.Fatalf("failed to analyzeAnnotations: %v", err)
}
tasks := res.tasks
}
}
+// 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.