cmd/trace: exclude threads in syscall on behalf of runtime

The number of threads in syscall presented by execution tracer's
trace view includes not only the threads calling system calls on behalf
of user created goroutines, but also those running on behalf of system
goroutines.

When the number of such system goroutines was small, the graph was
useful when examining where a program was saturating the CPU.
But as more and more system goroutines are invloved the graph became
less useful for the purpose - for example, after golang.org/cl/34784,
the timer goroutines dominate in the graph with large P
because the runtime creates per-P timer goroutines.

This change excludes the threads in syscall on behalf of runtime (system
goroutines) from the visualization. Alternatively, I could visualize the
count of such threads in a separate counter but in the same graph.
Given that many other debug endpoints (e.g. /debug/pprof/goroutine) hide
the system goroutines, including them in the same graph can confuse users.

Update #22574

Change-Id: If758cd6b9ed0596fde9a471e846b93246580b9d5
Reviewed-on: https://go-review.googlesource.com/81315
Reviewed-by: Austin Clements <austin@google.com>
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>

diff --git a/src/cmd/trace/trace.go b/src/cmd/trace/trace.go
index d69c5feebc2fcaa58162135c3d7bf5e7e90882a9..45d14f873d4e1ccfd5e2b4920698f9f8a741e09f 100644 (file)
--- a/src/cmd/trace/trace.go
+++ b/src/cmd/trace/trace.go
@@ -287,8 +287,9 @@ type heapStats struct {
 }
 
 type threadStats struct {
-       insyscall uint64
-       prunning  uint64
+       insyscallRuntime uint64 // system goroutine in syscall
+       insyscall        uint64 // user goroutine in syscall
+       prunning         uint64 // thread running P
 }
 
 type frameNode struct {
@@ -309,8 +310,9 @@ const (
 )
 
 type gInfo struct {
-       state      gState       // current state
-       name       string       // name chosen for this goroutine at first EvGoStart
+       state      gState // current state
+       name       string // name chosen for this goroutine at first EvGoStart
+       isSystemG  bool
        start      *trace.Event // most recent EvGoStart
        markAssist *trace.Event // if non-nil, the mark assist currently running.
 }
@@ -391,6 +393,7 @@ func generateTrace(params *traceParams) (ViewerData, error) {
                ctx.gstates[newState]++
                info.state = newState
        }
+
        for _, ev := range ctx.events {
                // Handle state transitions before we filter out events.
                switch ev.Type {
@@ -398,10 +401,12 @@ func generateTrace(params *traceParams) (ViewerData, error) {
                        setGState(ev, ev.G, gRunnable, gRunning)
                        info := getGInfo(ev.G)
                        if info.name == "" {
-                               if len(ev.Stk) > 0 {
-                                       info.name = fmt.Sprintf("G%v %s", ev.G, ev.Stk[0].Fn)
-                               } else {
+                               if len(ev.Stk) == 0 {
                                        info.name = fmt.Sprintf("G%v", ev.G)
+                               } else {
+                                       fname := ev.Stk[0].Fn
+                                       info.name = fmt.Sprintf("G%v %s", ev.G, fname)
+                                       info.isSystemG = strings.HasPrefix(fname, "runtime.") && fname != "runtime.main"
                                }
                        }
                        info.start = ev
@@ -419,10 +424,18 @@ func generateTrace(params *traceParams) (ViewerData, error) {
                        setGState(ev, ev.Args[0], gWaiting, gRunnable)
                case trace.EvGoSysExit:
                        setGState(ev, ev.G, gWaiting, gRunnable)
-                       ctx.threadStats.insyscall--
+                       if getGInfo(ev.G).isSystemG {
+                               ctx.threadStats.insyscallRuntime--
+                       } else {
+                               ctx.threadStats.insyscall--
+                       }
                case trace.EvGoSysBlock:
                        setGState(ev, ev.G, gRunning, gWaiting)
-                       ctx.threadStats.insyscall++
+                       if getGInfo(ev.G).isSystemG {
+                               ctx.threadStats.insyscallRuntime++
+                       } else {
+                               ctx.threadStats.insyscall++
+                       }
                case trace.EvGoSched, trace.EvGoPreempt:
                        setGState(ev, ev.G, gRunning, gRunnable)
                case trace.EvGoStop,
@@ -440,7 +453,11 @@ func generateTrace(params *traceParams) (ViewerData, error) {
                case trace.EvGoInSyscall:
                        // Cancel out the effect of EvGoCreate at the beginning.
                        setGState(ev, ev.G, gRunnable, gWaiting)
-                       ctx.threadStats.insyscall++
+                       if getGInfo(ev.G).isSystemG {
+                               ctx.threadStats.insyscallRuntime++
+                       } else {
+                               ctx.threadStats.insyscall++
+                       }
                case trace.EvHeapAlloc:
                        ctx.heapStats.heapAlloc = ev.Args[0]
                case trace.EvNextGC:
@@ -449,8 +466,8 @@ func generateTrace(params *traceParams) (ViewerData, error) {
                if setGStateErr != nil {
                        return ctx.data, setGStateErr
                }
-               if ctx.gstates[gRunnable] < 0 || ctx.gstates[gRunning] < 0 || ctx.threadStats.insyscall < 0 {
-                       return ctx.data, fmt.Errorf("invalid state after processing %v: runnable=%d running=%d insyscall=%d", ev, ctx.gstates[gRunnable], ctx.gstates[gRunning], ctx.threadStats.insyscall)
+               if ctx.gstates[gRunnable] < 0 || ctx.gstates[gRunning] < 0 || ctx.threadStats.insyscall < 0 || ctx.threadStats.insyscallRuntime < 0 {
+                       return ctx.data, fmt.Errorf("invalid state after processing %v: runnable=%d running=%d insyscall=%d insyscallRuntime=%d", ev, ctx.gstates[gRunnable], ctx.gstates[gRunning], ctx.threadStats.insyscall, ctx.threadStats.insyscallRuntime)
                }
 
                // Ignore events that are from uninteresting goroutines
@@ -663,7 +680,9 @@ func (ctx *traceContext) emitThreadCounters(ev *trace.Event) {
        if ctx.prevThreadStats == ctx.threadStats {
                return
        }
-       ctx.emit(&ViewerEvent{Name: "Threads", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &threadCountersArg{ctx.threadStats.prunning, ctx.threadStats.insyscall}})
+       ctx.emit(&ViewerEvent{Name: "Threads", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &threadCountersArg{
+               Running:   ctx.threadStats.prunning,
+               InSyscall: ctx.threadStats.insyscall}})
        ctx.prevThreadStats = ctx.threadStats
 }