Source file src/pkg/cmd/compile/internal/gc/timings.go

     1	// Copyright 2016 The Go Authors. All rights reserved.
     2	// Use of this source code is governed by a BSD-style
     3	// license that can be found in the LICENSE file.
     4	
     5	package gc
     6	
     7	import (
     8		"fmt"
     9		"io"
    10		"strings"
    11		"time"
    12	)
    13	
    14	// Timings collects the execution times of labeled phases
    15	// which are added trough a sequence of Start/Stop calls.
    16	// Events may be associated with each phase via AddEvent.
    17	type Timings struct {
    18		list   []timestamp
    19		events map[int][]*event // lazily allocated
    20	}
    21	
    22	type timestamp struct {
    23		time  time.Time
    24		label string
    25		start bool
    26	}
    27	
    28	type event struct {
    29		size int64  // count or amount of data processed (allocations, data size, lines, funcs, ...)
    30		unit string // unit of size measure (count, MB, lines, funcs, ...)
    31	}
    32	
    33	func (t *Timings) append(labels []string, start bool) {
    34		t.list = append(t.list, timestamp{time.Now(), strings.Join(labels, ":"), start})
    35	}
    36	
    37	// Start marks the beginning of a new phase and implicitly stops the previous phase.
    38	// The phase name is the colon-separated concatenation of the labels.
    39	func (t *Timings) Start(labels ...string) {
    40		t.append(labels, true)
    41	}
    42	
    43	// Stop marks the end of a phase and implicitly starts a new phase.
    44	// The labels are added to the labels of the ended phase.
    45	func (t *Timings) Stop(labels ...string) {
    46		t.append(labels, false)
    47	}
    48	
    49	// AddEvent associates an event, i.e., a count, or an amount of data,
    50	// with the most recently started or stopped phase; or the very first
    51	// phase if Start or Stop hasn't been called yet. The unit specifies
    52	// the unit of measurement (e.g., MB, lines, no. of funcs, etc.).
    53	func (t *Timings) AddEvent(size int64, unit string) {
    54		m := t.events
    55		if m == nil {
    56			m = make(map[int][]*event)
    57			t.events = m
    58		}
    59		i := len(t.list)
    60		if i > 0 {
    61			i--
    62		}
    63		m[i] = append(m[i], &event{size, unit})
    64	}
    65	
    66	// Write prints the phase times to w.
    67	// The prefix is printed at the start of each line.
    68	func (t *Timings) Write(w io.Writer, prefix string) {
    69		if len(t.list) > 0 {
    70			var lines lines
    71	
    72			// group of phases with shared non-empty label prefix
    73			var group struct {
    74				label string        // label prefix
    75				tot   time.Duration // accumulated phase time
    76				size  int           // number of phases collected in group
    77			}
    78	
    79			// accumulated time between Stop/Start timestamps
    80			var unaccounted time.Duration
    81	
    82			// process Start/Stop timestamps
    83			pt := &t.list[0] // previous timestamp
    84			tot := t.list[len(t.list)-1].time.Sub(pt.time)
    85			for i := 1; i < len(t.list); i++ {
    86				qt := &t.list[i] // current timestamp
    87				dt := qt.time.Sub(pt.time)
    88	
    89				var label string
    90				var events []*event
    91				if pt.start {
    92					// previous phase started
    93					label = pt.label
    94					events = t.events[i-1]
    95					if qt.start {
    96						// start implicitly ended previous phase; nothing to do
    97					} else {
    98						// stop ended previous phase; append stop labels, if any
    99						if qt.label != "" {
   100							label += ":" + qt.label
   101						}
   102						// events associated with stop replace prior events
   103						if e := t.events[i]; e != nil {
   104							events = e
   105						}
   106					}
   107				} else {
   108					// previous phase stopped
   109					if qt.start {
   110						// between a stopped and started phase; unaccounted time
   111						unaccounted += dt
   112					} else {
   113						// previous stop implicitly started current phase
   114						label = qt.label
   115						events = t.events[i]
   116					}
   117				}
   118				if label != "" {
   119					// add phase to existing group, or start a new group
   120					l := commonPrefix(group.label, label)
   121					if group.size == 1 && l != "" || group.size > 1 && l == group.label {
   122						// add to existing group
   123						group.label = l
   124						group.tot += dt
   125						group.size++
   126					} else {
   127						// start a new group
   128						if group.size > 1 {
   129							lines.add(prefix+group.label+"subtotal", 1, group.tot, tot, nil)
   130						}
   131						group.label = label
   132						group.tot = dt
   133						group.size = 1
   134					}
   135	
   136					// write phase
   137					lines.add(prefix+label, 1, dt, tot, events)
   138				}
   139	
   140				pt = qt
   141			}
   142	
   143			if group.size > 1 {
   144				lines.add(prefix+group.label+"subtotal", 1, group.tot, tot, nil)
   145			}
   146	
   147			if unaccounted != 0 {
   148				lines.add(prefix+"unaccounted", 1, unaccounted, tot, nil)
   149			}
   150	
   151			lines.add(prefix+"total", 1, tot, tot, nil)
   152	
   153			lines.write(w)
   154		}
   155	}
   156	
   157	func commonPrefix(a, b string) string {
   158		i := 0
   159		for i < len(a) && i < len(b) && a[i] == b[i] {
   160			i++
   161		}
   162		return a[:i]
   163	}
   164	
   165	type lines [][]string
   166	
   167	func (lines *lines) add(label string, n int, dt, tot time.Duration, events []*event) {
   168		var line []string
   169		add := func(format string, args ...interface{}) {
   170			line = append(line, fmt.Sprintf(format, args...))
   171		}
   172	
   173		add("%s", label)
   174		add("    %d", n)
   175		add("    %d ns/op", dt)
   176		add("    %.2f %%", float64(dt)/float64(tot)*100)
   177	
   178		for _, e := range events {
   179			add("    %d", e.size)
   180			add(" %s", e.unit)
   181			add("    %d", int64(float64(e.size)/dt.Seconds()+0.5))
   182			add(" %s/s", e.unit)
   183		}
   184	
   185		*lines = append(*lines, line)
   186	}
   187	
   188	func (lines lines) write(w io.Writer) {
   189		// determine column widths and contents
   190		var widths []int
   191		var number []bool
   192		for _, line := range lines {
   193			for i, col := range line {
   194				if i < len(widths) {
   195					if len(col) > widths[i] {
   196						widths[i] = len(col)
   197					}
   198				} else {
   199					widths = append(widths, len(col))
   200					number = append(number, isnumber(col)) // first line determines column contents
   201				}
   202			}
   203		}
   204	
   205		// make column widths a multiple of align for more stable output
   206		const align = 1 // set to a value > 1 to enable
   207		if align > 1 {
   208			for i, w := range widths {
   209				w += align - 1
   210				widths[i] = w - w%align
   211			}
   212		}
   213	
   214		// print lines taking column widths and contents into account
   215		for _, line := range lines {
   216			for i, col := range line {
   217				format := "%-*s"
   218				if number[i] {
   219					format = "%*s" // numbers are right-aligned
   220				}
   221				fmt.Fprintf(w, format, widths[i], col)
   222			}
   223			fmt.Fprintln(w)
   224		}
   225	}
   226	
   227	func isnumber(s string) bool {
   228		for _, ch := range s {
   229			if ch <= ' ' {
   230				continue // ignore leading whitespace
   231			}
   232			return '0' <= ch && ch <= '9' || ch == '.' || ch == '-' || ch == '+'
   233		}
   234		return false
   235	}
   236	

View as plain text