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(` Scheduler latency profile (⬇)
User-defined tasks
User-defined regions
+Minimum mutator utilization
`)) 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 = ` + + + + + + + + +
Loading plot...
+ + +` 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 +}