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