From 3053788cac0343c2fd29806ebc358d2f63976695 Mon Sep 17 00:00:00 2001
From: Austin Clements <austin@google.com>
Date: Mon, 24 Jul 2017 11:37:59 -0400
Subject: [PATCH] cmd/trace: add minimum mutator utilization (MMU) plot

This adds an endpoint to the trace tool that plots the minimum mutator
utilization curve using information on mark assists and GC pauses from
the trace.

This commit implements a fairly straightforward O(nm) algorithm for
computing the MMU (and tests against an even more direct but slower
algorithm). Future commits will extend and optimize this algorithm.

This should be useful for debugging and understanding mutator
utilization issues like #14951, #14812, #18155. #18534, #21107,
particularly once follow-up CLs add trace cross-referencing.

Change-Id: Ic2866869e7da1e6c56ba3e809abbcb2eb9c4923a
Reviewed-on: https://go-review.googlesource.com/c/60790
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Hyang-Ah Hana Kim <hyangah@gmail.com>
---
 src/cmd/trace/main.go               |   1 +
 src/cmd/trace/mmu.go                | 160 ++++++++++++++++++
 src/internal/traceparser/gc.go      | 248 ++++++++++++++++++++++++++++
 src/internal/traceparser/gc_test.go | 158 ++++++++++++++++++
 4 files changed, 567 insertions(+)
 create mode 100644 src/cmd/trace/mmu.go
 create mode 100644 src/internal/traceparser/gc.go
 create mode 100644 src/internal/traceparser/gc_test.go

diff --git a/src/cmd/trace/main.go b/src/cmd/trace/main.go
index a33d2f4679..f6ec38d673 100644
--- a/src/cmd/trace/main.go
+++ b/src/cmd/trace/main.go
@@ -202,6 +202,7 @@ var templMain = template.Must(template.New("").Parse(`
 <a href="/sched">Scheduler latency profile</a> (<a href="/sche?raw=1" download="sched.profile">⬇</a>)<br>
 <a href="/usertasks">User-defined tasks</a><br>
 <a href="/userregions">User-defined regions</a><br>
+<a href="/mmu">Minimum mutator utilization</a><br>
 </body>
 </html>
 `))
