| // 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 ( |
| "bytes" |
| "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 |
| |
| // 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) |
| |
| // 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 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 struct { |
| Zero time.Time // Absolute start time of the timer. |
| Intervals []Interval // List of intervals, in depth-first order. |
| |
| // 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 |
| } |
| |
| // 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(), |
| } |
| } |
| |
| // 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: |
| // |
| // 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 { |
| // 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 |
| // 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 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" |
| } |
| switch { |
| case p.Indent < 0: |
| p.Indent = 0 |
| case p.Indent == 0: |
| p.Indent = 3 |
| } |
| switch { |
| case p.MinGap < 0: |
| p.MinGap = InvalidDuration |
| case p.MinGap == 0: |
| p.MinGap = time.Millisecond |
| } |
| printer := printer{ |
| IntervalPrinter: p, |
| w: w, |
| now: now, |
| intervals: intervals, |
| } |
| return printer.print() |
| } |
| |
| 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 |
| } |
| // 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 *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*(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(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 |
| } |
| |
| 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 |
| } |
| 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))) |
| } |