src/cmd/compile/internal/gc/timings.go

// 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
}