internal/trace: fix analysis of EvGoWaiting/EvGoInSyscall events

When tracing is started in the middle of program execution,
we already have a number of runnable goroutines and a number
of blocked/in syscall goroutines. In order to reflect these
goroutines in the trace, we emit EvGoCreate for all existing
goroutines. Then for blocked/in syscall goroutines we additionally
emit EvGoWaiting/EvGoInSyscall events. These events don't reset g.ev
during trace analysis. So next EvGoStart finds g.ev set to the
previous EvGoCreate. As the result time between EvGoCreate and
EvGoStart is accounted as scheduler latency. While in reality
it is blocking/syscall time.

Properly reset g.ev for EvGoWaiting/EvGoInSyscall events.

Change-Id: I0615ba31ed7567600a0667ebb27458481da73adb
Reviewed-on: https://go-review.googlesource.com/25572
Reviewed-by: Hyang-Ah Hana Kim <hyangah@gmail.com>

diff --git a/src/internal/trace/parser.go b/src/internal/trace/parser.go
index c31517f683f9d856704c994d75d5c5dacb8d445f..b1fc17ac582585658e816c4829842e45be620d7b 100644 (file)
--- a/src/internal/trace/parser.go
+++ b/src/internal/trace/parser.go
@@ -581,11 +581,13 @@ func postProcessTrace(ver int, events []*Event) error {
                                return fmt.Errorf("g %v is not runnable before EvGoWaiting (offset %v, time %v)", ev.G, ev.Off, ev.Ts)
                        }
                        g.state = gWaiting
+                       g.ev = ev
                case EvGoInSyscall:
                        if g.state != gRunnable {
                                return fmt.Errorf("g %v is not runnable before EvGoInSyscall (offset %v, time %v)", ev.G, ev.Off, ev.Ts)
                        }
                        g.state = gWaiting
+                       g.ev = ev
                case EvGoCreate:
                        if err := checkRunning(p, g, ev, true); err != nil {
                                return err