lib: Added v.io/x/lib/timing package.
Adds the timing package, which provides utilities for collecting
trees of timing information and dumping it with a nice format.
An example of the output format:
00:00:01.000 root 98.000s 00:01:39.000
00:00:01.000 * 9.000s 00:00:10.000
00:00:10.000 foo 45.000s 00:00:55.000
00:00:10.000 * 5.000s 00:00:15.000
00:00:15.000 foo1 22.000s 00:00:37.000
00:00:37.000 foo2 18.000s 00:00:55.000
00:00:55.000 bar 25.000s 00:01:20.000
00:01:20.000 baz 19.000s 00:01:39.000
Also add this support to the cmdline package via the -time flag,
and add some preliminary timings for "jiri update".
MultiPart: 3/4
Change-Id: Ic22476e7b75ad31756eec8b6554991dd885b7632
diff --git a/cmdline/.api b/cmdline/.api
index 3f3d2df..1d867d0 100644
--- a/cmdline/.api
+++ b/cmdline/.api
@@ -5,6 +5,8 @@
pkg cmdline, func Main(*Command)
pkg cmdline, func Parse(*Command, *Env, []string) (Runner, []string, error)
pkg cmdline, func ParseAndRun(*Command, *Env, []string) error
+pkg cmdline, method (*Env) TimerPop()
+pkg cmdline, method (*Env) TimerPush(string)
pkg cmdline, method (*Env) UsageErrorf(string, ...interface{}) error
pkg cmdline, method (ErrExitCode) Error() string
pkg cmdline, method (RunnerFunc) Run(*Env, []string) error
@@ -23,6 +25,7 @@
pkg cmdline, type Env struct, Stderr io.Writer
pkg cmdline, type Env struct, Stdin io.Reader
pkg cmdline, type Env struct, Stdout io.Writer
+pkg cmdline, type Env struct, Timer timing.Timer
pkg cmdline, type Env struct, Usage func(*Env, io.Writer)
pkg cmdline, type Env struct, Vars map[string]string
pkg cmdline, type ErrExitCode int
diff --git a/cmdline/cmdline.go b/cmdline/cmdline.go
index 1286f55..4194803 100644
--- a/cmdline/cmdline.go
+++ b/cmdline/cmdline.go
@@ -53,6 +53,7 @@
"v.io/x/lib/envvar"
_ "v.io/x/lib/metadata" // for the -metadata flag
+ "v.io/x/lib/timing"
)
// Command represents a single command in a command-line program. A program
@@ -121,9 +122,16 @@
func Main(root *Command) {
env := EnvFromOS()
err := ParseAndRun(root, env, os.Args[1:])
- os.Exit(ExitCode(err, env.Stderr))
+ code := ExitCode(err, env.Stderr)
+ if *flagTime && env.Timer != nil {
+ env.Timer.Finish()
+ timing.IntervalPrinter{}.Print(env.Stderr, env.Timer.Root())
+ }
+ os.Exit(code)
}
+var flagTime = flag.Bool("time", false, "Dump timing information to stderr before exiting the program.")
+
// Parse parses args against the command tree rooted at root down to a leaf
// command. A single path through the command tree is traversed, based on the
// sub-commands specified in args. Global and command-specific flags are parsed
@@ -156,6 +164,8 @@
// Parse merges root flags into flag.CommandLine and sets ContinueOnError, so
// that subsequent calls to flag.Parsed return true.
func Parse(root *Command, env *Env, args []string) (Runner, []string, error) {
+ env.TimerPush("cmdline parse")
+ defer env.TimerPop()
if globalFlags == nil {
// Initialize our global flags to a cleaned copy. We don't want the merging
// in parseFlags to contaminate the global flags, even if Parse is called
@@ -203,6 +213,8 @@
if err != nil {
return err
}
+ env.TimerPush("cmdline run")
+ defer env.TimerPop()
return runner.Run(env, args)
}
@@ -337,7 +349,7 @@
if cmd.LookPath {
// Look for a matching executable in PATH.
subCmd := cmd.Name + "-" + subName
- if lookPath(subCmd, env.pathDirs()) {
+ if lookPath(env, subCmd) {
return binaryRunner{subCmd, cmdPath}, subArgs, nil
}
}
@@ -464,6 +476,8 @@
}
func (b binaryRunner) Run(env *Env, args []string) error {
+ env.TimerPush("run " + b.subCmd)
+ defer env.TimerPop()
vars := envvar.CopyMap(env.Vars)
vars["CMDLINE_PREFIX"] = b.cmdPath
cmd := exec.Command(b.subCmd, args...)
@@ -481,10 +495,12 @@
return err
}
-// lookPath returns a boolean that indicates whether executable <name>
-// can be found in any of the given directories.
-func lookPath(name string, dirs []string) bool {
- for _, dir := range dirs {
+// lookPath returns true iff an executable with the given name can be found in
+// any of the PATH directories.
+func lookPath(env *Env, name string) bool {
+ env.TimerPush("lookpath " + name)
+ defer env.TimerPop()
+ for _, dir := range env.pathDirs() {
fileInfos, err := ioutil.ReadDir(dir)
if err != nil {
continue
@@ -501,11 +517,13 @@
return false
}
-// lookPathAll returns a deduped list of all executables found in the given
-// directories whose name starts with "<name>-", and where the name doesn't
-// match the given seen set. The seen set may be mutated by this function.
-func lookPathAll(name string, dirs []string, seen map[string]bool) (result []string) {
- for _, dir := range dirs {
+// lookPathAll returns a deduped list of all executables found in the PATH
+// directories whose name starts with "name-", and where the name doesn't match
+// the given seen set. The seen set may be mutated by this function.
+func lookPathAll(env *Env, name string, seen map[string]bool) (result []string) {
+ env.TimerPush("lookpathall " + name)
+ defer env.TimerPop()
+ for _, dir := range env.pathDirs() {
fileInfos, err := ioutil.ReadDir(dir)
if err != nil {
continue
diff --git a/cmdline/cmdline_test.go b/cmdline/cmdline_test.go
index dcc446e..2df7ea7 100644
--- a/cmdline/cmdline_test.go
+++ b/cmdline/cmdline_test.go
@@ -2770,6 +2770,8 @@
The global flags are:
-metadata=<just specify -metadata to activate>
Displays metadata for the program and exits.
+ -time=false
+ Dump timing information to stderr before exiting the program.
`,
},
{
@@ -2788,6 +2790,8 @@
The global flags are:
-metadata=<just specify -metadata to activate>
Displays metadata for the program and exits.
+ -time=false
+ Dump timing information to stderr before exiting the program.
`,
},
{
diff --git a/cmdline/env.go b/cmdline/env.go
index a669fd3..5a849f0 100644
--- a/cmdline/env.go
+++ b/cmdline/env.go
@@ -13,6 +13,7 @@
"v.io/x/lib/envvar"
"v.io/x/lib/textutil"
+ "v.io/x/lib/timing"
)
// EnvFromOS returns a new environment based on the operating system.
@@ -22,6 +23,7 @@
Stdout: os.Stdout,
Stderr: os.Stderr,
Vars: envvar.SliceToMap(os.Environ()),
+ Timer: timing.NewFullTimer("root"),
}
}
@@ -33,6 +35,7 @@
Stdout io.Writer
Stderr io.Writer
Vars map[string]string // Environment variables
+ Timer timing.Timer
// Usage is a function that prints usage information to w. Typically set by
// calls to Main or Parse to print usage of the leaf command.
@@ -46,7 +49,20 @@
return usageErrorf(e, e.Usage, format, args...)
}
-// Clone creates a deep copy of Env.
+// TimerPush calls e.Timer.Push(name), only if the Timer is non-nil.
+func (e *Env) TimerPush(name string) {
+ if e.Timer != nil {
+ e.Timer.Push(name)
+ }
+}
+
+// TimerPop calls e.Timer.Pop(), only if the Timer is non-nil.
+func (e *Env) TimerPop() {
+ if e.Timer != nil {
+ e.Timer.Pop()
+ }
+}
+
func (e *Env) clone() *Env {
return &Env{
Stdin: e.Stdin,
@@ -54,6 +70,7 @@
Stderr: e.Stderr,
Vars: envvar.CopyMap(e.Vars),
Usage: e.Usage,
+ Timer: e.Timer, // use the same timer for all operations
}
}
diff --git a/cmdline/help.go b/cmdline/help.go
index 9619e5f..6ee2879 100644
--- a/cmdline/help.go
+++ b/cmdline/help.go
@@ -126,7 +126,7 @@
if cmd.LookPath {
// Look for a matching executable in PATH.
extName := cmd.Name + "-" + subName
- if lookPath(extName, env.pathDirs()) {
+ if lookPath(env, extName) {
runner := binaryRunner{extName, cmdPath}
envCopy := env.clone()
envCopy.Vars["CMDLINE_STYLE"] = config.style.String()
@@ -225,7 +225,7 @@
usageAll(w, env, append(path, help), config, false)
}
if cmd.LookPath {
- extNames := lookPathAll(cmd.Name, env.pathDirs(), cmd.subNames())
+ extNames := lookPathAll(env, cmd.Name, cmd.subNames())
for _, extName := range extNames {
runner := binaryRunner{extName, cmdPath}
var buffer bytes.Buffer
@@ -277,6 +277,8 @@
// avoid printing redundant information (e.g. help command, global flags).
func usage(w *textutil.LineWriter, env *Env, path []*Command, config *helpConfig, firstCall bool) {
cmd, cmdPath := path[len(path)-1], pathName(config.prefix, path)
+ env.TimerPush("usage " + cmdPath)
+ defer env.TimerPop()
if config.style == styleShort {
fmt.Fprintln(w, cmd.Short)
return
@@ -305,7 +307,7 @@
}
var extChildren []string
if cmd.LookPath {
- extChildren = lookPathAll(cmd.Name, env.pathDirs(), cmd.subNames())
+ extChildren = lookPathAll(env, cmd.Name, cmd.subNames())
}
hasSubcommands := len(cmd.Children) > 0 || len(extChildren) > 0
if hasSubcommands {
diff --git a/timing/.api b/timing/.api
new file mode 100644
index 0000000..6356f10
--- /dev/null
+++ b/timing/.api
@@ -0,0 +1,45 @@
+pkg timing, func IntervalDuration(Interval, time.Time) time.Duration
+pkg timing, func NewCompactTimer(string) *CompactTimer
+pkg timing, func NewFullTimer(string) *FullTimer
+pkg timing, method (*CompactTimer) Finish()
+pkg timing, method (*CompactTimer) Pop()
+pkg timing, method (*CompactTimer) Push(string)
+pkg timing, method (*CompactTimer) Root() Interval
+pkg timing, method (*CompactTimer) String() string
+pkg timing, method (*FullTimer) Finish()
+pkg timing, method (*FullTimer) Pop()
+pkg timing, method (*FullTimer) Push(string)
+pkg timing, method (*FullTimer) Root() Interval
+pkg timing, method (*FullTimer) String() string
+pkg timing, method (FullInterval) Child(int) Interval
+pkg timing, method (FullInterval) End() time.Time
+pkg timing, method (FullInterval) Name() string
+pkg timing, method (FullInterval) NumChild() int
+pkg timing, method (FullInterval) Start() time.Time
+pkg timing, method (FullInterval) String() string
+pkg timing, method (IntervalPrinter) Print(io.Writer, Interval) error
+pkg timing, type CompactTimer struct
+pkg timing, type FullInterval struct
+pkg timing, type FullInterval struct, Children []FullInterval
+pkg timing, type FullInterval struct, EndTime time.Time
+pkg timing, type FullInterval struct, Label string
+pkg timing, type FullInterval struct, StartTime time.Time
+pkg timing, type FullTimer struct
+pkg timing, type FullTimer struct, FullRoot FullInterval
+pkg timing, type Interval interface { Child, End, Name, NumChild, Start, String }
+pkg timing, type Interval interface, Child(int) Interval
+pkg timing, type Interval interface, End() time.Time
+pkg timing, type Interval interface, Name() string
+pkg timing, type Interval interface, NumChild() int
+pkg timing, type Interval interface, Start() time.Time
+pkg timing, type Interval interface, String() string
+pkg timing, type IntervalPrinter struct
+pkg timing, type IntervalPrinter struct, Indent int
+pkg timing, type IntervalPrinter struct, MinGap time.Duration
+pkg timing, type IntervalPrinter struct, TimeFormat string
+pkg timing, type Timer interface { Finish, Pop, Push, Root, String }
+pkg timing, type Timer interface, Finish()
+pkg timing, type Timer interface, Pop()
+pkg timing, type Timer interface, Push(string)
+pkg timing, type Timer interface, Root() Interval
+pkg timing, type Timer interface, String() string
diff --git a/timing/compact_timer.go b/timing/compact_timer.go
new file mode 100644
index 0000000..6faf513
--- /dev/null
+++ b/timing/compact_timer.go
@@ -0,0 +1,173 @@
+// Copyright 2015 The Vanadium 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 timing
+
+import (
+ "bytes"
+ "time"
+)
+
+// CompactTimer implements Timer with a memory-efficient implementation.
+// Timestamps are only recorded on calls to Push and Finish; the assumption is
+// that there is typically a very small delay between a call to Pop and a
+// subsequent call to Push or Finish, so the Pop time doesn't need to be
+// recorded.
+//
+// CompactTimer performs fewer memory allocations and is faster than FullTimer
+// for push and pop, but doesn't collect actual end times.
+type CompactTimer struct {
+ points []compactPoint
+ depth int
+ zero time.Time
+}
+
+// compactPoint represents a single interval, taking advantage of the fact that
+// all intervals are required to be disjoint, and also assuming that all
+// intervals are adjacent to each other. Thus instead of holding both a start
+// and end time, it only holds a single NextStart time, represented as a delta
+// from the zero time for further space savings.
+//
+// The NextStart time represents the time that the next interval starts. If the
+// next interval is at the same or smaller depth, this is also the end time for
+// the current interval.
+//
+// The interesting logic is in Push; we rely on each Push call to update
+// NextStart for the previous entry, and to create a new entry. This also lets
+// us keep a single slice of points in CompactTimer, which is more memory
+// efficient than the tree of slices used in FullInterval.
+//
+// The trade-off we make for the memory efficiency and simple Push/Pop/Finish
+// logic is that we need to do more work in compactInterval to piece-together
+// the resulting time intervals.
+type compactPoint struct {
+ Label string
+ Depth int
+ NextStart time.Duration
+}
+
+const invalidNext = time.Duration(-1 << 63)
+
+// NewCompactTimer returns a new CompactTimer, with the root interval
+// initialized to the given name.
+func NewCompactTimer(name string) *CompactTimer {
+ return &CompactTimer{
+ points: []compactPoint{{
+ Label: name,
+ Depth: 0,
+ NextStart: invalidNext,
+ }},
+ zero: nowFunc(),
+ }
+}
+
+// Push implements the Timer.Push method.
+func (t *CompactTimer) Push(name string) {
+ t.depth++
+ t.points[len(t.points)-1].NextStart = nowFunc().Sub(t.zero)
+ t.points = append(t.points, compactPoint{
+ Label: name,
+ Depth: t.depth,
+ NextStart: invalidNext,
+ })
+}
+
+// Pop implements the Timer.Pop method.
+func (t *CompactTimer) Pop() {
+ if t.depth > 0 {
+ t.depth--
+ }
+}
+
+// Finish implements the Timer.Finish method.
+func (t *CompactTimer) Finish() {
+ t.depth = 0
+ t.points[len(t.points)-1].NextStart = nowFunc().Sub(t.zero)
+}
+
+// String returns a formatted string describing the tree of time intervals.
+func (t *CompactTimer) String() string {
+ return t.Root().String()
+}
+
+// Root returns the root interval.
+func (t *CompactTimer) Root() Interval {
+ return compactInterval{
+ points: t.points,
+ children: computeCompactChildren(t.points),
+ zero: t.zero,
+ start: t.zero,
+ }
+}
+
+// compactInterval implements Interval using the underlying slice of points
+// recorded by CompactTimer. The interesting method is Child, where we
+// re-compute the points to use for the next compactInterval.
+type compactInterval struct {
+ points []compactPoint
+ children []int
+ zero, start time.Time
+}
+
+// computeCompactChildren returns the indices in points that are immediate
+// children of the first point. Points must be a subtree rooted at the first
+// point; the depth of every point in points[1:] must be greater than the depth
+// of the first point.
+func computeCompactChildren(points []compactPoint) (children []int) {
+ if len(points) < 2 {
+ return
+ }
+ target := points[0].Depth + 1
+ for index := 1; index < len(points); index++ {
+ if point := points[index]; point.Depth == target {
+ children = append(children, index)
+ }
+ }
+ return
+}
+
+// Name returns the name of the interval.
+func (i compactInterval) Name() string { return i.points[0].Label }
+
+// Start returns the start time of the interval.
+func (i compactInterval) Start() time.Time { return i.start }
+
+// End returns the end time of the interval, or zero if the interval hasn't
+// ended yet (i.e. it's still open).
+func (i compactInterval) End() time.Time {
+ if next := i.points[len(i.points)-1].NextStart; next != invalidNext {
+ return i.zero.Add(next)
+ }
+ return time.Time{}
+}
+
+// NumChild returns the number of children contained in this interval.
+func (i compactInterval) NumChild() int { return len(i.children) }
+
+// Child returns the child interval at the given index. Valid children are in
+// the range [0, NumChild).
+func (i compactInterval) Child(index int) Interval {
+ beg := i.children[index]
+ var end int
+ if index+1 < len(i.children) {
+ end = i.children[index+1]
+ } else {
+ end = len(i.points)
+ }
+ points := i.points[beg:end]
+ return compactInterval{
+ points: points,
+ children: computeCompactChildren(points),
+ zero: i.zero,
+ start: i.zero.Add(i.points[beg-1].NextStart),
+ }
+}
+
+// String returns a formatted string describing the tree starting with the
+// given interval.
+func (i compactInterval) String() string {
+ var buf bytes.Buffer
+ IntervalPrinter{}.Print(&buf, i)
+ return buf.String()
+}
diff --git a/timing/full_timer.go b/timing/full_timer.go
new file mode 100644
index 0000000..20f18e0
--- /dev/null
+++ b/timing/full_timer.go
@@ -0,0 +1,117 @@
+// Copyright 2015 The Vanadium 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 timing
+
+import (
+ "bytes"
+ "time"
+)
+
+// FullInterval implements Interval with a direct data mapping; each
+// FullInterval represents a node in the FullTimer tree.
+type FullInterval struct {
+ Label string
+ StartTime, EndTime time.Time
+ Children []FullInterval
+}
+
+// Name returns the name of the interval.
+func (i FullInterval) Name() string { return i.Label }
+
+// Start returns the start time of the interval.
+func (i FullInterval) Start() time.Time { return i.StartTime }
+
+// End returns the end time of the interval, or zero if the interval hasn't
+// ended yet (i.e. it's still open).
+func (i FullInterval) End() time.Time { return i.EndTime }
+
+// NumChild returns the number of children contained in this interval.
+func (i FullInterval) NumChild() int { return len(i.Children) }
+
+// Child returns the child interval at the given index. Valid children are in
+// the range [0, NumChild).
+func (i FullInterval) Child(index int) Interval { return i.Children[index] }
+
+// String returns a formatted string describing the tree starting with the
+// given interval.
+func (i FullInterval) String() string {
+ var buf bytes.Buffer
+ IntervalPrinter{}.Print(&buf, i)
+ return buf.String()
+}
+
+// FullTimer implements Timer, using FullInterval to represent the tree of
+// intervals. Timestamps are recorded on each call to Push, Pop and Finish.
+//
+// FullTimer performs more memory allocations and is slower than CompactTimer
+// for push and pop, but collects actual start and end times for all intervals.
+type FullTimer struct {
+ // FullRoot holds the root of the time interval tree.
+ FullRoot FullInterval
+
+ // The stack holds the path through the interval tree leading to the current
+ // interval. This makes it easy to determine the current interval, as well as
+ // pop up to the parent interval. The root is never held in the stack.
+ //
+ // There is a subtlely here, since we're keeping a stack of pointers; we must
+ // be careful not to invalidate any pointers. E.g. given an Interval X with a
+ // child Y, we will invalidate the pointer to Y when we append to X.Children,
+ // if a new underlying array is created. This never occurs since the stack
+ // never contains a pointer to Y when appending to X.Children.
+ stack []*FullInterval
+}
+
+// NewFullTimer returns a new FullTimer, with the root interval initialized to
+// the given name.
+func NewFullTimer(name string) *FullTimer {
+ return &FullTimer{
+ FullRoot: FullInterval{Label: name, StartTime: nowFunc()},
+ }
+}
+
+// Push implements the Timer.Push method.
+func (t *FullTimer) Push(name string) {
+ var current *FullInterval
+ if len(t.stack) == 0 {
+ // Unset the root end time, to handle Push after Finish.
+ t.FullRoot.EndTime = time.Time{}
+ current = &t.FullRoot
+ } else {
+ current = t.stack[len(t.stack)-1]
+ }
+ push := FullInterval{Label: name, StartTime: nowFunc()}
+ current.Children = append(current.Children, push)
+ t.stack = append(t.stack, ¤t.Children[len(current.Children)-1])
+}
+
+// Pop implements the Timer.Pop method.
+func (t *FullTimer) Pop() {
+ if len(t.stack) == 0 {
+ return // Pop on the root does nothing.
+ }
+ last := len(t.stack) - 1
+ t.stack[last].EndTime = nowFunc()
+ t.stack = t.stack[:last]
+}
+
+// Finish implements the Timer.Finish method.
+func (t *FullTimer) Finish() {
+ end := nowFunc()
+ t.FullRoot.EndTime = end
+ for _, interval := range t.stack {
+ interval.EndTime = end
+ }
+ t.stack = t.stack[:0]
+}
+
+// Root returns the root interval.
+func (t *FullTimer) Root() Interval {
+ return t.FullRoot
+}
+
+// String returns a formatted string describing the tree of time intervals.
+func (t *FullTimer) String() string {
+ return t.FullRoot.String()
+}
diff --git a/timing/timer.go b/timing/timer.go
new file mode 100644
index 0000000..2819711
--- /dev/null
+++ b/timing/timer.go
@@ -0,0 +1,219 @@
+// Copyright 2015 The Vanadium 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 timing implements utilities for tracking timing information.
+package timing
+
+import (
+ "fmt"
+ "io"
+ "strings"
+ "time"
+)
+
+// nowFunc is used rather than direct calls to time.Now to allow tests to inject
+// different clock functions.
+var nowFunc = time.Now
+
+// Interval represents a named time interval and its children. The children are
+// non-overlapping and ordered from earliest to latest. The start and end time
+// of a given interval always completely cover all of its children. Put another
+// way, intervals form a strictly hierarchical tree.
+type Interval interface {
+ // Name returns the name of the interval.
+ Name() string
+
+ // Start returns the start time of the interval.
+ Start() time.Time
+
+ // End returns the end time of the interval, or zero if the interval hasn't
+ // ended yet (i.e. it's still open).
+ End() time.Time
+
+ // NumChild returns the number of children contained in this interval.
+ NumChild() int
+
+ // Child returns the child interval at the given index. Valid children are in
+ // the range [0, NumChild).
+ Child(index int) Interval
+
+ // String returns a formatted string describing the tree starting with the
+ // given interval.
+ String() string
+}
+
+// Timer provides support for tracking a tree of hierarchical time intervals.
+// If you need to track overlapping time intervals, simply use separate Timers.
+//
+// Timer maintains a notion of a current interval, initialized to the root. The
+// tree of intervals is constructed by push and pop operations, which add and
+// update intervals to the tree, while updating the currently referenced
+// interval. Finish should be called to finish all timing.
+type Timer interface {
+ // Push appends a child with the given name and an open interval to current,
+ // and updates the current interval to refer to the newly created child.
+ Push(name string)
+
+ // Pop closes the current interval, and updates the current interval to refer
+ // to its parent. Pop does nothing if the current interval is the root.
+ Pop()
+
+ // Finish finishes all timing, closing all intervals including the root.
+ Finish()
+
+ // Root returns the root interval.
+ Root() Interval
+
+ // String returns a formatted string describing the tree of time intervals.
+ String() string
+}
+
+// IntervalDuration returns the elapsed time between i.start and i.end if i.end
+// is nonzero, otherwise it returns the elapsed time between i.start and now.
+// Now is passed in explicitly to allow the caller to use the same now time when
+// computing the duration of many intervals. E.g. the same now time is used by
+// the IntervalPrinter to compute the duration of all intervals, to ensure
+// consistent output.
+func IntervalDuration(i Interval, now time.Time) time.Duration {
+ start, end := i.Start(), i.End()
+ if end.IsZero() {
+ return now.Sub(start)
+ }
+ return end.Sub(start)
+}
+
+// IntervalPrinter is a pretty-printer for Intervals. Example output:
+//
+// 00:00:01.000 root 98.000s 00:01:39.000
+// 00:00:01.000 * 9.000s 00:00:10.000
+// 00:00:10.000 foo 45.000s 00:00:55.000
+// 00:00:10.000 * 5.000s 00:00:15.000
+// 00:00:15.000 foo1 22.000s 00:00:37.000
+// 00:00:37.000 foo2 18.000s 00:00:55.000
+// 00:00:55.000 bar 25.000s 00:01:20.000
+// 00:01:20.000 baz 19.000s 00:01:39.000
+type IntervalPrinter struct {
+ // TimeFormat is passed to time.Format to format the start and end times.
+ // Defaults to "15:04:05.000" if the value is empty.
+ TimeFormat string
+ // Indent is the number of spaces to indent each successive depth in the tree.
+ // Defaults to 3 spaces if the value is 0; set to a negative value for no
+ // indent.
+ Indent int
+ // MinGap is the minimum duration for gaps to be shown between successive
+ // entries; only gaps that are larger than this threshold will be shown.
+ // Defaults to 1 millisecond if the value is 0; set to a negative duration to
+ // show all gaps.
+ MinGap time.Duration
+}
+
+// Print writes formatted output to w representing the tree rooted at i.
+func (p IntervalPrinter) Print(w io.Writer, i Interval) error {
+ // Set default options for zero fields.
+ if p.TimeFormat == "" {
+ p.TimeFormat = "15:04:05.000"
+ }
+ switch {
+ case p.Indent < 0:
+ p.Indent = 0
+ case p.Indent == 0:
+ p.Indent = 3
+ }
+ switch {
+ case p.MinGap < 0:
+ p.MinGap = 0
+ case p.MinGap == 0:
+ p.MinGap = time.Millisecond
+ }
+ return p.print(w, i, p.collectPrintStats(i), i.Start(), 0)
+}
+
+func (p IntervalPrinter) print(w io.Writer, i Interval, stats *printStats, prevEnd time.Time, depth int) error {
+ // Print gap before children, if a gap exists.
+ if gap := i.Start().Sub(prevEnd); gap >= p.MinGap {
+ if err := p.row(w, "*", prevEnd, i.Start(), gap, stats, depth); err != nil {
+ return err
+ }
+ }
+ // Print the current interval.
+ if err := p.row(w, i.Name(), i.Start(), i.End(), IntervalDuration(i, stats.Now), stats, depth); err != nil {
+ return err
+ }
+ // Print children recursively.
+ for child := 0; child < i.NumChild(); child++ {
+ prevEnd = i.Start()
+ if child > 0 {
+ prevEnd = i.Child(child - 1).End()
+ }
+ if err := p.print(w, i.Child(child), stats, prevEnd, depth+1); err != nil {
+ return err
+ }
+ }
+ // Print gap after children, if a gap exists.
+ if last := i.NumChild() - 1; last >= 0 {
+ lastChild := i.Child(last)
+ if gap := i.End().Sub(lastChild.End()); gap >= p.MinGap {
+ if err := p.row(w, "*", lastChild.End(), i.End(), gap, stats, depth+1); err != nil {
+ return err
+ }
+ }
+ }
+ return nil
+}
+
+func (p IntervalPrinter) row(w io.Writer, name string, start, end time.Time, dur time.Duration, stats *printStats, depth int) error {
+ pad := strings.Repeat(" ", p.Indent*depth)
+ pad2 := strings.Repeat(" ", p.Indent*(stats.MaxDepth-depth))
+ endStr := stats.NowLabel
+ if !end.IsZero() {
+ endStr = end.Format(p.TimeFormat)
+ }
+ _, err := fmt.Fprintf(w, "%s %-*s %s%*.3fs%s %s\n", start.Format(p.TimeFormat), stats.NameWidth, pad+name, pad, stats.DurationWidth, float64(dur)/float64(time.Second), pad2, endStr)
+ return err
+}
+
+// collectPrintStats performs a walk through the tree rooted at i, collecting
+// statistics along the way, to help align columns in the output.
+func (p IntervalPrinter) collectPrintStats(i Interval) *printStats {
+ stats := &printStats{
+ Now: nowFunc(),
+ NameWidth: 1,
+ NowLabel: strings.Repeat("-", len(p.TimeFormat)-3) + "now",
+ }
+ stats.collect(i, p.Indent, i.Start(), 0)
+ dur := fmt.Sprintf("%.3f", float64(stats.MaxDuration)/float64(time.Second))
+ stats.DurationWidth = len(dur)
+ return stats
+}
+
+type printStats struct {
+ Now time.Time
+ NowLabel string
+ NameWidth int
+ MaxDuration time.Duration
+ DurationWidth int
+ MaxDepth int
+}
+
+func (s *printStats) collect(i Interval, indent int, prevEnd time.Time, depth int) {
+ if x := len(i.Name()) + indent*depth; x > s.NameWidth {
+ s.NameWidth = x
+ }
+ if x := i.Start().Sub(prevEnd); x > s.MaxDuration {
+ s.MaxDuration = x
+ }
+ if x := IntervalDuration(i, s.Now); x > s.MaxDuration {
+ s.MaxDuration = x
+ }
+ if x := depth; x > s.MaxDepth {
+ s.MaxDepth = x
+ }
+ for child := 0; child < i.NumChild(); child++ {
+ prevEnd = i.Start()
+ if child > 0 {
+ prevEnd = i.Child(child - 1).End()
+ }
+ s.collect(i.Child(child), indent, prevEnd, depth+1)
+ }
+}
diff --git a/timing/timer_test.go b/timing/timer_test.go
new file mode 100644
index 0000000..122587d
--- /dev/null
+++ b/timing/timer_test.go
@@ -0,0 +1,522 @@
+// Copyright 2015 The Vanadium 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 timing
+
+import (
+ "bytes"
+ "fmt"
+ "math/rand"
+ "strings"
+ "testing"
+ "time"
+)
+
+func sec(d int) time.Time {
+ return time.Time{}.Add(time.Second * time.Duration(d))
+}
+
+// fakeNow is a simulated clock where now is set manually.
+type fakeNow struct{ now int }
+
+func (f *fakeNow) Now() time.Time { return sec(f.now) }
+
+// stepNow is a simulated clock where now increments in 1 second steps.
+type stepNow struct{ now int }
+
+func (s *stepNow) Now() time.Time {
+ s.now++
+ return sec(s.now)
+}
+
+type (
+ // op represents the operations that can be performed on a Timer, with a fake
+ // clock. This makes it easy to construct test cases.
+ op interface {
+ run(f *fakeNow, t Timer)
+ }
+ push struct {
+ now int
+ name string
+ }
+ pop struct {
+ now int
+ }
+ finish struct {
+ now int
+ }
+)
+
+func (x push) run(f *fakeNow, t Timer) {
+ f.now = x.now
+ t.Push(x.name)
+}
+func (x pop) run(f *fakeNow, t Timer) {
+ f.now = x.now
+ t.Pop()
+}
+func (x finish) run(f *fakeNow, t Timer) {
+ f.now = x.now
+ t.Finish()
+}
+
+type kind int
+
+const (
+ kindFull kind = iota
+ kindCompact
+)
+
+func (k kind) NewTimer(name string) Timer {
+ switch k {
+ case kindFull:
+ return NewFullTimer(name)
+ default:
+ return NewCompactTimer(name)
+ }
+}
+
+func (k kind) String() string {
+ switch k {
+ case kindFull:
+ return "FullTimer"
+ default:
+ return "CompactTimer"
+ }
+}
+
+func TestTimer(t *testing.T) {
+ tests := []struct {
+ ops []op
+ full, compact *FullInterval
+ fullStr, compactStr string
+ }{
+ {
+ nil,
+ &FullInterval{"root", sec(1), sec(0), nil}, nil,
+ `
+00:00:01.000 root 999.000s ---------now
+`, ``,
+ },
+ {
+ []op{pop{123}},
+ &FullInterval{"root", sec(1), sec(0), nil}, nil,
+ `
+00:00:01.000 root 999.000s ---------now
+`, ``,
+ },
+ {
+ []op{finish{99}},
+ &FullInterval{"root", sec(1), sec(99), nil}, nil,
+ `
+00:00:01.000 root 98.000s 00:01:39.000
+`, ``,
+ },
+ {
+ []op{finish{99}, pop{123}},
+ &FullInterval{"root", sec(1), sec(99), nil}, nil,
+ `
+00:00:01.000 root 98.000s 00:01:39.000
+`, ``,
+ },
+ {
+ []op{push{10, "abc"}},
+ &FullInterval{"root", sec(1), sec(0),
+ []FullInterval{{"abc", sec(10), sec(0), nil}}}, nil,
+ `
+00:00:01.000 root 999.000s ---------now
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 abc 990.000s ---------now
+`, ``,
+ },
+ {
+ []op{push{10, "abc"}, finish{99}},
+ &FullInterval{"root", sec(1), sec(99),
+ []FullInterval{{"abc", sec(10), sec(99), nil}}}, nil,
+ `
+00:00:01.000 root 98.000s 00:01:39.000
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 abc 89.000s 00:01:39.000
+`, ``,
+ },
+ {
+ []op{push{10, "abc"}, pop{20}, finish{99}},
+ &FullInterval{"root", sec(1), sec(99),
+ []FullInterval{{"abc", sec(10), sec(20), nil}}},
+ &FullInterval{"root", sec(1), sec(99),
+ []FullInterval{{"abc", sec(10), sec(99), nil}}},
+ `
+00:00:01.000 root 98.000s 00:01:39.000
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 abc 10.000s 00:00:20.000
+00:00:20.000 * 79.000s 00:01:39.000
+`,
+ `
+00:00:01.000 root 98.000s 00:01:39.000
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 abc 89.000s 00:01:39.000
+`,
+ },
+ {
+ []op{push{10, "A1"}, push{20, "A1_1"}},
+ &FullInterval{"root", sec(1), sec(0),
+ []FullInterval{{"A1", sec(10), sec(0),
+ []FullInterval{{"A1_1", sec(20), sec(0), nil}}}}}, nil,
+ `
+00:00:01.000 root 999.000s ---------now
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 A1 990.000s ---------now
+00:00:10.000 * 10.000s 00:00:20.000
+00:00:20.000 A1_1 980.000s ---------now
+`, ``,
+ },
+ {
+ []op{push{10, "A1"}, push{20, "A1_1"}, finish{99}},
+ &FullInterval{"root", sec(1), sec(99),
+ []FullInterval{{"A1", sec(10), sec(99),
+ []FullInterval{{"A1_1", sec(20), sec(99), nil}}}}}, nil,
+ `
+00:00:01.000 root 98.000s 00:01:39.000
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 A1 89.000s 00:01:39.000
+00:00:10.000 * 10.000s 00:00:20.000
+00:00:20.000 A1_1 79.000s 00:01:39.000
+`, ``,
+ },
+ {
+ []op{push{10, "A1"}, push{20, "A1_1"}, pop{30}, finish{99}},
+ &FullInterval{"root", sec(1), sec(99),
+ []FullInterval{{"A1", sec(10), sec(99),
+ []FullInterval{{"A1_1", sec(20), sec(30), nil}}}}},
+ &FullInterval{"root", sec(1), sec(99),
+ []FullInterval{{"A1", sec(10), sec(99),
+ []FullInterval{{"A1_1", sec(20), sec(99), nil}}}}},
+ `
+00:00:01.000 root 98.000s 00:01:39.000
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 A1 89.000s 00:01:39.000
+00:00:10.000 * 10.000s 00:00:20.000
+00:00:20.000 A1_1 10.000s 00:00:30.000
+00:00:30.000 * 69.000s 00:01:39.000
+`,
+ `
+00:00:01.000 root 98.000s 00:01:39.000
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 A1 89.000s 00:01:39.000
+00:00:10.000 * 10.000s 00:00:20.000
+00:00:20.000 A1_1 79.000s 00:01:39.000
+`,
+ },
+ {
+ []op{push{10, "A1"}, push{20, "A1_1"}, pop{30}, pop{40}, finish{99}},
+ &FullInterval{"root", sec(1), sec(99),
+ []FullInterval{{"A1", sec(10), sec(40),
+ []FullInterval{{"A1_1", sec(20), sec(30), nil}}}}},
+ &FullInterval{"root", sec(1), sec(99),
+ []FullInterval{{"A1", sec(10), sec(99),
+ []FullInterval{{"A1_1", sec(20), sec(99), nil}}}}},
+ `
+00:00:01.000 root 98.000s 00:01:39.000
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 A1 30.000s 00:00:40.000
+00:00:10.000 * 10.000s 00:00:20.000
+00:00:20.000 A1_1 10.000s 00:00:30.000
+00:00:30.000 * 10.000s 00:00:40.000
+00:00:40.000 * 59.000s 00:01:39.000
+`,
+ `
+00:00:01.000 root 98.000s 00:01:39.000
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 A1 89.000s 00:01:39.000
+00:00:10.000 * 10.000s 00:00:20.000
+00:00:20.000 A1_1 79.000s 00:01:39.000
+`,
+ },
+ {
+ []op{push{10, "A1"}, push{20, "A1_1"}, finish{30}, push{40, "B1"}},
+ &FullInterval{"root", sec(1), sec(0), []FullInterval{
+ {"A1", sec(10), sec(30), []FullInterval{
+ {"A1_1", sec(20), sec(30), nil}}},
+ {"B1", sec(40), sec(0), nil}}},
+ &FullInterval{"root", sec(1), sec(0), []FullInterval{
+ {"A1", sec(10), sec(40), []FullInterval{
+ {"A1_1", sec(20), sec(40), nil}}},
+ {"B1", sec(40), sec(0), nil}}},
+ `
+00:00:01.000 root 999.000s ---------now
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 A1 20.000s 00:00:30.000
+00:00:10.000 * 10.000s 00:00:20.000
+00:00:20.000 A1_1 10.000s 00:00:30.000
+00:00:30.000 * 10.000s 00:00:40.000
+00:00:40.000 B1 960.000s ---------now
+`,
+ `
+00:00:01.000 root 999.000s ---------now
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 A1 30.000s 00:00:40.000
+00:00:10.000 * 10.000s 00:00:20.000
+00:00:20.000 A1_1 20.000s 00:00:40.000
+00:00:40.000 B1 960.000s ---------now
+`,
+ },
+ {
+ []op{push{10, "A1"}, push{20, "A1_1"}, finish{30}, push{40, "B1"}, finish{99}},
+ &FullInterval{"root", sec(1), sec(99), []FullInterval{
+ {"A1", sec(10), sec(30), []FullInterval{
+ {"A1_1", sec(20), sec(30), nil}}},
+ {"B1", sec(40), sec(99), nil}}},
+ &FullInterval{"root", sec(1), sec(99), []FullInterval{
+ {"A1", sec(10), sec(40), []FullInterval{
+ {"A1_1", sec(20), sec(40), nil}}},
+ {"B1", sec(40), sec(99), nil}}},
+ `
+00:00:01.000 root 98.000s 00:01:39.000
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 A1 20.000s 00:00:30.000
+00:00:10.000 * 10.000s 00:00:20.000
+00:00:20.000 A1_1 10.000s 00:00:30.000
+00:00:30.000 * 10.000s 00:00:40.000
+00:00:40.000 B1 59.000s 00:01:39.000
+`,
+ `
+00:00:01.000 root 98.000s 00:01:39.000
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 A1 30.000s 00:00:40.000
+00:00:10.000 * 10.000s 00:00:20.000
+00:00:20.000 A1_1 20.000s 00:00:40.000
+00:00:40.000 B1 59.000s 00:01:39.000
+`,
+ },
+ {
+ []op{push{10, "foo"}, push{15, "foo1"}, pop{37}, push{37, "foo2"}, pop{55}, pop{55}, push{55, "bar"}, pop{80}, push{80, "baz"}, pop{99}, finish{99}},
+ &FullInterval{
+ "root", sec(1), sec(99), []FullInterval{
+ {"foo", sec(10), sec(55), []FullInterval{
+ {"foo1", sec(15), sec(37), nil},
+ {"foo2", sec(37), sec(55), nil},
+ }},
+ {"bar", sec(55), sec(80), nil},
+ {"baz", sec(80), sec(99), nil}}}, nil,
+ `
+00:00:01.000 root 98.000s 00:01:39.000
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 foo 45.000s 00:00:55.000
+00:00:10.000 * 5.000s 00:00:15.000
+00:00:15.000 foo1 22.000s 00:00:37.000
+00:00:37.000 foo2 18.000s 00:00:55.000
+00:00:55.000 bar 25.000s 00:01:20.000
+00:01:20.000 baz 19.000s 00:01:39.000
+`, ``,
+ },
+ {
+ []op{push{10, "foo"}, push{15, "foo1"}, pop{30}, push{37, "foo2"}, pop{50}, pop{53}, push{55, "bar"}, pop{75}, push{80, "baz"}, pop{90}, finish{99}},
+ &FullInterval{
+ "root", sec(1), sec(99), []FullInterval{
+ {"foo", sec(10), sec(53), []FullInterval{
+ {"foo1", sec(15), sec(30), nil},
+ {"foo2", sec(37), sec(50), nil},
+ }},
+ {"bar", sec(55), sec(75), nil},
+ {"baz", sec(80), sec(90), nil}}},
+ &FullInterval{
+ "root", sec(1), sec(99), []FullInterval{
+ {"foo", sec(10), sec(55), []FullInterval{
+ {"foo1", sec(15), sec(37), nil},
+ {"foo2", sec(37), sec(55), nil},
+ }},
+ {"bar", sec(55), sec(80), nil},
+ {"baz", sec(80), sec(99), nil}}},
+ `
+00:00:01.000 root 98.000s 00:01:39.000
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 foo 43.000s 00:00:53.000
+00:00:10.000 * 5.000s 00:00:15.000
+00:00:15.000 foo1 15.000s 00:00:30.000
+00:00:30.000 * 7.000s 00:00:37.000
+00:00:37.000 foo2 13.000s 00:00:50.000
+00:00:50.000 * 3.000s 00:00:53.000
+00:00:53.000 * 2.000s 00:00:55.000
+00:00:55.000 bar 20.000s 00:01:15.000
+00:01:15.000 * 5.000s 00:01:20.000
+00:01:20.000 baz 10.000s 00:01:30.000
+00:01:30.000 * 9.000s 00:01:39.000
+`,
+ `
+00:00:01.000 root 98.000s 00:01:39.000
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 foo 45.000s 00:00:55.000
+00:00:10.000 * 5.000s 00:00:15.000
+00:00:15.000 foo1 22.000s 00:00:37.000
+00:00:37.000 foo2 18.000s 00:00:55.000
+00:00:55.000 bar 25.000s 00:01:20.000
+00:01:20.000 baz 19.000s 00:01:39.000
+`,
+ },
+ }
+ for _, test := range tests {
+ for _, kind := range []kind{kindFull, kindCompact} {
+ // Run all ops.
+ now := &fakeNow{1}
+ nowFunc = now.Now
+ timer := kind.NewTimer("root")
+ for _, op := range test.ops {
+ op.run(now, timer)
+ }
+ // Check all intervals.
+ wantRoot := test.full
+ if kind == kindCompact && test.compact != nil {
+ wantRoot = test.compact
+ }
+ name := fmt.Sprintf("%s %#v", kind.String(), test.ops)
+ expectEqualIntervals(t, name, timer.Root(), *wantRoot)
+ // Check string output.
+ now.now = 1000
+ wantStr := test.fullStr
+ if kind == kindCompact && test.compactStr != "" {
+ wantStr = test.compactStr
+ }
+ if got, want := timer.String(), strings.TrimLeft(wantStr, "\n"); got != want {
+ t.Errorf("%s GOT STRING\n%sWANT\n%s", name, got, want)
+ }
+ // Check print output hiding all gaps.
+ var buf bytes.Buffer
+ printer := IntervalPrinter{MinGap: time.Hour}
+ if err := printer.Print(&buf, timer.Root()); err != nil {
+ t.Errorf("%s got printer error: %v", name, err)
+ }
+ if got, want := buf.String(), stripGaps(wantStr); got != want {
+ t.Errorf("%s GOT PRINT\n%sWANT\n%s", name, got, want)
+ }
+ }
+ }
+ nowFunc = time.Now
+}
+
+func expectEqualIntervals(t *testing.T, name string, a, b Interval) {
+ if got, want := a.Name(), b.Name(); got != want {
+ t.Errorf("%s got name %q, want %q", name, got, want)
+ }
+ if got, want := a.Start(), b.Start(); !got.Equal(want) {
+ t.Errorf("%s got start %v, want %v", name, got, want)
+ }
+ if got, want := a.End(), b.End(); !got.Equal(want) {
+ t.Errorf("%s got end %v, want %v", name, got, want)
+ }
+ if got, want := a.NumChild(), b.NumChild(); got != want {
+ t.Errorf("%s got num child %v, want %v", name, got, want)
+ return
+ }
+ for child := 0; child < a.NumChild(); child++ {
+ expectEqualIntervals(t, name, a.Child(child), b.Child(child))
+ }
+}
+
+// stripGaps strips out leading newlines, and also strips any line with an
+// asterisk (*). Asterisks appear in lines with gaps, as shown here:
+// 00:00:01.000 root 98.000s 00:01:39.000
+// 00:00:01.000 * 9.000s 00:00:10.000
+// 00:00:10.000 abc 89.000s 00:01:39.000
+func stripGaps(out string) string {
+ out = strings.TrimLeft(out, "\n")
+ var lines []string
+ for _, line := range strings.Split(out, "\n") {
+ if !strings.ContainsRune(line, '*') {
+ lines = append(lines, line)
+ }
+ }
+ return strings.Join(lines, "\n")
+}
+
+func BenchmarkFullTimerPush(b *testing.B) {
+ t := NewFullTimer("root")
+ for i := 0; i < b.N; i++ {
+ t.Push("child")
+ }
+}
+func BenchmarkCompactTimerPush(b *testing.B) {
+ t := NewCompactTimer("root")
+ for i := 0; i < b.N; i++ {
+ t.Push("child")
+ }
+}
+
+func BenchmarkFullTimerPushPop(b *testing.B) {
+ t := NewFullTimer("root")
+ for i := 0; i < b.N; i++ {
+ timerPushPop(t)
+ }
+}
+func BenchmarkCompactTimerPushPop(b *testing.B) {
+ t := NewCompactTimer("root")
+ for i := 0; i < b.N; i++ {
+ timerPushPop(t)
+ }
+}
+func timerPushPop(t Timer) {
+ t.Push("child1")
+ t.Pop()
+ t.Push("child2")
+ t.Push("child2_1")
+ t.Pop()
+ t.Push("child2_2")
+ t.Pop()
+ t.Pop()
+ t.Push("child3")
+ t.Pop()
+}
+
+var randSource = rand.NewSource(123)
+
+func BenchmarkFullTimerRandom(b *testing.B) {
+ t, rng := NewFullTimer("root"), rand.New(randSource)
+ for i := 0; i < b.N; i++ {
+ timerRandom(rng, t)
+ }
+}
+func BenchmarkCompactTimerRandom(b *testing.B) {
+ t, rng := NewCompactTimer("root"), rand.New(randSource)
+ for i := 0; i < b.N; i++ {
+ timerRandom(rng, t)
+ }
+}
+func timerRandom(rng *rand.Rand, t Timer) {
+ switch pct := rng.Intn(100); {
+ case pct < 60:
+ timerPushPop(t)
+ case pct < 90:
+ t.Push("foo")
+ case pct < 95:
+ t.Pop()
+ default:
+ t.Finish()
+ }
+}
+
+func BenchmarkFullTimerPrint(b *testing.B) {
+ now := &stepNow{0}
+ nowFunc = now.Now
+ benchTimerPrint(b, NewFullTimer("root"))
+ nowFunc = time.Now
+}
+func BenchmarkCompactTimerPrint(b *testing.B) {
+ now := &stepNow{0}
+ nowFunc = now.Now
+ benchTimerPrint(b, NewCompactTimer("root"))
+ nowFunc = time.Now
+}
+func benchTimerPrint(b *testing.B, t Timer) {
+ rng := rand.New(randSource)
+ for i := 0; i < 1000; i++ {
+ timerRandom(rng, t)
+ }
+ t.Finish() // Make sure all intervals are closed.
+ want := t.String()
+ b.ResetTimer()
+ for i := 0; i < b.N; i++ {
+ if got := t.String(); got != want {
+ b.Fatalf("GOT\n%sWANT\n%s\nTIMER\n%#v", got, want, t)
+ }
+ }
+}
