lib: Update v.io/x/lib/timing to a single implementation
The initial implementation of the timing package had two
implementations: a FullTimer with full timing info, and a
CompactTimer that is smaller and faster, but doesn't have full
timing info. This is annoying for the user since they have to
make a choice, and adds complexity, and it bugged me.
This change consolidates things down to a single implementation,
and gets rid of the interfaces. This is simpler to use for the
user. The main point of CompactTimer was to avoid multiple small
allocations in the interval tree; the new Timer does the same
thing, while retaining full timing info.
As a bonus, the printing logic is faster, since we simply loop
through the intervals in the slice. The printing logic for
CompactTimer was quite inefficient since it caused new
allocations for each list of children in compactInterval.
MultiPart: 2/2
Change-Id: I2fea725ccb9cd3ec0107d2d33bf1d8c32b07b452
diff --git a/cmdline/.api b/cmdline/.api
index 1d867d0..fa05fd7 100644
--- a/cmdline/.api
+++ b/cmdline/.api
@@ -25,7 +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, 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 4194803..a587e46 100644
--- a/cmdline/cmdline.go
+++ b/cmdline/cmdline.go
@@ -125,7 +125,13 @@
code := ExitCode(err, env.Stderr)
if *flagTime && env.Timer != nil {
env.Timer.Finish()
- timing.IntervalPrinter{}.Print(env.Stderr, env.Timer.Root())
+ p := timing.IntervalPrinter{Zero: env.Timer.Zero}
+ if err := p.Print(env.Stderr, env.Timer.Intervals, env.Timer.Now()); err != nil {
+ code2 := ExitCode(err, env.Stderr)
+ if code == 0 {
+ code = code2
+ }
+ }
}
os.Exit(code)
}
diff --git a/cmdline/env.go b/cmdline/env.go
index 5a849f0..b1f1802 100644
--- a/cmdline/env.go
+++ b/cmdline/env.go
@@ -23,7 +23,7 @@
Stdout: os.Stdout,
Stderr: os.Stderr,
Vars: envvar.SliceToMap(os.Environ()),
- Timer: timing.NewFullTimer("root"),
+ Timer: timing.NewTimer("root"),
}
}
@@ -35,7 +35,7 @@
Stdout io.Writer
Stderr io.Writer
Vars map[string]string // Environment variables
- Timer timing.Timer
+ 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.
diff --git a/timing/.api b/timing/.api
index 6356f10..e919800 100644
--- a/timing/.api
+++ b/timing/.api
@@ -1,45 +1,21 @@
-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, const InvalidDuration time.Duration
+pkg timing, func NewTimer(string) *Timer
+pkg timing, method (*Timer) Finish()
+pkg timing, method (*Timer) Now() time.Duration
+pkg timing, method (*Timer) Pop()
+pkg timing, method (*Timer) Push(string)
+pkg timing, method (*Timer) String() string
+pkg timing, method (IntervalPrinter) Print(io.Writer, []Interval, time.Duration) error
+pkg timing, type Interval struct
+pkg timing, type Interval struct, Depth int
+pkg timing, type Interval struct, End time.Duration
+pkg timing, type Interval struct, Name string
+pkg timing, type Interval struct, Start time.Duration
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
+pkg timing, type IntervalPrinter struct, Zero time.Time
+pkg timing, type Timer struct
+pkg timing, type Timer struct, Intervals []Interval
+pkg timing, type Timer struct, Zero time.Time
diff --git a/timing/compact_timer.go b/timing/compact_timer.go
deleted file mode 100644
index 6faf513..0000000
--- a/timing/compact_timer.go
+++ /dev/null
@@ -1,173 +0,0 @@
-// 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
deleted file mode 100644
index 20f18e0..0000000
--- a/timing/full_timer.go
+++ /dev/null
@@ -1,117 +0,0 @@
-// 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
index 2819711..8313d34 100644
--- a/timing/timer.go
+++ b/timing/timer.go
@@ -6,6 +6,7 @@
package timing
import (
+ "bytes"
"fmt"
"io"
"strings"
@@ -16,71 +17,94 @@
// 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
+// InvalidDuration is set on Interval.End to indicate that the end hasn't been
+// set yet; i.e. the interval is open.
+const InvalidDuration = time.Duration(-1 << 63)
- // 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
+// Interval represents a named time interval. The start and end time of the
+// interval are represented as durations from a fixed "zero" time, rather than
+// time.Time, for a more compact and faster implementation.
+type Interval struct {
+ Name string
+ Depth int
+ Start, End time.Duration
}
-// Timer provides support for tracking a tree of hierarchical time intervals.
-// If you need to track overlapping time intervals, simply use separate Timers.
+// Timer provides support for tracking a tree of strictly 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)
+type Timer struct {
+ Zero time.Time // Absolute start time of the timer.
+ Intervals []Interval // List of intervals, in depth-first order.
- // 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
+ // 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.
+ stack []int
}
-// 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)
+// NewTimer returns a new Timer, with the root interval set to the given name.
+func NewTimer(name string) *Timer {
+ return &Timer{
+ Intervals: []Interval{{
+ Name: name,
+ End: InvalidDuration,
+ }},
+ Zero: nowFunc(),
}
- return end.Sub(start)
+}
+
+// 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.
+func (t *Timer) Push(name string) {
+ depth := len(t.stack)
+ if depth == 0 {
+ // Unset the root end time, to handle Push after Finish.
+ t.Intervals[0].End = InvalidDuration
+ }
+ t.Intervals = append(t.Intervals, Interval{
+ Name: name,
+ Depth: depth + 1,
+ Start: t.Now(),
+ End: InvalidDuration,
+ })
+ t.stack = append(t.stack, len(t.Intervals)-1)
+}
+
+// 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.
+func (t *Timer) Pop() {
+ if last := len(t.stack) - 1; last >= 0 {
+ t.Intervals[t.stack[last]].End = t.Now()
+ t.stack = t.stack[:last]
+ }
+}
+
+// Finish finishes all timing, closing all intervals including the root.
+func (t *Timer) Finish() {
+ end := t.Now()
+ t.Intervals[0].End = end
+ for _, index := range t.stack {
+ t.Intervals[index].End = end
+ }
+ t.stack = t.stack[:0]
+}
+
+// Now returns the time now relative to timer.Zero.
+func (t *Timer) Now() time.Duration {
+ return nowFunc().Sub(t.Zero)
+}
+
+// String returns a formatted string describing the tree of time intervals.
+func (t *Timer) String() string {
+ var buf bytes.Buffer
+ IntervalPrinter{Zero: t.Zero}.Print(&buf, t.Intervals, t.Now())
+ return buf.String()
}
// IntervalPrinter is a pretty-printer for Intervals. Example output:
@@ -94,6 +118,11 @@
// 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 {
+ // Zero is the absolute start time to use for printing; all interval times are
+ // computed relative to the zero time. Typically this is set to Timer.Zero to
+ // print actual timestamps, or time.Time{} to print relative timestamps
+ // starting at the root.
+ Zero time.Time
// 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
@@ -108,8 +137,17 @@
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 {
+// Print writes formatted output to w representing the given intervals. The
+// intervals must be in depth-first order; i.e. any slice or subslice of
+// intervals produced by Timer are valid.
+//
+// The time now is used as the end time for any open intervals, and is
+// represented as a duration from the zero time for the intervals;
+// e.g. use Timer.Now() for intervals collected by the Timer.
+func (p IntervalPrinter) Print(w io.Writer, intervals []Interval, now time.Duration) error {
+ if len(intervals) == 0 {
+ return nil
+ }
// Set default options for zero fields.
if p.TimeFormat == "" {
p.TimeFormat = "15:04:05.000"
@@ -122,98 +160,151 @@
}
switch {
case p.MinGap < 0:
- p.MinGap = 0
+ p.MinGap = InvalidDuration
case p.MinGap == 0:
p.MinGap = time.Millisecond
}
- return p.print(w, i, p.collectPrintStats(i), i.Start(), 0)
+ printer := printer{
+ IntervalPrinter: p,
+ w: w,
+ now: now,
+ intervals: intervals,
+ }
+ return printer.print()
}
-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 {
+type printer struct {
+ IntervalPrinter
+ w io.Writer
+ now time.Duration
+ intervals []Interval
+ stack []int
+
+ // Stats collected to help formatting.
+ nowLabel string
+ depthMin int
+ depthRange int
+ nameWidth int
+ durWidth int
+}
+
+func (p *printer) print() error {
+ p.stack = make([]int, 1)
+ p.collectStats()
+ return p.walkIntervals(p.printRow)
+}
+
+func (p *printer) walkIntervals(fn func(name string, start, end time.Duration, depth int) error) error {
+ stack := p.stack[:1]
+ stack[0] = 0
+ prev := Interval{"", p.intervals[0].Depth, 0, 0}
+ for index, i := range p.intervals {
+ for i.Depth < prev.Depth && len(stack) > 1 {
+ // Handle the normal case for gaps based on pops, where we have a full
+ // subtree. The gap end is based on the end of the parent, which is the
+ // new previous interval.
+ parent := p.intervals[stack[len(stack)-2]]
+ start, end := prev.End, parent.End
+ if gap := end - start; gap >= p.MinGap {
+ if err := fn("*", start, end, prev.Depth); err != nil {
+ return err
+ }
+ }
+ stack = stack[:len(stack)-1]
+ prev = parent
+ }
+ switch {
+ case i.Depth < prev.Depth && len(stack) == 1:
+ // Handle a corner-case for gaps based on pops, where we have a partial
+ // subtree. The gap end is based on the start of the current interval,
+ // and we update the stack to start with the current interval.
+ start, end := prev.End, i.Start
+ if gap := end - start; gap >= p.MinGap {
+ if err := fn("*", start, end, prev.Depth); err != nil {
+ return err
+ }
+ }
+ stack[0] = index
+ case i.Depth == prev.Depth:
+ // Handle the regular case for gaps based on pop/push siblings.
+ start, end := prev.End, i.Start
+ if gap := end - start; gap >= p.MinGap {
+ if err := fn("*", start, end, i.Depth); err != nil {
+ return err
+ }
+ }
+ stack[len(stack)-1] = index
+ case i.Depth > prev.Depth:
+ // Handle the regular case for gaps based on push children.
+ start, end := prev.Start, i.Start
+ if gap := end - start; gap >= p.MinGap {
+ if err := fn("*", start, end, i.Depth); err != nil {
+ return err
+ }
+ }
+ stack = append(stack, index)
+ }
+ // Visit the current interval.
+ if err := fn(i.Name, i.Start, i.End, i.Depth); err != nil {
return err
}
+ prev = i
}
- // 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 {
+ // Handle leftover gaps (based on pops), if any exist.
+ for len(stack) > 1 {
+ parent := p.intervals[stack[len(stack)-2]]
+ start, end := prev.End, parent.End
+ if gap := end - start; gap >= p.MinGap {
+ if err := fn("*", start, end, prev.Depth); err != nil {
return err
}
}
+ stack = stack[:len(stack)-1]
+ prev = parent
}
+ p.stack = stack[:0]
return nil
}
-func (p IntervalPrinter) row(w io.Writer, name string, start, end time.Time, dur time.Duration, stats *printStats, depth int) error {
+func (p *printer) printRow(name string, start, end time.Duration, depth int) error {
+ depth -= p.depthMin
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)
+ pad2 := strings.Repeat(" ", p.Indent*(p.depthRange-depth))
+ startStr := p.Zero.Add(start).Format(p.TimeFormat)
+ endStr, dur := p.nowLabel, p.now-start
+ if end != InvalidDuration {
+ endStr, dur = p.Zero.Add(end).Format(p.TimeFormat), end-start
}
- _, 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)
+ _, err := fmt.Fprintf(p.w, "%s %-*s %s%*.3fs%s %s\n", startStr, p.nameWidth, pad+name, pad, p.durWidth, 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()
+func (p *printer) collectStats() {
+ p.nowLabel = strings.Repeat("-", len(p.TimeFormat)-3) + "now"
+ depthMin, depthMax := p.intervals[0].Depth, p.intervals[0].Depth
+ for _, i := range p.intervals[1:] {
+ if x := i.Depth; x < depthMin {
+ depthMin = x
}
- s.collect(i.Child(child), indent, prevEnd, depth+1)
+ if x := i.Depth; x > depthMax {
+ depthMax = x
+ }
}
+ p.depthMin = depthMin
+ p.depthRange = depthMax - depthMin
+ var durMax time.Duration
+ p.walkIntervals(func(name string, start, end time.Duration, depth int) error {
+ if x := len(name) + p.Indent*(depth-p.depthMin); x > p.nameWidth {
+ p.nameWidth = x
+ }
+ dur := p.now - start
+ if end != InvalidDuration {
+ dur = end - start
+ }
+ if dur > durMax {
+ durMax = dur
+ }
+ return nil
+ })
+ p.durWidth = len(fmt.Sprintf("%.3f", float64(durMax)/float64(time.Second)))
}
diff --git a/timing/timer_test.go b/timing/timer_test.go
index 122587d..bfc6991 100644
--- a/timing/timer_test.go
+++ b/timing/timer_test.go
@@ -8,33 +8,38 @@
"bytes"
"fmt"
"math/rand"
+ "reflect"
"strings"
"testing"
"time"
)
-func sec(d int) time.Time {
- return time.Time{}.Add(time.Second * time.Duration(d))
+func sec(d int) time.Duration {
+ return time.Second * time.Duration(d)
+}
+
+func tsec(d int) time.Time {
+ return time.Time{}.Add(sec(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) }
+func (f *fakeNow) Now() time.Time { return tsec(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)
+ return tsec(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)
+ run(f *fakeNow, t *Timer)
}
push struct {
now int
@@ -48,371 +53,19 @@
}
)
-func (x push) run(f *fakeNow, t Timer) {
+func (x push) run(f *fakeNow, t *Timer) {
f.now = x.now
t.Push(x.name)
}
-func (x pop) run(f *fakeNow, t Timer) {
+func (x pop) run(f *fakeNow, t *Timer) {
f.now = x.now
t.Pop()
}
-func (x finish) run(f *fakeNow, t Timer) {
+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
@@ -429,32 +82,588 @@
return strings.Join(lines, "\n")
}
-func BenchmarkFullTimerPush(b *testing.B) {
- t := NewFullTimer("root")
- for i := 0; i < b.N; i++ {
- t.Push("child")
+func TestTimer(t *testing.T) {
+ tests := []struct {
+ ops []op
+ intervals []Interval
+ str string
+ }{
+ {
+ nil,
+ []Interval{{"root", 0, sec(0), InvalidDuration}},
+ `
+00:00:01.000 root 999.000s ---------now
+`,
+ },
+ {
+ []op{pop{123}},
+ []Interval{{"root", 0, sec(0), InvalidDuration}},
+ `
+00:00:01.000 root 999.000s ---------now
+`,
+ },
+ {
+ []op{finish{99}},
+ []Interval{{"root", 0, sec(0), sec(98)}},
+ `
+00:00:01.000 root 98.000s 00:01:39.000
+`,
+ },
+ {
+ []op{finish{99}, pop{123}},
+ []Interval{{"root", 0, sec(0), sec(98)}},
+ `
+00:00:01.000 root 98.000s 00:01:39.000
+`,
+ },
+ {
+ []op{push{10, "abc"}},
+ []Interval{
+ {"root", 0, sec(0), InvalidDuration},
+ {"abc", 1, sec(9), InvalidDuration},
+ },
+ `
+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}},
+ []Interval{
+ {"root", 0, sec(0), sec(98)},
+ {"abc", 1, sec(9), sec(98)},
+ },
+ `
+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}},
+ []Interval{
+ {"root", 0, sec(0), sec(98)},
+ {"abc", 1, sec(9), sec(19)},
+ },
+ `
+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
+`,
+ },
+ {
+ []op{push{10, "A1"}, push{20, "A1_1"}},
+ []Interval{
+ {"root", 0, sec(0), InvalidDuration},
+ {"A1", 1, sec(9), InvalidDuration},
+ {"A1_1", 2, sec(19), InvalidDuration},
+ },
+ `
+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}},
+ []Interval{
+ {"root", 0, sec(0), sec(98)},
+ {"A1", 1, sec(9), sec(98)},
+ {"A1_1", 2, sec(19), sec(98)},
+ },
+ `
+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}},
+ []Interval{
+ {"root", 0, sec(0), sec(98)},
+ {"A1", 1, sec(9), sec(98)},
+ {"A1_1", 2, sec(19), sec(29)},
+ },
+ `
+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
+`,
+ },
+ {
+ []op{push{10, "A1"}, push{20, "A1_1"}, pop{30}, pop{40}, finish{99}},
+ []Interval{
+ {"root", 0, sec(0), sec(98)},
+ {"A1", 1, sec(9), sec(39)},
+ {"A1_1", 2, sec(19), sec(29)},
+ },
+ `
+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
+`,
+ },
+ {
+ []op{push{10, "A1"}, push{20, "A1_1"}, push{30, "A1_1_1"}},
+ []Interval{
+ {"root", 0, sec(0), InvalidDuration},
+ {"A1", 1, sec(9), InvalidDuration},
+ {"A1_1", 2, sec(19), InvalidDuration},
+ {"A1_1_1", 3, sec(29), InvalidDuration},
+ },
+ `
+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
+00:00:20.000 * 10.000s 00:00:30.000
+00:00:30.000 A1_1_1 970.000s ---------now
+`,
+ },
+ {
+ []op{push{10, "A1"}, push{20, "A1_1"}, push{30, "A1_1_1"}, finish{99}},
+ []Interval{
+ {"root", 0, sec(0), sec(98)},
+ {"A1", 1, sec(9), sec(98)},
+ {"A1_1", 2, sec(19), sec(98)},
+ {"A1_1_1", 3, sec(29), sec(98)},
+ },
+ `
+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
+00:00:20.000 * 10.000s 00:00:30.000
+00:00:30.000 A1_1_1 69.000s 00:01:39.000
+`,
+ },
+ {
+ []op{push{10, "A1"}, push{20, "A1_1"}, push{30, "A1_1_1"}, pop{40}, finish{99}},
+ []Interval{
+ {"root", 0, sec(0), sec(98)},
+ {"A1", 1, sec(9), sec(98)},
+ {"A1_1", 2, sec(19), sec(98)},
+ {"A1_1_1", 3, sec(29), sec(39)},
+ },
+ `
+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
+00:00:20.000 * 10.000s 00:00:30.000
+00:00:30.000 A1_1_1 10.000s 00:00:40.000
+00:00:40.000 * 59.000s 00:01:39.000
+`,
+ },
+ {
+ []op{push{10, "A1"}, push{20, "A1_1"}, push{30, "A1_1_1"}, pop{40}, pop{55}, finish{99}},
+ []Interval{
+ {"root", 0, sec(0), sec(98)},
+ {"A1", 1, sec(9), sec(98)},
+ {"A1_1", 2, sec(19), sec(54)},
+ {"A1_1_1", 3, sec(29), sec(39)},
+ },
+ `
+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 35.000s 00:00:55.000
+00:00:20.000 * 10.000s 00:00:30.000
+00:00:30.000 A1_1_1 10.000s 00:00:40.000
+00:00:40.000 * 15.000s 00:00:55.000
+00:00:55.000 * 44.000s 00:01:39.000
+`,
+ },
+ {
+ []op{push{10, "A1"}, push{20, "A1_1"}, push{30, "A1_1_1"}, pop{40}, pop{55}, pop{75}, finish{99}},
+ []Interval{
+ {"root", 0, sec(0), sec(98)},
+ {"A1", 1, sec(9), sec(74)},
+ {"A1_1", 2, sec(19), sec(54)},
+ {"A1_1_1", 3, sec(29), sec(39)},
+ },
+ `
+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 65.000s 00:01:15.000
+00:00:10.000 * 10.000s 00:00:20.000
+00:00:20.000 A1_1 35.000s 00:00:55.000
+00:00:20.000 * 10.000s 00:00:30.000
+00:00:30.000 A1_1_1 10.000s 00:00:40.000
+00:00:40.000 * 15.000s 00:00:55.000
+00:00:55.000 * 20.000s 00:01:15.000
+00:01:15.000 * 24.000s 00:01:39.000
+`,
+ },
+ {
+ []op{push{10, "A1"}, push{20, "A1_1"}, finish{30}, push{40, "B1"}},
+ []Interval{
+ {"root", 0, sec(0), InvalidDuration},
+ {"A1", 1, sec(9), sec(29)},
+ {"A1_1", 2, sec(19), sec(29)},
+ {"B1", 1, sec(39), InvalidDuration},
+ },
+ `
+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
+`,
+ },
+ {
+ []op{push{10, "A1"}, push{20, "A1_1"}, finish{30}, push{40, "B1"}, finish{99}},
+ []Interval{
+ {"root", 0, sec(0), sec(98)},
+ {"A1", 1, sec(9), sec(29)},
+ {"A1_1", 2, sec(19), sec(29)},
+ {"B1", 1, sec(39), sec(98)},
+ },
+ `
+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
+`,
+ },
+ {
+ []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}},
+ []Interval{
+ {"root", 0, sec(0), sec(98)},
+ {"foo", 1, sec(9), sec(54)},
+ {"foo1", 2, sec(14), sec(36)},
+ {"foo2", 2, sec(36), sec(54)},
+ {"bar", 1, sec(54), sec(79)},
+ {"baz", 1, sec(79), sec(98)},
+ },
+ `
+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}},
+ []Interval{
+ {"root", 0, sec(0), sec(98)},
+ {"foo", 1, sec(9), sec(52)},
+ {"foo1", 2, sec(14), sec(29)},
+ {"foo2", 2, sec(36), sec(49)},
+ {"bar", 1, sec(54), sec(74)},
+ {"baz", 1, sec(79), sec(89)},
+ },
+ `
+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
+`,
+ },
+ }
+ for _, test := range tests {
+ // Run all ops.
+ now := &fakeNow{1}
+ nowFunc = now.Now
+ timer := NewTimer("root")
+ for _, op := range test.ops {
+ op.run(now, timer)
+ }
+ name := fmt.Sprintf("%#v", test.ops)
+ // Check all intervals.
+ if got, want := timer.Intervals, test.intervals; !reflect.DeepEqual(got, want) {
+ t.Errorf("%s got intervals %v, want %v", name, got, want)
+ }
+ // Check string output.
+ now.now = 1000
+ if got, want := timer.String(), strings.TrimLeft(test.str, "\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{Zero: timer.Zero, MinGap: time.Hour}
+ if err := printer.Print(&buf, timer.Intervals, nowFunc().Sub(timer.Zero)); err != nil {
+ t.Errorf("%s got printer error: %v", name, err)
+ }
+ if got, want := buf.String(), stripGaps(test.str); got != want {
+ t.Errorf("%s GOT PRINT\n%sWANT\n%s", name, got, want)
+ }
+ }
+ nowFunc = time.Now
+}
+
+// TestIntervalPrinterCornerCases tests corner cases for the printer. These are
+// all cases where only a subset of the full Timer intervals is printed.
+func TestIntervalPrinterCornerCases(t *testing.T) {
+ tests := []struct {
+ intervals []Interval
+ str string
+ }{
+ {
+ []Interval{{"abc", 1, sec(9), InvalidDuration}},
+ `
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 abc 990.000s ---------now
+`,
+ },
+ {
+ []Interval{{"abc", 1, sec(9), sec(98)}},
+ `
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 abc 89.000s 00:01:39.000
+`,
+ },
+ {
+ []Interval{
+ {"A1", 1, sec(9), InvalidDuration},
+ {"A1_1", 2, sec(19), InvalidDuration},
+ },
+ `
+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
+`,
+ },
+ {
+ []Interval{
+ {"A1", 1, sec(9), InvalidDuration},
+ {"A1_1", 2, sec(19), sec(49)},
+ },
+ `
+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 30.000s 00:00:50.000
+00:00:50.000 * 950.000s ---------now
+`,
+ },
+ {
+ []Interval{
+ {"A1", 1, sec(9), sec(98)},
+ {"A1_1", 2, sec(19), sec(49)},
+ },
+ `
+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 30.000s 00:00:50.000
+00:00:50.000 * 49.000s 00:01:39.000
+`,
+ },
+ {
+ []Interval{
+ {"A1_1", 2, sec(9), sec(19)},
+ {"B1", 1, sec(39), InvalidDuration},
+ },
+ `
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 A1_1 10.000s 00:00:20.000
+00:00:20.000 * 20.000s 00:00:40.000
+00:00:40.000 B1 960.000s ---------now
+`,
+ },
+ {
+ []Interval{
+ {"A1_1", 2, sec(9), sec(19)},
+ {"B1", 1, sec(39), sec(64)},
+ },
+ `
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 A1_1 10.000s 00:00:20.000
+00:00:20.000 * 20.000s 00:00:40.000
+00:00:40.000 B1 25.000s 00:01:05.000
+`,
+ },
+ {
+ []Interval{
+ {"A1_1", 2, sec(9), sec(19)},
+ {"B1", 1, sec(39), sec(64)},
+ {"C1", 1, sec(69), sec(84)},
+ },
+ `
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 A1_1 10.000s 00:00:20.000
+00:00:20.000 * 20.000s 00:00:40.000
+00:00:40.000 B1 25.000s 00:01:05.000
+00:01:05.000 * 5.000s 00:01:10.000
+00:01:10.000 C1 15.000s 00:01:25.000
+`,
+ },
+ {
+ []Interval{
+ {"A1_1", 2, sec(9), sec(19)},
+ {"B1", 1, sec(39), sec(84)},
+ {"B1_1", 2, sec(64), sec(69)},
+ },
+ `
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 A1_1 10.000s 00:00:20.000
+00:00:20.000 * 20.000s 00:00:40.000
+00:00:40.000 B1 45.000s 00:01:25.000
+00:00:40.000 * 25.000s 00:01:05.000
+00:01:05.000 B1_1 5.000s 00:01:10.000
+00:01:10.000 * 15.000s 00:01:25.000
+`,
+ },
+ {
+ []Interval{
+ {"A1_1", 2, sec(9), sec(19)},
+ {"B1", 1, sec(39), sec(89)},
+ {"B1_1", 2, sec(64), sec(69)},
+ {"B1_2", 2, sec(79), sec(87)},
+ },
+ `
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 A1_1 10.000s 00:00:20.000
+00:00:20.000 * 20.000s 00:00:40.000
+00:00:40.000 B1 50.000s 00:01:30.000
+00:00:40.000 * 25.000s 00:01:05.000
+00:01:05.000 B1_1 5.000s 00:01:10.000
+00:01:10.000 * 10.000s 00:01:20.000
+00:01:20.000 B1_2 8.000s 00:01:28.000
+00:01:28.000 * 2.000s 00:01:30.000
+`,
+ },
+ {
+ []Interval{
+ {"A1_1_1", 3, sec(9), sec(19)},
+ {"B1", 1, sec(39), InvalidDuration},
+ },
+ `
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 A1_1_1 10.000s 00:00:20.000
+00:00:20.000 * 20.000s 00:00:40.000
+00:00:40.000 B1 960.000s ---------now
+`,
+ },
+ {
+ []Interval{
+ {"A1_1_1", 3, sec(9), sec(19)},
+ {"B1", 1, sec(39), sec(64)},
+ },
+ `
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 A1_1_1 10.000s 00:00:20.000
+00:00:20.000 * 20.000s 00:00:40.000
+00:00:40.000 B1 25.000s 00:01:05.000
+`,
+ },
+ {
+ []Interval{
+ {"A1_1_1", 3, sec(9), sec(19)},
+ {"B1", 1, sec(39), sec(64)},
+ {"C1", 1, sec(69), sec(84)},
+ },
+ `
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 A1_1_1 10.000s 00:00:20.000
+00:00:20.000 * 20.000s 00:00:40.000
+00:00:40.000 B1 25.000s 00:01:05.000
+00:01:05.000 * 5.000s 00:01:10.000
+00:01:10.000 C1 15.000s 00:01:25.000
+`,
+ },
+ {
+ []Interval{
+ {"A1_1_1", 3, sec(9), sec(19)},
+ {"B1", 1, sec(39), sec(84)},
+ {"B1_1", 2, sec(59), sec(69)},
+ },
+ `
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 A1_1_1 10.000s 00:00:20.000
+00:00:20.000 * 20.000s 00:00:40.000
+00:00:40.000 B1 45.000s 00:01:25.000
+00:00:40.000 * 20.000s 00:01:00.000
+00:01:00.000 B1_1 10.000s 00:01:10.000
+00:01:10.000 * 15.000s 00:01:25.000
+`,
+ },
+ {
+ []Interval{
+ {"A1_1", 2, sec(9), sec(84)},
+ {"A1_1_1", 3, sec(39), sec(79)},
+ {"A1_1_1_1", 4, sec(54), sec(69)},
+ {"B1", 1, sec(89), sec(99)},
+ },
+ `
+00:00:01.000 * 9.000s 00:00:10.000
+00:00:10.000 A1_1 75.000s 00:01:25.000
+00:00:10.000 * 30.000s 00:00:40.000
+00:00:40.000 A1_1_1 40.000s 00:01:20.000
+00:00:40.000 * 15.000s 00:00:55.000
+00:00:55.000 A1_1_1_1 15.000s 00:01:10.000
+00:01:10.000 * 10.000s 00:01:20.000
+00:01:20.000 * 5.000s 00:01:25.000
+00:01:25.000 * 5.000s 00:01:30.000
+00:01:30.000 B1 10.000s 00:01:40.000
+`,
+ },
+ }
+ for _, test := range tests {
+ name := fmt.Sprintf("%#v", test.intervals)
+ // Check print output with gaps.
+ var buf bytes.Buffer
+ printer := IntervalPrinter{Zero: tsec(1)}
+ if err := printer.Print(&buf, test.intervals, sec(999)); err != nil {
+ t.Errorf("%s got printer error: %v", name, err)
+ }
+ if got, want := buf.String(), strings.TrimLeft(test.str, "\n"); got != want {
+ t.Errorf("%s GOT STRING\n%sWANT\n%s", name, got, want)
+ }
}
}
-func BenchmarkCompactTimerPush(b *testing.B) {
- t := NewCompactTimer("root")
+
+func BenchmarkTimerPush(b *testing.B) {
+ t := NewTimer("root")
for i := 0; i < b.N; i++ {
t.Push("child")
}
}
-func BenchmarkFullTimerPushPop(b *testing.B) {
- t := NewFullTimer("root")
+func BenchmarkTimerPushPop(b *testing.B) {
+ t := NewTimer("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) {
+func timerPushPop(t *Timer) {
t.Push("child1")
t.Pop()
t.Push("child2")
@@ -469,45 +678,28 @@
var randSource = rand.NewSource(123)
-func BenchmarkFullTimerRandom(b *testing.B) {
- t, rng := NewFullTimer("root"), rand.New(randSource)
+func BenchmarkTimerRandom(b *testing.B) {
+ t, rng := NewTimer("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) {
+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:
+ case pct < 99:
t.Pop()
default:
t.Finish()
}
}
-func BenchmarkFullTimerPrint(b *testing.B) {
- now := &stepNow{0}
+func BenchmarkTimerString(b *testing.B) {
+ t, rng, now := NewTimer("root"), rand.New(randSource), &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)
}
@@ -519,4 +711,5 @@
b.Fatalf("GOT\n%sWANT\n%s\nTIMER\n%#v", got, want, t)
}
}
+ nowFunc = time.Now
}
