]> Cypherpunks repositories - gostls13.git/commitdiff
cmd/compile: add compiler phase timing
authorRobert Griesemer <gri@golang.org>
Fri, 24 Jun 2016 22:03:04 +0000 (15:03 -0700)
committerRobert Griesemer <gri@golang.org>
Wed, 17 Aug 2016 17:27:04 +0000 (17:27 +0000)
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 <mdempsky@google.com>
src/cmd/compile/internal/gc/main.go
src/cmd/compile/internal/gc/timings.go [new file with mode: 0644]

index b9a4ca3ec18ed52266ad4a2c4bb860dad8243b85..0f5e065310c9af5007cabeeb5d309833de58b254 100644 (file)
@@ -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 (file)
index 0000000..56b3899
--- /dev/null
@@ -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
+}