From: Robert Griesemer Date: Fri, 24 Jun 2016 22:03:04 +0000 (-0700) Subject: cmd/compile: add compiler phase timing X-Git-Tag: go1.8beta1~1815 X-Git-Url: http://www.git.cypherpunks.su/?a=commitdiff_plain;h=f542576b9e576758b7e0a8ec7f8d07b5d0c1f29a;p=gostls13.git cmd/compile: add compiler phase timing Timings is a simple data structure that collects times of labeled Start/Stop events describing timed phases, which later can be written to a file. Adjacent phases with common label prefix are automatically collected in a group together with the accumulated phase time. Timing data can be appended to a file in benchmark data format using the new -bench flag: $ go build -gcflags="-bench=/dev/stdout" -o /dev/null go/types commit: devel +8847c6b Mon Aug 15 17:51:53 2016 -0700 goos: darwin goarch: amd64 BenchmarkCompile:go/types:fe:init 1 663292 ns/op 0.07 % BenchmarkCompile:go/types:fe:loadsys 1 1337371 ns/op 0.14 % BenchmarkCompile:go/types:fe:parse 1 47008869 ns/op 4.91 % 10824 lines 230254 lines/s BenchmarkCompile:go/types:fe:typecheck:top1 1 2843343 ns/op 0.30 % BenchmarkCompile:go/types:fe:typecheck:top2 1 447457 ns/op 0.05 % BenchmarkCompile:go/types:fe:typecheck:func 1 15119595 ns/op 1.58 % 427 funcs 28241 funcs/s BenchmarkCompile:go/types:fe:capturevars 1 56314 ns/op 0.01 % BenchmarkCompile:go/types:fe:inlining 1 9805767 ns/op 1.02 % BenchmarkCompile:go/types:fe:escapes 1 53598646 ns/op 5.60 % BenchmarkCompile:go/types:fe:xclosures 1 199302 ns/op 0.02 % BenchmarkCompile:go/types:fe:subtotal 1 131079956 ns/op 13.70 % BenchmarkCompile:go/types:be:compilefuncs 1 692009428 ns/op 72.33 % 427 funcs 617 funcs/s BenchmarkCompile:go/types:be:externaldcls 1 54591 ns/op 0.01 % BenchmarkCompile:go/types:be:dumpobj 1 133478173 ns/op 13.95 % BenchmarkCompile:go/types:be:subtotal 1 825542192 ns/op 86.29 % BenchmarkCompile:go/types:unaccounted 1 106101 ns/op 0.01 % BenchmarkCompile:go/types:total 1 956728249 ns/op 100.00 % For #16169. Change-Id: I93265fe0cb08e47cd413608d0824c5dd35ba7899 Reviewed-on: https://go-review.googlesource.com/24462 Reviewed-by: Matthew Dempsky --- diff --git a/src/cmd/compile/internal/gc/main.go b/src/cmd/compile/internal/gc/main.go index b9a4ca3ec1..0f5e065310 100644 --- a/src/cmd/compile/internal/gc/main.go +++ b/src/cmd/compile/internal/gc/main.go @@ -8,6 +8,7 @@ package gc import ( "bufio" + "bytes" "cmd/compile/internal/ssa" "cmd/internal/obj" "cmd/internal/sys" @@ -96,7 +97,13 @@ func supportsDynlink(arch *sys.Arch) bool { return arch.InFamily(sys.AMD64, sys.ARM, sys.ARM64, sys.I386, sys.PPC64, sys.S390X) } +// timing data for compiler phases +var timings Timings +var benchfile string + func Main() { + timings.Start("fe", "init") + defer hidePanic() goarch = obj.Getgoarch() @@ -208,6 +215,7 @@ func Main() { flag.StringVar(&memprofile, "memprofile", "", "write memory profile to `file`") flag.Int64Var(&memprofilerate, "memprofilerate", 0, "set runtime.MemProfileRate to `rate`") flag.BoolVar(&ssaEnabled, "ssa", true, "use SSA backend to generate code") + flag.StringVar(&benchfile, "bench", "", "append benchmark times to `file`") obj.Flagparse(usage) Ctxt.Flag_shared = flag_dynlink || flag_shared @@ -302,8 +310,11 @@ func Main() { nerrors = 0 lexlineno = 1 + timings.Start("fe", "loadsys") loadsys() + timings.Start("fe", "parse") + lexlineno0 := lexlineno for _, infile = range flag.Args() { if trace && Debug['x'] != 0 { fmt.Printf("--- %s ---\n", infile) @@ -341,6 +352,8 @@ func Main() { linehistpop() f.Close() } + timings.Stop() + timings.AddEvent(int64(lexlineno-lexlineno0), "lines") testdclstack() mkpackage(localpkg.Name) // final import not used checks @@ -359,6 +372,7 @@ func Main() { defercheckwidth() // Don't use range--typecheck can add closures to xtop. + timings.Start("fe", "typecheck", "top1") for i := 0; i < len(xtop); i++ { if xtop[i].Op != ODCL && xtop[i].Op != OAS && xtop[i].Op != OAS2 { xtop[i] = typecheck(xtop[i], Etop) @@ -369,6 +383,7 @@ func Main() { // To check interface assignments, depends on phase 1. // Don't use range--typecheck can add closures to xtop. + timings.Start("fe", "typecheck", "top2") for i := 0; i < len(xtop); i++ { if xtop[i].Op == ODCL || xtop[i].Op == OAS || xtop[i].Op == OAS2 { xtop[i] = typecheck(xtop[i], Etop) @@ -378,6 +393,8 @@ func Main() { // Phase 3: Type check function bodies. // Don't use range--typecheck can add closures to xtop. + timings.Start("fe", "typecheck", "func") + var fcount int64 for i := 0; i < len(xtop); i++ { if xtop[i].Op == ODCLFUNC || xtop[i].Op == OCLOSURE { Curfn = xtop[i] @@ -388,12 +405,15 @@ func Main() { if nerrors != 0 { Curfn.Nbody.Set(nil) // type errors; do not compile } + fcount++ } } + timings.AddEvent(fcount, "funcs") // Phase 4: Decide how to capture closed variables. // This needs to run before escape analysis, // because variables captured by value do not escape. + timings.Start("fe", "capturevars") for _, n := range xtop { if n.Op == ODCLFUNC && n.Func.Closure != nil { Curfn = n @@ -408,6 +428,7 @@ func Main() { } // Phase 5: Inlining + timings.Start("fe", "inlining") if Debug['l'] > 1 { // Typecheck imported function bodies if debug['l'] > 1, // otherwise lazily when used or re-exported. @@ -443,11 +464,13 @@ func Main() { // or else the stack copier will not update it. // Large values are also moved off stack in escape analysis; // because large values may contain pointers, it must happen early. + timings.Start("fe", "escapes") escapes(xtop) // Phase 7: Transform closure bodies to properly reference captured variables. // This needs to happen before walk, because closures must be transformed // before walk reaches a call of a closure. + timings.Start("fe", "xclosures") for _, n := range xtop { if n.Op == ODCLFUNC && n.Func.Closure != nil { Curfn = n @@ -459,11 +482,15 @@ func Main() { // Phase 8: Compile top level functions. // Don't use range--walk can add functions to xtop. + timings.Start("be", "compilefuncs") + fcount = 0 for i := 0; i < len(xtop); i++ { if xtop[i].Op == ODCLFUNC { funccompile(xtop[i]) + fcount++ } } + timings.AddEvent(fcount, "funcs") if nsavederrors+nerrors == 0 { fninit(xtop) @@ -474,6 +501,7 @@ func Main() { } // Phase 9: Check external declarations. + timings.Start("be", "externaldcls") for i, n := range externdcl { if n.Op == ONAME { externdcl[i] = typecheck(externdcl[i], Erv) @@ -484,8 +512,8 @@ func Main() { errorexit() } + timings.Start("be", "dumpobj") dumpobj() - if asmhdr != "" { dumpasmhdr() } @@ -495,6 +523,36 @@ func Main() { } Flusherrors() + timings.Stop() + + if benchfile != "" { + if err := writebench(benchfile); err != nil { + log.Fatalf("cannot write benchmark data: %v", err) + } + } +} + +func writebench(filename string) error { + f, err := os.OpenFile(filename, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0666) + if err != nil { + return err + } + + var buf bytes.Buffer + fmt.Fprintln(&buf, "commit:", obj.Getgoversion()) + fmt.Fprintln(&buf, "goos:", runtime.GOOS) + fmt.Fprintln(&buf, "goarch:", runtime.GOARCH) + timings.Write(&buf, "BenchmarkCompile:"+myimportpath+":") + + n, err := f.Write(buf.Bytes()) + if err != nil { + return err + } + if n != buf.Len() { + panic("bad writer") + } + + return f.Close() } var importMap = map[string]string{} diff --git a/src/cmd/compile/internal/gc/timings.go b/src/cmd/compile/internal/gc/timings.go new file mode 100644 index 0000000000..56b3899e2f --- /dev/null +++ b/src/cmd/compile/internal/gc/timings.go @@ -0,0 +1,235 @@ +// Copyright 2016 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 gc + +import ( + "fmt" + "io" + "strings" + "time" +) + +// Timings collects the execution times of labeled phases +// which are added trough a sequence of Start/Stop calls. +// Events may be associated with each phase via AddEvent. +type Timings struct { + list []timestamp + events map[int][]*event // lazily allocated +} + +type timestamp struct { + time time.Time + label string + start bool +} + +type event struct { + size int64 // count or amount of data processed (allocations, data size, lines, funcs, ...) + unit string // unit of size measure (count, MB, lines, funcs, ...) +} + +func (t *Timings) append(labels []string, start bool) { + t.list = append(t.list, timestamp{time.Now(), strings.Join(labels, ":"), start}) +} + +// Start marks the beginning of a new phase and implicitly stops the previous phase. +// The phase name is the colon-separated concatenation of the labels. +func (t *Timings) Start(labels ...string) { + t.append(labels, true) +} + +// Stop marks the end of a phase and implicitly starts a new phase. +// The labels are added to the labels of the ended phase. +func (t *Timings) Stop(labels ...string) { + t.append(labels, false) +} + +// AddEvent associates an event, i.e., a count, or an amount of data, +// with the most recently started or stopped phase; or the very first +// phase if Start or Stop hasn't been called yet. The unit specifies +// the unit of measurement (e.g., MB, lines, no. of funcs, etc.). +func (t *Timings) AddEvent(size int64, unit string) { + m := t.events + if m == nil { + m = make(map[int][]*event) + t.events = m + } + i := len(t.list) + if i > 0 { + i-- + } + m[i] = append(m[i], &event{size, unit}) +} + +// Write prints the phase times to w. +// The prefix is printed at the start of each line. +func (t *Timings) Write(w io.Writer, prefix string) { + if len(t.list) > 0 { + var lines lines + + // group of phases with shared non-empty label prefix + var group struct { + label string // label prefix + tot time.Duration // accumulated phase time + size int // number of phases collected in group + } + + // accumulated time between Stop/Start timestamps + var unaccounted time.Duration + + // process Start/Stop timestamps + pt := &t.list[0] // previous timestamp + tot := t.list[len(t.list)-1].time.Sub(pt.time) + for i := 1; i < len(t.list); i++ { + qt := &t.list[i] // current timestamp + dt := qt.time.Sub(pt.time) + + var label string + var events []*event + if pt.start { + // previous phase started + label = pt.label + events = t.events[i-1] + if qt.start { + // start implicitly ended previous phase; nothing to do + } else { + // stop ended previous phase; append stop labels, if any + if qt.label != "" { + label += ":" + qt.label + } + // events associated with stop replace prior events + if e := t.events[i]; e != nil { + events = e + } + } + } else { + // previous phase stopped + if qt.start { + // between a stopped and started phase; unaccounted time + unaccounted += dt + } else { + // previous stop implicitly started current phase + label = qt.label + events = t.events[i] + } + } + if label != "" { + // add phase to existing group, or start a new group + l := commonPrefix(group.label, label) + if group.size == 1 && l != "" || group.size > 1 && l == group.label { + // add to existing group + group.label = l + group.tot += dt + group.size++ + } else { + // start a new group + if group.size > 1 { + lines.add(prefix+group.label+"subtotal", 1, group.tot, tot, nil) + } + group.label = label + group.tot = dt + group.size = 1 + } + + // write phase + lines.add(prefix+label, 1, dt, tot, events) + } + + pt = qt + } + + if group.size > 1 { + lines.add(prefix+group.label+"subtotal", 1, group.tot, tot, nil) + } + + if unaccounted != 0 { + lines.add(prefix+"unaccounted", 1, unaccounted, tot, nil) + } + + lines.add(prefix+"total", 1, tot, tot, nil) + + lines.write(w) + } +} + +func commonPrefix(a, b string) string { + i := 0 + for i < len(a) && i < len(b) && a[i] == b[i] { + i++ + } + return a[:i] +} + +type lines [][]string + +func (lines *lines) add(label string, n int, dt, tot time.Duration, events []*event) { + var line []string + add := func(format string, args ...interface{}) { + line = append(line, fmt.Sprintf(format, args...)) + } + + add("%s", label) + add(" %d", n) + add(" %d ns/op", dt) + add(" %.2f %%", float64(dt)/float64(tot)*100) + + for _, e := range events { + add(" %d", e.size) + add(" %s", e.unit) + add(" %d", int64(float64(e.size)/dt.Seconds()+0.5)) + add(" %s/s", e.unit) + } + + *lines = append(*lines, line) +} + +func (lines lines) write(w io.Writer) { + // determine column widths and contents + var widths []int + var number []bool + for _, line := range lines { + for i, col := range line { + if i < len(widths) { + if len(col) > widths[i] { + widths[i] = len(col) + } + } else { + widths = append(widths, len(col)) + number = append(number, isnumber(col)) // first line determines column contents + } + } + } + + // make column widths a multiple of align for more stable output + const align = 1 // set to a value > 1 to enable + if align > 1 { + for i, w := range widths { + w += align - 1 + widths[i] = w - w%align + } + } + + // print lines taking column widths and contents into account + for _, line := range lines { + for i, col := range line { + format := "%-*s" + if number[i] { + format = "%*s" // numbers are right-aligned + } + fmt.Fprintf(w, format, widths[i], col) + } + fmt.Fprintln(w) + } +} + +func isnumber(s string) bool { + for _, ch := range s { + if ch <= ' ' { + continue // ignore leading whitespace + } + return '0' <= ch && ch <= '9' || ch == '.' || ch == '-' || ch == '+' + } + return false +}