internal/trace: fix GC time computation of short goroutines

Goroutine analysis reports the sum of all overlapping GC intervals as
the GCTime of a goroutine. The computation is done by adding the length
of a completed GC interval to 'active' goroutines when processing the
corresponding EvGCDone event. This change fixes the two corner cases
the current implementation ignores:

1) Goroutine that ends during GC. Previously, this goroutine was ignored
and GC time was undercounted. We handle this case by setting the
gcStartTime only when GC is active and handling non-zero gcStartTime
when processing EvGoStop and EvGoStart.

2) Goroutine that starts during GC. Previously, the entire GC interval
length was added to the Goroutine's GCTime which resulted in overcount
of GC time. We handle this case by computing the length of overlapped
period precisely.

Change-Id: Ifa8e82672ec341b5ff87837209f4311fa7262b7f
Reviewed-on: https://go-review.googlesource.com/100842
Reviewed-by: Heschi Kreinick <heschi@google.com>
Run-TryBot: Heschi Kreinick <heschi@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>

diff --git a/src/internal/trace/goroutines.go b/src/internal/trace/goroutines.go
index 923a157416f1f452fef8bcbcdcd55c0d25e7ca2b..355fb4d0ad18eb9b64cc4ba8368a0c8bae3dd939 100644 (file)
--- a/src/internal/trace/goroutines.go
+++ b/src/internal/trace/goroutines.go
@@ -40,7 +40,7 @@ type gdesc struct {
 func GoroutineStats(events []*Event) map[uint64]*GDesc {
        gs := make(map[uint64]*GDesc)
        var lastTs int64
-       var gcStartTime int64
+       var gcStartTime int64 // gcStartTime == 0 indicates gc is inactive.
        for _, ev := range events {
                lastTs = ev.Ts
                switch ev.Type {
@@ -67,6 +67,15 @@ func GoroutineStats(events []*Event) map[uint64]*GDesc {
                        g.ExecTime += ev.Ts - g.lastStartTime
                        g.TotalTime = ev.Ts - g.CreationTime
                        g.EndTime = ev.Ts
+                       if gcStartTime != 0 {
+                               if g.CreationTime < gcStartTime {
+                                       g.GCTime += ev.Ts - gcStartTime
+                               } else {
+                                       // The goroutine's lifetime overlaps
+                                       // with a GC completely.
+                                       g.GCTime += ev.Ts - g.CreationTime
+                               }
+                       }
                case EvGoBlockSend, EvGoBlockRecv, EvGoBlockSelect,
                        EvGoBlockSync, EvGoBlockCond:
                        g := gs[ev.G]
@@ -125,10 +134,16 @@ func GoroutineStats(events []*Event) map[uint64]*GDesc {
                        gcStartTime = ev.Ts
                case EvGCDone:
                        for _, g := range gs {
-                               if g.EndTime == 0 {
+                               if g.EndTime != 0 {
+                                       continue
+                               }
+                               if gcStartTime < g.CreationTime {
+                                       g.GCTime += ev.Ts - g.CreationTime
+                               } else {
                                        g.GCTime += ev.Ts - gcStartTime
                                }
                        }
+                       gcStartTime = 0 // indicates gc is inactive.
                }
        }