diff --git a/src/cmd/trace/mmu.go b/src/cmd/trace/mmu.go
new file mode 100644
index 0000000000..cc14025d38
--- /dev/null
+++ b/src/cmd/trace/mmu.go
@@ -0,0 +1,160 @@
+// Copyright 2017 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+// Minimum mutator utilization (MMU) graphing.
+
+package main
+
+import (
+	"encoding/json"
+	"fmt"
+	trace "internal/traceparser"
+	"log"
+	"math"
+	"net/http"
+	"strings"
+	"sync"
+	"time"
+)
+
+func init() {
+	http.HandleFunc("/mmu", httpMMU)
+	http.HandleFunc("/mmuPlot", httpMMUPlot)
+}
+
+var mmuCache struct {
+	init     sync.Once
+	util     []trace.MutatorUtil
+	mmuCurve *trace.MMUCurve
+	err      error
+}
+
+func getMMUCurve() ([]trace.MutatorUtil, *trace.MMUCurve, error) {
+	mmuCache.init.Do(func() {
+		tr, err := parseTrace()
+		if err != nil {
+			mmuCache.err = err
+		} else {
+			mmuCache.util = tr.MutatorUtilization()
+			mmuCache.mmuCurve = trace.NewMMUCurve(mmuCache.util)
+		}
+	})
+	return mmuCache.util, mmuCache.mmuCurve, mmuCache.err
+}
+
+// httpMMU serves the MMU plot page.
+func httpMMU(w http.ResponseWriter, r *http.Request) {
+	http.ServeContent(w, r, "", time.Time{}, strings.NewReader(templMMU))
+}
+
+// httpMMUPlot serves the JSON data for the MMU plot.
+func httpMMUPlot(w http.ResponseWriter, r *http.Request) {
+	mu, mmuCurve, err := getMMUCurve()
+	if err != nil {
+		http.Error(w, fmt.Sprintf("failed to parse events: %v", err), http.StatusInternalServerError)
+		return
+	}
+
+	// Find a nice starting point for the plot.
+	xMin := time.Second
+	for xMin > 1 {
+		if mmu := mmuCurve.MMU(xMin); mmu < 0.0001 {
+			break
+		}
+		xMin /= 1000
+	}
+	// Cover six orders of magnitude.
+	xMax := xMin * 1e6
+	// But no more than the length of the trace.
+	if maxMax := time.Duration(mu[len(mu)-1].Time - mu[0].Time); xMax > maxMax {
+		xMax = maxMax
+	}
+	// Compute MMU curve.
+	logMin, logMax := math.Log(float64(xMin)), math.Log(float64(xMax))
+	const samples = 100
+	plot := make([][2]float64, samples)
+	for i := 0; i < samples; i++ {
+		window := time.Duration(math.Exp(float64(i)/(samples-1)*(logMax-logMin) + logMin))
+		y := mmuCurve.MMU(window)
+		plot[i] = [2]float64{float64(window), y}
+	}
+
+	// Create JSON response.
+	err = json.NewEncoder(w).Encode(map[string]interface{}{"xMin": int64(xMin), "xMax": int64(xMax), "curve": plot})
+	if err != nil {
+		log.Printf("failed to serialize response: %v", err)
+		return
+	}
+}
+
+var templMMU = `<!doctype html>
+<html>
+  <head>
+    <meta charset="utf-8">
+    <script type="text/javascript" src="https://www.gstatic.com/charts/loader.js"></script>
+    <script type="text/javascript" src="https://ajax.googleapis.com/ajax/libs/jquery/3.2.1/jquery.min.js"></script>
+    <script type="text/javascript">
+      google.charts.load('current', {'packages':['corechart']});
+      google.charts.setOnLoadCallback(refreshChart);
+
+      function niceDuration(ns) {
+          if (ns < 1e3) { return ns + 'ns'; }
+          else if (ns < 1e6) { return ns / 1e3 + 'µs'; }
+          else if (ns < 1e9) { return ns / 1e6 + 'ms'; }
+          else { return ns / 1e9 + 's'; }
+      }
+
+      function refreshChart() {
+        $.getJSON('/mmuPlot')
+         .fail(function(xhr, status, error) {
+           alert('failed to load plot: ' + status);
+         })
+         .done(drawChart);
+      }
+
+      function drawChart(plotData) {
+        var curve = plotData.curve;
+        var data = new google.visualization.DataTable();
+        data.addColumn('number', 'Window duration');
+        data.addColumn('number', 'Minimum mutator utilization');
+        data.addRows(curve);
+        for (var i = 0; i < curve.length; i++) {
+          data.setFormattedValue(i, 0, niceDuration(curve[i][0]));
+        }
+
+        var options = {
+          chart: {
+            title: 'Minimum mutator utilization',
+          },
+          hAxis: {
+            title: 'Window duration',
+            scaleType: 'log',
+            ticks: [],
+          },
+          vAxis: {
+            title: 'Minimum mutator utilization',
+            minValue: 0.0,
+            maxValue: 1.0,
+          },
+          legend: { position: 'none' },
+          width: 900,
+          height: 500,
+          chartArea: { width: '80%', height: '80%' },
+        };
+        for (var v = plotData.xMin; v <= plotData.xMax; v *= 10) {
+          options.hAxis.ticks.push({v:v, f:niceDuration(v)});
+        }
+
+        var container = $('#mmu_chart');
+        container.empty();
+        var chart = new google.visualization.LineChart(container[0]);
+        chart.draw(data, options);
+      }
+    </script>
+  </head>
+  <body>
+    <div id="mmu_chart" style="width: 900px; height: 500px">Loading plot...</div>
+  </body>
+</html>
+`
diff --git a/src/internal/traceparser/gc.go b/src/internal/traceparser/gc.go
new file mode 100644
index 0000000000..7e349308d7
--- /dev/null
+++ b/src/internal/traceparser/gc.go
@@ -0,0 +1,248 @@
+// Copyright 2017 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package traceparser
+
+import (
+	"strings"
+	"time"
+)
+
+// MutatorUtil is a change in mutator utilization at a particular
+// time. Mutator utilization functions are represented as a
+// time-ordered []MutatorUtil.
+type MutatorUtil struct {
+	Time int64
+	// Util is the mean mutator utilization starting at Time. This
+	// is in the range [0, 1].
+	Util float64
+}
+
+// MutatorUtilization returns the mutator utilization function for the
+// given trace. This function will always end with 0 utilization. The
+// bounds of the function are implicit in the first and last event;
+// outside of these bounds the function is undefined.
+func (p *Parsed) MutatorUtilization() []MutatorUtil {
+	events := p.Events
+	if len(events) == 0 {
+		return nil
+	}
+
+	gomaxprocs, gcPs, stw := 1, 0, 0
+	out := []MutatorUtil{{events[0].Ts, 1}}
+	assists := map[uint64]bool{}
+	block := map[uint64]*Event{}
+	bgMark := map[uint64]bool{}
+	for _, ev := range events {
+		switch ev.Type {
+		case EvGomaxprocs:
+			gomaxprocs = int(ev.Args[0])
+		case EvGCSTWStart:
+			stw++
+		case EvGCSTWDone:
+			stw--
+		case EvGCMarkAssistStart:
+			gcPs++
+			assists[ev.G] = true
+		case EvGCMarkAssistDone:
+			gcPs--
+			delete(assists, ev.G)
+		case EvGoStartLabel:
+			if strings.HasPrefix(ev.SArgs[0], "GC ") && ev.SArgs[0] != "GC (idle)" {
+				// Background mark worker.
+				bgMark[ev.G] = true
+				gcPs++
+			}
+			fallthrough
+		case EvGoStart:
+			if assists[ev.G] {
+				// Unblocked during assist.
+				gcPs++
+			}
+			block[ev.G] = ev.Link
+		default:
+			if ev != block[ev.G] {
+				continue
+			}
+
+			if assists[ev.G] {
+				// Blocked during assist.
+				gcPs--
+			}
+			if bgMark[ev.G] {
+				// Background mark worker done.
+				gcPs--
+				delete(bgMark, ev.G)
+			}
+			delete(block, ev.G)
+		}
+
+		ps := gcPs
+		if stw > 0 {
+			ps = gomaxprocs
+		}
+		mu := MutatorUtil{ev.Ts, 1 - float64(ps)/float64(gomaxprocs)}
+		if mu.Util == out[len(out)-1].Util {
+			// No change.
+			continue
+		}
+		if mu.Time == out[len(out)-1].Time {
+			// Take the lowest utilization at a time stamp.
+			if mu.Util < out[len(out)-1].Util {
+				out[len(out)-1] = mu
+			}
+		} else {
+			out = append(out, mu)
+		}
+	}
+
+	// Add final 0 utilization event. This is important to mark
+	// the end of the trace. The exact value shouldn't matter
+	// since no window should extend beyond this, but using 0 is
+	// symmetric with the start of the trace.
+	endTime := events[len(events)-1].Ts
+	if out[len(out)-1].Time == endTime {
+		out[len(out)-1].Util = 0
+	} else {
+		out = append(out, MutatorUtil{endTime, 0})
+	}
+
+	return out
+}
+
+// totalUtil is total utilization, measured in nanoseconds. This is a
+// separate type primarily to distinguish it from mean utilization,
+// which is also a float64.
+type totalUtil float64
+
+func totalUtilOf(meanUtil float64, dur int64) totalUtil {
+	return totalUtil(meanUtil * float64(dur))
+}
+
+// mean returns the mean utilization over dur.
+func (u totalUtil) mean(dur time.Duration) float64 {
+	return float64(u) / float64(dur)
+}
+
+// An MMUCurve is the minimum mutator utilization curve across
+// multiple window sizes.
+type MMUCurve struct {
+	util []MutatorUtil
+	// sums[j] is the cumulative sum of util[:j].
+	sums []totalUtil
+}
+
+// NewMMUCurve returns an MMU curve for the given mutator utilization
+// function.
+func NewMMUCurve(util []MutatorUtil) *MMUCurve {
+	// Compute cumulative sum.
+	sums := make([]totalUtil, len(util))
+	var prev MutatorUtil
+	var sum totalUtil
+	for j, u := range util {
+		sum += totalUtilOf(prev.Util, u.Time-prev.Time)
+		sums[j] = sum
+		prev = u
+	}
+
+	return &MMUCurve{util, sums}
+}
+
+// MMU returns the minimum mutator utilization for the given time
+// window. This is the minimum utilization for all windows of this
+// duration across the execution. The returned value is in the range
+// [0, 1].
+func (c *MMUCurve) MMU(window time.Duration) (mmu float64) {
+	if window <= 0 {
+		return 0
+	}
+	util := c.util
+	if max := time.Duration(util[len(util)-1].Time - util[0].Time); window > max {
+		window = max
+	}
+
+	mmu = 1.0
+
+	// We think of the mutator utilization over time as the
+	// box-filtered utilization function, which we call the
+	// "windowed mutator utilization function". The resulting
+	// function is continuous and piecewise linear (unless
+	// window==0, which we handle elsewhere), where the boundaries
+	// between segments occur when either edge of the window
+	// encounters a change in the instantaneous mutator
+	// utilization function. Hence, the minimum of this function
+	// will always occur when one of the edges of the window
+	// aligns with a utilization change, so these are the only
+	// points we need to consider.
+	//
+	// We compute the mutator utilization function incrementally
+	// by tracking the integral from t=0 to the left edge of the
+	// window and to the right edge of the window.
+	left := integrator{c, 0}
+	right := left
+	time := util[0].Time
+	for {
+		// Advance edges to time and time+window.
+		mu := (right.advance(time+int64(window)) - left.advance(time)).mean(window)
+		if mu < mmu {
+			mmu = mu
+			if mmu == 0 {
+				// The minimum can't go any lower than
+				// zero, so stop early.
+				break
+			}
+		}
+
+		// Advance the window to the next time where either
+		// the left or right edge of the window encounters a
+		// change in the utilization curve.
+		if t1, t2 := left.next(time), right.next(time+int64(window))-int64(window); t1 < t2 {
+			time = t1
+		} else {
+			time = t2
+		}
+		if time > util[len(util)-1].Time-int64(window) {
+			break
+		}
+	}
+	return mmu
+}
+
+// An integrator tracks a position in a utilization function and
+// integrates it.
+type integrator struct {
+	u *MMUCurve
+	// pos is the index in u.util of the current time's non-strict
+	// predecessor.
+	pos int
+}
+
+// advance returns the integral of the utilization function from 0 to
+// time. advance must be called on monotonically increasing values of
+// times.
+func (in *integrator) advance(time int64) totalUtil {
+	util, pos := in.u.util, in.pos
+	// Advance pos until pos+1 is time's strict successor (making
+	// pos time's non-strict predecessor).
+	for pos+1 < len(util) && util[pos+1].Time <= time {
+		pos++
+	}
+	in.pos = pos
+	var partial totalUtil
+	if time != util[pos].Time {
+		partial = totalUtilOf(util[pos].Util, time-util[pos].Time)
+	}
+	return in.u.sums[pos] + partial
+}
+
+// next returns the smallest time t' > time of a change in the
+// utilization function.
+func (in *integrator) next(time int64) int64 {
+	for _, u := range in.u.util[in.pos:] {
+		if u.Time > time {
+			return u.Time
+		}
+	}
+	return 1<<63 - 1
+}
diff --git a/src/internal/traceparser/gc_test.go b/src/internal/traceparser/gc_test.go
new file mode 100644
index 0000000000..821b0f217c
--- /dev/null
+++ b/src/internal/traceparser/gc_test.go
@@ -0,0 +1,158 @@
+// Copyright 2017 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package traceparser
+
+import (
+	"math"
+	"testing"
+	"time"
+)
+
+// aeq returns true if x and y are equal up to 8 digits (1 part in 100
+// million).
+func aeq(x, y float64) bool {
+	if x < 0 && y < 0 {
+		x, y = -x, -y
+	}
+	const digits = 8
+	factor := 1 - math.Pow(10, -digits+1)
+	return x*factor <= y && y*factor <= x
+}
+
+func TestMMU(t *testing.T) {
+	t.Parallel()
+
+	// MU
+	// 1.0  *****   *****   *****
+	// 0.5      *   *   *   *
+	// 0.0      *****   *****
+	//      0   1   2   3   4   5
+	util := []MutatorUtil{
+		{0e9, 1},
+		{1e9, 0},
+		{2e9, 1},
+		{3e9, 0},
+		{4e9, 1},
+		{5e9, 0},
+	}
+	mmuCurve := NewMMUCurve(util)
+
+	for _, test := range []struct {
+		window time.Duration
+		want   float64
+	}{
+		{0, 0},
+		{time.Millisecond, 0},
+		{time.Second, 0},
+		{2 * time.Second, 0.5},
+		{3 * time.Second, 1 / 3.0},
+		{4 * time.Second, 0.5},
+		{5 * time.Second, 3 / 5.0},
+		{6 * time.Second, 3 / 5.0},
+	} {
+		if got := mmuCurve.MMU(test.window); !aeq(test.want, got) {
+			t.Errorf("for %s window, want mu = %f, got %f", test.window, test.want, got)
+		}
+	}
+}
+
+func TestMMUTrace(t *testing.T) {
+	t.Parallel()
+
+	p, err := New("../trace/testdata/stress_1_10_good")
+	if err != nil {
+		t.Fatalf("failed to read input file: %v", err)
+	}
+	if err := p.Parse(0, 1<<62, nil); err != nil {
+		t.Fatalf("failed to parse trace: %s", err)
+	}
+	mu := p.MutatorUtilization()
+	mmuCurve := NewMMUCurve(mu)
+
+	// Test the optimized implementation against the "obviously
+	// correct" implementation.
+	for window := time.Nanosecond; window < 10*time.Second; window *= 10 {
+		want := mmuSlow(mu, window)
+		got := mmuCurve.MMU(window)
+		if !aeq(want, got) {
+			t.Errorf("want %f, got %f mutator utilization in window %s", want, got, window)
+		}
+	}
+}
+
+func BenchmarkMMU(b *testing.B) {
+	p, err := New("../trace/testdata/stress_1_10_good")
+	if err != nil {
+		b.Fatalf("failed to read input file: %v", err)
+	}
+	if err := p.Parse(0, 1<<62, nil); err != nil {
+		b.Fatalf("failed to parse trace: %s", err)
+	}
+	mu := p.MutatorUtilization()
+	b.ResetTimer()
+
+	for i := 0; i < b.N; i++ {
+		mmuCurve := NewMMUCurve(mu)
+		xMin, xMax := time.Microsecond, time.Second
+		logMin, logMax := math.Log(float64(xMin)), math.Log(float64(xMax))
+		const samples = 100
+		for i := 0; i < samples; i++ {
+			window := time.Duration(math.Exp(float64(i)/(samples-1)*(logMax-logMin) + logMin))
+			mmuCurve.MMU(window)
+		}
+	}
+}
+
+func mmuSlow(util []MutatorUtil, window time.Duration) (mmu float64) {
+	if max := time.Duration(util[len(util)-1].Time - util[0].Time); window > max {
+		window = max
+	}
+
+	mmu = 1.0
+
+	// muInWindow returns the mean mutator utilization between
+	// util[0].Time and end.
+	muInWindow := func(util []MutatorUtil, end int64) float64 {
+		total := 0.0
+		var prevU MutatorUtil
+		for _, u := range util {
+			if u.Time > end {
+				total += prevU.Util * float64(end-prevU.Time)
+				break
+			}
+			total += prevU.Util * float64(u.Time-prevU.Time)
+			prevU = u
+		}
+		return total / float64(end-util[0].Time)
+	}
+	update := func() {
+		for i, u := range util {
+			if u.Time+int64(window) > util[len(util)-1].Time {
+				break
+			}
+			mmu = math.Min(mmu, muInWindow(util[i:], u.Time+int64(window)))
+		}
+	}
+
+	// Consider all left-aligned windows.
+	update()
+	// Reverse the trace. Slightly subtle because each MutatorUtil
+	// is a *change*.
+	rutil := make([]MutatorUtil, len(util))
+	if util[len(util)-1].Util != 0 {
+		panic("irreversible trace")
+	}
+	for i, u := range util {
+		util1 := 0.0
+		if i != 0 {
+			util1 = util[i-1].Util
+		}
+		rutil[len(rutil)-i-1] = MutatorUtil{Time: -u.Time, Util: util1}
+	}
+	util = rutil
+	// Consider all right-aligned windows.
+	update()
+	return
+}
-- 
2.48.1