mirror of
https://github.com/golang/go
synced 2024-09-25 15:10:11 -06:00
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>
This commit is contained in:
Austin Clements
parent
f999576dd8
commit
3053788cac
@ -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>
|
||||
`))
|
||||
|
||||
160
src/cmd/trace/mmu.go
Normal file
160
src/cmd/trace/mmu.go
Normal file
@ -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>
|
||||
`
|
||||
248
src/internal/traceparser/gc.go
Normal file
248
src/internal/traceparser/gc.go
Normal file
@ -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
|
||||
}
|
||||
158
src/internal/traceparser/gc_test.go
Normal file
158
src/internal/traceparser/gc_test.go
Normal file
@ -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
|
||||
}
|
||||
Loading…
Reference in New Issue
Block a user