diff --git a/README.md b/README.md index 00e07af..a9bad4c 100644 --- a/README.md +++ b/README.md @@ -36,20 +36,21 @@ func main() { ``` 50 samples of 100 events -Cumulative: 669.433006ms -HMean: 47.477µs -Avg.: 13.38866ms -p50: 11.191119ms -p75: 19.15929ms -p95: 28.145686ms -p99: 30.135862ms -p999: 30.135862ms -Long 5%: 29.156558ms -Short 5%: 424.823µs -Max: 30.135862ms -Min: 1.765µs -Range: 30.134097ms -Rate/sec.: 74.69 +Cumulative: 671.871ms +HMean: 125.38µs +Avg.: 13.43742ms +p50: 13.165ms +p75: 20.058ms +p95: 27.536ms +p99: 30.043ms +p999: 30.043ms +Long 5%: 29.749ms +Short 5%: 399.666µs +Max: 30.043ms +Min: 4µs +Range: 30.039ms +StdDev: 8.385117ms +Rate/sec.: 74.42 ``` ### Output Descriptions @@ -63,6 +64,7 @@ Rate/sec.: 74.69 - `Max`: Max observed event duration. - `Min`: Min observed event duration. - `Range`: The delta between the max and min sample time +- `StdDev`: The population standard deviation - `Rate/sec.`: Per-second rate based on cumulative time and sample count. @@ -83,7 +85,7 @@ fmt.Printf("Median latency: %s\n", metrics.Time.P50) Output: ``` -Median latency: 12.501677ms +Median latency: 13.165ms ``` ### `Metrics`: JSON string @@ -92,31 +94,32 @@ fmt.Printf("%s\n\", metrics.JSON()) ``` Output: ``` -{"Time":{"Cumulative":"673.736214ms","HMean":"57.485µs","Avg":"13.474724ms","P50":"12.501677ms","P75":"19.974307ms","P95":"28.460246ms","P99":"30.101584ms","P999":"30.101584ms","Long5p":"29.505675ms","Short5p":"399.399µs","Max":"30.101584ms","Min":"2.145µs","Range":"30.099439ms"},"Rate":{"Second":74.21302129975754},"Samples":50,"Count":100,"Histogram":[{"2.145µs - 3.012088ms":5},{"3.012089ms - 6.022031ms":3},{"6.022032ms - 9.031974ms":11},{"9.031975ms - 12.041917ms":5},{"12.041918ms - 15.05186ms":8},{"15.051861ms - 18.061803ms":4},{"18.061804ms - 21.071746ms":2},{"21.071747ms - 24.081689ms":5},{"24.08169ms - 27.091632ms":3},{"27.091633ms - 30.101584ms":4}]} +{"Time":{"Cumulative":"671.871ms","HMean":"125.38µs","Avg":"13.43742ms","P50":"13.165ms","P75":"20.058ms","P95":"27.536ms","P99":"30.043ms","P999":"30.043ms","Long5p":"29.749ms","Short5p":"399.666µs","Max":"30.043ms","Min":"4µs","Range":"30.039ms","StdDev":"8.385117ms"},"Rate":{"Second":74.41904770409796},"Samples":50,"Count":100,"Histogram":[{"4µs - 3.007ms":5},{"3.007ms - 6.011ms":4},{"6.011ms - 9.015ms":10},{"9.015ms - 12.019ms":6},{"12.019ms - 15.023ms":7},{"15.023ms - 18.027ms":3},{"18.027ms - 21.031ms":4},{"21.031ms - 24.035ms":3},{"24.035ms - 27.039ms":3},{"27.039ms - 30.043ms":5}]} ``` ### `Metrics`: pre-formatted string ```golang fmt.Println(metrics.String()) ``` - + Output: ``` - 50 samples of 100 events -Cumulative: 669.433006ms -HMean: 47.477µs -Avg.: 13.38866ms -p50: 11.191119ms -p75: 19.15929ms -p95: 28.145686ms -p99: 30.135862ms -p999: 30.135862ms -Long 5%: 29.156558ms -Short 5%: 424.823µs -Max: 30.135862ms -Min: 1.765µs -Range: 30.134097ms -Rate/sec.: 74.69 +50 samples of 100 events +Cumulative: 671.871ms +HMean: 125.38µs +Avg.: 13.43742ms +p50: 13.165ms +p75: 20.058ms +p95: 27.536ms +p99: 30.043ms +p999: 30.043ms +Long 5%: 29.749ms +Short 5%: 399.666µs +Max: 30.043ms +Min: 4µs +Range: 30.039ms +StdDev: 8.385117ms +Rate/sec.: 74.42 ``` ### `Histogram`: text format @@ -127,16 +130,16 @@ fmt.Println(metrics.Histogram.String(25)) Output: ``` - 4ms - 12.9ms ------------------------- -12.9ms - 21.8ms ------------------------- -21.8ms - 30.7ms - -30.7ms - 39.6ms ---------- -39.6ms - 48.5ms ----- -48.5ms - 57.4ms ----- -57.4ms - 66.3ms - -66.3ms - 75.2ms - -75.2ms - 84.1ms ----- - 84.1ms - 93ms ------------------------- + 4µs - 3.007ms ----- + 3.007ms - 6.011ms --- + 6.011ms - 9.015ms --------------- + 9.015ms - 12.019ms ------- + 12.019ms - 15.023ms --------- + 15.023ms - 18.027ms - + 18.027ms - 21.031ms --- + 21.031ms - 24.035ms - + 24.035ms - 27.039ms - + 27.039ms - 30.043ms ----- ``` ### `Histogram`: HTML graphs @@ -145,21 +148,21 @@ A `Histogram` can be written as HTML histograms. The `Metrics.WriteHTML(p string ```golang err := metrics.WriteHTML(".") ``` - + Output: -![ss](https://cloud.githubusercontent.com/assets/4108044/25826873/c40d62b8-3405-11e7-9dec-047d1e0c6f42.png) +![ss](https://user-images.githubusercontent.com/4108044/37558972-a40374f2-29e2-11e8-9df2-60b2927a8fa4.png) Tachymeter also provides a `Timeline` type that's used to gather a series of `*Metrics` (each `*Metrics` themselves holding data summarizing a series of measured events). `*Metrics` are added to a `*Timeline` using the `AddEvent(m *Metrics)` method. Once the desired number of `*Metrics` has been collected, `WriteHTML` can be called on the `*Timeline`, resulting in an single HTML page with a histogram for each captured `*Metrics`. An example use case may be a benchmark where tachymeter is used to summarize the timing results of a loop, but several iterations of the loop are to be called in series. See the [tachymeter-graphing example](https://github.com/jamiealquiza/tachymeter/tree/master/example/tachymeter-graphing) for further details. ### Configuration -Tachymeter is initialized with a `Size` parameter that specifies the max sample count that can be held. This is done to control resource usage and minimize the impact of tachymeter inside an application; the `AddTime` method is o(1) @ ~20ns on modern hardware. If the actual event count is smaller than or equal to the configured tachymeter size, all of the meaused events will be included in the calculated results. If the event count exceeds the tachymeter size, the oldest data will be overwritten. In this scenario, the last window of data (that fits into the configured `Size`) will be used for output calculations. +Tachymeter is initialized with a `Size` parameter that specifies the max sample count that can be held. This is done to control resource usage and minimize the impact of tachymeter inside an application; the `AddTime` method should be a sub-microsecond o(1) on modern hardware. If the actual event count is smaller than or equal to the configured tachymeter size, all of the measured events will be included in the calculated results. If the event count exceeds the tachymeter size, the oldest data will be overwritten. In this scenario, the last window of data (that fits into the configured `Size`) will be used for output calculations. Note the tradeoffs of this counting mechanism as a design choice; calculations are intended to be lossless within the data window, but the window size has upper limitations. If you're doing extremely high counts (either by sheer rate or by using long windows), you may benefit from a sketch counter (not currently supported). # Accurate Rates With Parallelism -By default, tachymeter calcualtes rate based on the number of events possible per-second according to average event duration. This model doesn't work in asynchronous or parallelized scenarios since events may be overlapping in time. For example, with many Goroutines writing durations to a shared tachymeter in parallel, the global rate must be determined by using the total event count over the total wall time elapsed. +By default, tachymeter calculates rate based on the number of events possible per-second according to average event duration. This model doesn't work in asynchronous or parallelized scenarios since events may be overlapping in time. For example, with many Goroutines writing durations to a shared tachymeter in parallel, the global rate must be determined by using the total event count over the total wall time elapsed. Tachymeter exposes a `SetWallTime` method for these scenarios. @@ -175,18 +178,18 @@ func main() { // Start wall time for all Goroutines. wallTimeStart := time.Now() var wg sync.WaitGroup - + // Run tasks. for i := 0; i < 5; i++ { wg.Add(1) go someTask(t, wg) } - + wg.Wait() // When finished, set elapsed wall time. t.SetWallTime(time.Since(wallTimeStart)) - + // Rate outputs will be accurate. fmt.Println(t.Calc().String()) } @@ -194,7 +197,7 @@ func main() { func someTask(t *tachymeter.Tachymeter, wg *sync.WaitGroup) { defer wg.Done() start := time.Now() - + // doSomeSlowDbCall() // Task we're timing added here. diff --git a/calcs.go b/calcs.go index de97b7b..1e7b1ef 100644 --- a/calcs.go +++ b/calcs.go @@ -48,43 +48,44 @@ func (m *Tachymeter) Calc() *Metrics { metrics.Time.Min = times.min() metrics.Time.Max = times.max() metrics.Time.Range = times.srange() + metrics.Time.StdDev = times.stdDev() - metrics.Histogram, metrics.HistogramBucketSize = times.hgram(m.HBuckets) + metrics.Histogram, metrics.HistogramBinSize = times.hgram(m.HBins) return metrics } // hgram returns a histogram of event durations in -// b buckets, along with the bucket size. +// b bins, along with the bin size. func (ts timeSlice) hgram(b int) (*Histogram, time.Duration) { res := time.Duration(1000) - // Interval is the time range / n buckets. + // Interval is the time range / n bins. interval := time.Duration(int64(ts.srange()) / int64(b)) high := ts.min() + interval low := ts.min() max := ts.max() hgram := &Histogram{} - pos := 1 // Bucket position. + pos := 1 // Bin position. bstring := fmt.Sprintf("%s - %s", low/res*res, high/res*res) - bucket := map[string]uint64{} + bin := map[string]uint64{} for _, v := range ts { - // If v fits in the current bucket, - // increment the bucket count. + // If v fits in the current bin, + // increment the bin count. if v <= high { - bucket[bstring]++ + bin[bstring]++ } else { - // If not, prepare the next bucket. - *hgram = append(*hgram, bucket) - bucket = map[string]uint64{} + // If not, prepare the next bin. + *hgram = append(*hgram, bin) + bin = map[string]uint64{} // Update the high/low range values. low = high + time.Nanosecond high += interval // if we're going into the - // last bucket, set high to max. + // last bin, set high to max. if pos == b-1 { high = max } @@ -92,38 +93,38 @@ func (ts timeSlice) hgram(b int) (*Histogram, time.Duration) { bstring = fmt.Sprintf("%s - %s", low/res*res, high/res*res) // The value didn't fit in the previous - // bucket, so the new bucket count should + // bin, so the new bin count should // be incremented. - bucket[bstring]++ + bin[bstring]++ pos++ } } - *hgram = append(*hgram, bucket) + *hgram = append(*hgram, bin) return hgram, interval } // These should be self-explanatory: -func (ts timeSlice) hMean() time.Duration { - var total float64 - +func (ts timeSlice) cumulative() time.Duration { + var total time.Duration for _, t := range ts { - total += (1 / float64(t)) + total += t } - return time.Duration(float64(ts.Len()) / total) + return total } -func (ts timeSlice) cumulative() time.Duration { - var total time.Duration +func (ts timeSlice) hMean() time.Duration { + var total float64 + for _, t := range ts { - total += t + total += (1 / float64(t)) } - return total + return time.Duration(float64(ts.Len()) / total) } func (ts timeSlice) avg() time.Duration { @@ -138,6 +139,19 @@ func (ts timeSlice) p(p float64) time.Duration { return ts[int(float64(ts.Len())*p+0.5)-1] } +func (ts timeSlice) stdDev() time.Duration { + m := ts.avg() + s := 0.00 + + for _, t := range ts { + s += math.Pow(float64(m-t), 2) + } + + msq := s / float64(ts.Len()) + + return time.Duration(math.Sqrt(msq)) +} + func (ts timeSlice) long5p() time.Duration { set := ts[int(float64(ts.Len())*0.95+0.5):] diff --git a/calcs_test.go b/calcs_test.go index 7fa8101..374b031 100644 --- a/calcs_test.go +++ b/calcs_test.go @@ -148,6 +148,10 @@ func TestCalc(t *testing.T) { t.Errorf("Expected 89000000, got %d\n", metrics.Time.Range) } + if metrics.Time.StdDev != 30772281 { + t.Errorf("Expected abc, got %d\n", metrics.Time.StdDev) + } + if metrics.Rate.Second != 22.72727272727273 { t.Errorf("Expected 22.73, got %0.2f\n", metrics.Rate.Second) } diff --git a/example/tachymeter-graphing/main.go b/example/tachymeter-graphing/main.go index e2493d1..eb6a831 100644 --- a/example/tachymeter-graphing/main.go +++ b/example/tachymeter-graphing/main.go @@ -14,7 +14,7 @@ func main() { // Run 3 iterations of a loop that we're // interesting in summarizing with tachymeter. - for iter := 0; iter <3; iter++ { + for iter := 0; iter < 3; iter++ { fmt.Printf("Running iteration %d\n", iter) // Capture timing data from the loop. for i := 0; i < 100; i++ { @@ -29,7 +29,6 @@ func main() { c.Reset() } - // Write out an HTML page with the // histogram for all iterations. err := tl.WriteHTML(".") diff --git a/example/tachymeter-simple/README.md b/example/tachymeter-simple/README.md index 3d8f27d..122647f 100644 --- a/example/tachymeter-simple/README.md +++ b/example/tachymeter-simple/README.md @@ -44,32 +44,33 @@ func main() { ### Output ``` $ $GOPATH/bin/tachymeter-simple -{"Time":{"Cumulative":"694.643892ms","HMean":"59.157µs","Avg":"13.892877ms","P50":"11.457787ms","P75":"20.14303ms","P95":"29.169708ms","P99":"31.149213ms","P999":"31.149213ms","Long5p":"30.62519ms","Short5p":"429.969µs","Max":"31.149213ms","Min":"1.778µs","Range":"31.147435ms"},"Rate":{"Second":71.97932721475654},"Samples":50,"Count":100,"Histogram":[{"1µs - 3.116ms":5},{"3.116ms - 6.231ms":5},{"6.231ms - 9.346ms":8},{"9.346ms - 12.46ms":8},{"12.46ms - 15.575ms":5},{"15.575ms - 18.69ms":4},{"18.69ms - 21.804ms":4},{"21.804ms - 24.919ms":4},{"24.919ms - 28.034ms":2},{"28.034ms - 31.149ms":5}]} +{"Time":{"Cumulative":"671.871ms","HMean":"125.38µs","Avg":"13.43742ms","P50":"13.165ms","P75":"20.058ms","P95":"27.536ms","P99":"30.043ms","P999":"30.043ms","Long5p":"29.749ms","Short5p":"399.666µs","Max":"30.043ms","Min":"4µs","Range":"30.039ms","StdDev":"8.385117ms"},"Rate":{"Second":74.41904770409796},"Samples":50,"Count":100,"Histogram":[{"4µs - 3.007ms":5},{"3.007ms - 6.011ms":4},{"6.011ms - 9.015ms":10},{"9.015ms - 12.019ms":6},{"12.019ms - 15.023ms":7},{"15.023ms - 18.027ms":3},{"18.027ms - 21.031ms":4},{"21.031ms - 24.035ms":3},{"24.035ms - 27.039ms":3},{"27.039ms - 30.043ms":5}]} 50 samples of 100 events -Cumulative: 694.643892ms -HMean: 59.157µs -Avg.: 13.892877ms -p50: 11.457787ms -p75: 20.14303ms -p95: 29.169708ms -p99: 31.149213ms -p999: 31.149213ms -Long 5%: 30.62519ms -Short 5%: 429.969µs -Max: 31.149213ms -Min: 1.778µs -Range: 31.147435ms -Rate/sec.: 71.98 +Cumulative: 671.871ms +HMean: 125.38µs +Avg.: 13.43742ms +p50: 13.165ms +p75: 20.058ms +p95: 27.536ms +p99: 30.043ms +p999: 30.043ms +Long 5%: 29.749ms +Short 5%: 399.666µs +Max: 30.043ms +Min: 4µs +Range: 30.039ms +StdDev: 8.385117ms +Rate/sec.: 74.42 - 1µs - 3.116ms -------- - 3.116ms - 6.231ms -------- - 6.231ms - 9.346ms --------------- - 9.346ms - 12.46ms --------------- - 12.46ms - 15.575ms -------- - 15.575ms - 18.69ms ----- - 18.69ms - 21.804ms ----- - 21.804ms - 24.919ms ----- - 24.919ms - 28.034ms - - 28.034ms - 31.149ms -------- + 4µs - 3.007ms ----- + 3.007ms - 6.011ms --- + 6.011ms - 9.015ms --------------- + 9.015ms - 12.019ms ------- + 12.019ms - 15.023ms --------- + 15.023ms - 18.027ms - + 18.027ms - 21.031ms --- + 21.031ms - 24.035ms - + 24.035ms - 27.039ms - + 27.039ms - 30.043ms ----- ``` diff --git a/tachymeter.go b/tachymeter.go index edef4cb..7b56d26 100644 --- a/tachymeter.go +++ b/tachymeter.go @@ -17,9 +17,9 @@ import ( // parameters. Size defines the sample capacity. // Tachymeter is thread safe. type Config struct { - Size int - Safe bool // Deprecated. Flag held on to as to not break existing users. - HBuckets int // Histogram buckets. + Size int + Safe bool // Deprecated. Flag held on to as to not break existing users. + HBins int // Histogram bins. } // Tachymeter holds event durations @@ -30,7 +30,7 @@ type Tachymeter struct { Times timeSlice Count uint64 WallTime time.Duration - HBuckets int + HBins int } // timeslice holds time.Duration values. @@ -61,6 +61,7 @@ type Metrics struct { Short5p time.Duration // Average of the shortest 5% event durations. Max time.Duration // Highest event duration. Min time.Duration // Lowest event duration. + StdDev time.Duration // Standard deviation. Range time.Duration // Event duration range (Max-Min). } Rate struct { @@ -68,25 +69,25 @@ type Metrics struct { // If SetWallTime was called, event duration avg = wall time / Metrics.Count Second float64 } - Histogram *Histogram // Frequency distribution of event durations in len(Histogram) buckets of HistogramBucketSize. - HistogramBucketSize time.Duration // The width of a histogram bucket in time. - Samples int // Number of events included in the sample set. - Count int // Total number of events observed. + Histogram *Histogram // Frequency distribution of event durations in len(Histogram) bins of HistogramBinSize. + HistogramBinSize time.Duration // The width of a histogram bin in time. + Samples int // Number of events included in the sample set. + Count int // Total number of events observed. } // New initializes a new Tachymeter. func New(c *Config) *Tachymeter { var hSize int - if c.HBuckets != 0 { - hSize = c.HBuckets + if c.HBins != 0 { + hSize = c.HBins } else { hSize = 10 } return &Tachymeter{ - Size: uint64(c.Size), - Times: make([]time.Duration, c.Size), - HBuckets: hSize, + Size: uint64(c.Size), + Times: make([]time.Duration, c.Size), + HBins: hSize, } } @@ -143,6 +144,7 @@ Short 5%%: %s Max: %s Min: %s Range: %s +StdDev: %s Rate/sec.: %.2f`, m.Samples, m.Count, @@ -159,6 +161,7 @@ Rate/sec.: %.2f`, m.Time.Max, m.Time.Min, m.Time.Range, + m.Time.StdDev, m.Rate.Second) } @@ -189,6 +192,7 @@ func (m *Metrics) MarshalJSON() ([]byte, error) { Max string Min string Range string + StdDev string } Rate struct { Second float64 @@ -211,6 +215,7 @@ func (m *Metrics) MarshalJSON() ([]byte, error) { Max string Min string Range string + StdDev string }{ Cumulative: m.Time.Cumulative.String(), HMean: m.Time.HMean.String(), @@ -225,6 +230,7 @@ func (m *Metrics) MarshalJSON() ([]byte, error) { Max: m.Time.Max.String(), Min: m.Time.Min.String(), Range: m.Time.Range.String(), + StdDev: m.Time.StdDev.String(), }, Rate: struct{ Second float64 }{ Second: m.Rate.Second, @@ -250,8 +256,8 @@ func (h *Histogram) String(s int) string { var min, max uint64 = math.MaxUint64, 0 // Get the histogram min/max counts. - for _, bucket := range *h { - for _, v := range bucket { + for _, bin := range *h { + for _, v := range bin { if v > max { max = v } @@ -264,8 +270,8 @@ func (h *Histogram) String(s int) string { var b bytes.Buffer // Build histogram string. - for _, bucket := range *h { - for k, v := range bucket { + for _, bin := range *h { + for k, v := range bin { // Get the bar length. blen := scale(float64(v), float64(min), float64(max), 1, float64(s)) line := fmt.Sprintf("%20s %s\n", k, strings.Repeat("-", int(blen)))