timings.go

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