From 1e2e1f3dacb382c63ef203c3949e07bf9f027b9f Mon Sep 17 00:00:00 2001 From: Klaus Post Date: Tue, 21 Mar 2023 09:10:54 -0700 Subject: [PATCH] Add standard deviation for requests (#253) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The adds standard deviation to detailed analysis and compares for requests and TTFB. Examples: Analysis: ``` λ warp analyze -analyze.v warp-get-2020-06-24[154208]-jmuM.csv.zst ... Operation: GET (574228). Ran 1m0s. Size: 10000 bytes. Concurrency: 100. Requests considered: 573756: * Avg: 10ms, 50%: 10ms, 90%: 15ms, 99%: 24ms, Fastest: 0s, Slowest: 117ms, StdDev: 5ms * TTFB: Avg: 10ms, Best: 0s, 25th: 8ms, Median: 10ms, 75th: 13ms, 90th: 15ms, 99th: 23ms, Worst: 116ms StdDev: 5ms * First Access: Avg: 10ms, 50%: 10ms, 90%: 15ms, 99%: 20ms, Fastest: 1ms, Slowest: 25ms, StdDev: 4ms * First Access TTFB: Avg: 10ms, Best: 1ms, 25th: 8ms, Median: 10ms, 75th: 13ms, 90th: 15ms, 99th: 20ms, Worst: 25ms StdDev: 4ms * Last Access: Avg: 10ms, 50%: 10ms, 90%: 15ms, 99%: 19ms, Fastest: 1ms, Slowest: 22ms, StdDev: 4ms * Last Access TTFB: Avg: 10ms, Best: 1ms, 25th: 8ms, Median: 10ms, 75th: 13ms, 90th: 15ms, 99th: 19ms, Worst: 22ms StdDev: 4ms ``` Compare: ``` λ go build&&warp cmp -analyze.v warp-get-2020-06-24[154208]-jmuM.csv.zst warp-get-2020-06-24[153319]-hBwl.csv.zst 576728 operations loaded... Done! 581688 operations loaded... Done! ------------------- Operation: PUT * Average: -5.22% (-0.5 MiB/s) throughput, -5.22% (-48.8) obj/s * Requests: Avg: +4.15ms (+4%), P50: +4.6619ms (+4%), P99: +4.3328ms (+2%), Best: +3.7533ms (+17%), Worst: -82.0389ms (-24%) StdDev: +1.059646ms (+6%) * Fastest: -4.42% (-0.4 MiB/s) throughput, -4.42% (-42.9) obj/s * 50% Median: -4.42% (-0.4 MiB/s) throughput, -4.42% (-42.9) obj/s * Slowest: -13.69% (-1.2 MiB/s) throughput, -13.69% (-130.1) obj/s ``` Throughput stddev doesn't make much sense. And since requests are reflective of throughput we have what we need. --- cli/analyze.go | 6 +++++- pkg/aggregate/requests.go | 17 +++++++++++++++++ pkg/aggregate/ttfb.go | 7 +++++-- pkg/bench/analyze.go | 16 ++++++++++++++-- pkg/bench/compare.go | 16 ++++++++++++++-- pkg/bench/ops.go | 14 ++++++++++++++ 6 files changed, 69 insertions(+), 7 deletions(-) diff --git a/cli/analyze.go b/cli/analyze.go index c66b0d18..7d1f0f75 100644 --- a/cli/analyze.go +++ b/cli/analyze.go @@ -472,6 +472,7 @@ func printRequestAnalysis(ctx *cli.Context, ops aggregate.Operation, details boo ", 99%: ", time.Duration(reqs.Dur99Millis)*time.Millisecond, ", Fastest: ", time.Duration(reqs.FastestMillis)*time.Millisecond, ", Slowest: ", time.Duration(reqs.SlowestMillis)*time.Millisecond, + ", StdDev: ", time.Duration(reqs.StdDev)*time.Millisecond, "\n") if reqs.FirstByte != nil { @@ -487,6 +488,7 @@ func printRequestAnalysis(ctx *cli.Context, ops aggregate.Operation, details boo ", 99%: ", time.Duration(reqs.Dur99Millis)*time.Millisecond, ", Fastest: ", time.Duration(reqs.FastestMillis)*time.Millisecond, ", Slowest: ", time.Duration(reqs.SlowestMillis)*time.Millisecond, + ", StdDev: ", time.Duration(reqs.StdDev)*time.Millisecond, "\n") if reqs.FirstByte != nil { console.Print(" * First Access TTFB: ", reqs.FirstByte, "\n") @@ -501,6 +503,7 @@ func printRequestAnalysis(ctx *cli.Context, ops aggregate.Operation, details boo ", 99%: ", time.Duration(reqs.Dur99Millis)*time.Millisecond, ", Fastest: ", time.Duration(reqs.FastestMillis)*time.Millisecond, ", Slowest: ", time.Duration(reqs.SlowestMillis)*time.Millisecond, + ", StdDev: ", time.Duration(reqs.StdDev)*time.Millisecond, "\n") if reqs.FirstByte != nil { console.Print(" * Last Access TTFB: ", reqs.FirstByte, "\n") @@ -522,7 +525,8 @@ func printRequestAnalysis(ctx *cli.Context, ops aggregate.Operation, details boo "Fastest:", time.Duration(reqs.FastestMillis)*time.Millisecond, "Slowest:", time.Duration(reqs.SlowestMillis)*time.Millisecond, "50%:", time.Duration(reqs.DurMedianMillis)*time.Millisecond, - "90%:", time.Duration(reqs.Dur90Millis)*time.Millisecond) + "90%:", time.Duration(reqs.Dur90Millis)*time.Millisecond, + "StdDev:", time.Duration(reqs.StdDev)*time.Millisecond) if reqs.FirstByte != nil { console.Println("\t- First Byte:", reqs.FirstByte) } diff --git a/pkg/aggregate/requests.go b/pkg/aggregate/requests.go index 552ed604..f0b6ecf1 100644 --- a/pkg/aggregate/requests.go +++ b/pkg/aggregate/requests.go @@ -28,32 +28,48 @@ import ( type SingleSizedRequests struct { // Skipped if too little data. Skipped bool `json:"skipped"` + // Object size per operation. Can be 0. ObjSize int64 `json:"obj_size"` + // Total number of requests. Requests int `json:"requests"` + // Average request duration. DurAvgMillis int `json:"dur_avg_millis"` + // Median request duration. DurMedianMillis int `json:"dur_median_millis"` + // 90% request time. Dur90Millis int `json:"dur_90_millis"` + // 99% request time. Dur99Millis int `json:"dur_99_millis"` + // Fastest request time. FastestMillis int `json:"fastest_millis"` + // Slowest request time. SlowestMillis int `json:"slowest_millis"` + + // StdDev is the standard deviation of requests. + StdDev int `json:"std_dev_millis"` + // DurPct is duration percentiles. DurPct [101]int `json:"dur_percentiles_millis"` + // Time to first byte if applicable. FirstByte *TTFB `json:"first_byte,omitempty"` + // FirstAccess is filled if the same object is accessed multiple times. // This records the first touch of the object. FirstAccess *SingleSizedRequests `json:"first_access,omitempty"` LastAccess *SingleSizedRequests `json:"last_access,omitempty"` + // Host names, sorted. HostNames []string + // Request times by host. ByHost map[string]SingleSizedRequests `json:"by_host,omitempty"` } @@ -64,6 +80,7 @@ func (a *SingleSizedRequests) fill(ops bench.Operations) { a.Requests = len(ops) a.ObjSize = ops.FirstObjSize() a.DurAvgMillis = durToMillis(ops.AvgDuration()) + a.StdDev = durToMillis(ops.StdDev()) a.DurMedianMillis = durToMillis(ops.Median(0.5).Duration()) a.Dur90Millis = durToMillis(ops.Median(0.9).Duration()) a.Dur99Millis = durToMillis(ops.Median(0.99).Duration()) diff --git a/pkg/aggregate/ttfb.go b/pkg/aggregate/ttfb.go index 7b638182..fd6ca9d4 100644 --- a/pkg/aggregate/ttfb.go +++ b/pkg/aggregate/ttfb.go @@ -34,6 +34,7 @@ type TTFB struct { P90Millis int `json:"p90_millis"` P99Millis int `json:"p99_millis"` SlowestMillis int `json:"slowest_millis"` + StdDevMillis int `json:"std_dev_millis"` PercentilesMillis [101]int `json:"percentiles_millis"` } @@ -42,7 +43,7 @@ func (t TTFB) String() string { if t.AverageMillis == 0 { return "" } - return fmt.Sprintf("Avg: %v, Best: %v, 25th: %v, Median: %v, 75th: %v, 90th: %v, 99th: %v, Worst: %v", + return fmt.Sprintf("Avg: %v, Best: %v, 25th: %v, Median: %v, 75th: %v, 90th: %v, 99th: %v, Worst: %v StdDev: %v", time.Duration(t.AverageMillis)*time.Millisecond, time.Duration(t.FastestMillis)*time.Millisecond, time.Duration(t.P25Millis)*time.Millisecond, @@ -50,7 +51,8 @@ func (t TTFB) String() string { time.Duration(t.P75Millis)*time.Millisecond, time.Duration(t.P90Millis)*time.Millisecond, time.Duration(t.P99Millis)*time.Millisecond, - time.Duration(t.SlowestMillis)*time.Millisecond) + time.Duration(t.SlowestMillis)*time.Millisecond, + time.Duration(t.StdDevMillis)*time.Millisecond) } // TtfbFromBench converts from bench.TTFB @@ -66,6 +68,7 @@ func TtfbFromBench(t bench.TTFB) *TTFB { P75Millis: durToMillis(t.P75), P90Millis: durToMillis(t.P90), P99Millis: durToMillis(t.P99), + StdDevMillis: durToMillis(t.StdDev), FastestMillis: durToMillis(t.Best), } for i, v := range t.Percentiles[:] { diff --git a/pkg/bench/analyze.go b/pkg/bench/analyze.go index 9daddfac..4208a0b3 100644 --- a/pkg/bench/analyze.go +++ b/pkg/bench/analyze.go @@ -62,6 +62,7 @@ type TTFB struct { P90 time.Duration P99 time.Duration Worst time.Duration + StdDev time.Duration Percentiles [101]time.Duration `json:"percentiles_millis"` } @@ -121,7 +122,18 @@ func (o Operations) TTFB(start, end time.Time) TTFB { ttfb := op.TTFB() res.Average += ttfb } + avg := float64(res.Average) / float64(len(filtered)) res.Average /= time.Duration(len(filtered)) + res.StdDev = 0 + if len(filtered) > 1 { + var stdDev float64 + for _, op := range filtered { + ttfb := op.TTFB() + d := float64(ttfb) - avg + stdDev += d * d + } + res.StdDev = time.Duration(math.Sqrt(stdDev / float64(len(filtered)-1))) + } return res } @@ -361,6 +373,6 @@ func (t TTFB) String() string { if t.Average == 0 { return "" } - return fmt.Sprintf("Average: %v, Median: %v, Best: %v, Worst: %v", - t.Average.Round(time.Millisecond), t.Median.Round(time.Millisecond), t.Best.Round(time.Millisecond), t.Worst.Round(time.Millisecond)) + return fmt.Sprintf("Average: %v, Median: %v, Best: %v, Worst: %v, StdDev: %v", + t.Average.Round(time.Millisecond), t.Median.Round(time.Millisecond), t.Best.Round(time.Millisecond), t.Worst.Round(time.Millisecond), t.StdDev.Round(time.Millisecond)) } diff --git a/pkg/bench/compare.go b/pkg/bench/compare.go index 95e5664e..21060963 100644 --- a/pkg/bench/compare.go +++ b/pkg/bench/compare.go @@ -64,6 +64,7 @@ func (c *CmpReqs) Compare(before, after Operations) { P75: a.P75 - b.P75, P90: a.P90 - b.P90, P99: a.P99 - b.P99, + StdDev: a.StdDev - b.StdDev, } } @@ -78,6 +79,7 @@ type CmpRequests struct { P90 time.Duration P99 time.Duration Worst time.Duration + StdDev time.Duration } func (c *CmpRequests) fill(ops Operations) { @@ -92,6 +94,7 @@ func (c *CmpRequests) fill(ops Operations) { c.P90 = ops.Median(0.9).Duration() c.P99 = ops.Median(0.99).Duration() c.Worst = ops.Median(1).Duration() + c.StdDev = ops.StdDev() } // String returns a human readable representation of the TTFB comparison. @@ -99,7 +102,7 @@ func (c *CmpReqs) String() string { if c == nil { return "" } - return fmt.Sprintf("Avg: %s%v (%s%.f%%), P50: %s%v (%s%.f%%), P99: %s%v (%s%.f%%), Best: %s%v (%s%.f%%), Worst: %s%v (%s%.f%%)", + return fmt.Sprintf("Avg: %s%v (%s%.f%%), P50: %s%v (%s%.f%%), P99: %s%v (%s%.f%%), Best: %s%v (%s%.f%%), Worst: %s%v (%s%.f%%) StdDev: %s%v (%s%.f%%)", plusPositiveD(c.Average), c.Average.Round(time.Millisecond/20), plusPositiveD(c.Average), @@ -120,6 +123,10 @@ func (c *CmpReqs) String() string { c.Worst, plusPositiveD(c.Worst), 100*(float64(c.After.Worst)-float64(c.Before.Worst))/float64(c.Before.Worst), + plusPositiveD(c.StdDev), + c.StdDev, + plusPositiveD(c.StdDev), + 100*(float64(c.After.StdDev)-float64(c.Before.StdDev))/float64(c.Before.StdDev), ) } @@ -186,6 +193,7 @@ func (t TTFB) Compare(after TTFB) *TTFBCmp { P75: after.P75 - t.P75, P90: after.P90 - t.P90, P99: after.P99 - t.P99, + StdDev: after.StdDev - t.StdDev, }, Before: t, After: after, @@ -197,7 +205,7 @@ func (t *TTFBCmp) String() string { if t == nil { return "" } - return fmt.Sprintf("Avg: %s%v (%s%.f%%), P50: %s%v (%s%.f%%), P99: %s%v (%s%.f%%), Best: %s%v (%s%.f%%), Worst: %s%v (%s%.f%%)", + return fmt.Sprintf("Avg: %s%v (%s%.f%%), P50: %s%v (%s%.f%%), P99: %s%v (%s%.f%%), Best: %s%v (%s%.f%%), Worst: %s%v (%s%.f%%) StdDev: %s%v (%s%.f%%)", plusPositiveD(t.Average), t.Average.Round(time.Millisecond/20), plusPositiveD(t.Average), @@ -218,6 +226,10 @@ func (t *TTFBCmp) String() string { t.Worst, plusPositiveD(t.Worst), 100*(float64(t.After.Worst)-float64(t.Before.Worst))/float64(t.Before.Worst), + plusPositiveD(t.StdDev), + t.StdDev, + plusPositiveD(t.StdDev), + 100*(float64(t.After.StdDev)-float64(t.Before.StdDev))/float64(t.Before.StdDev), ) } diff --git a/pkg/bench/ops.go b/pkg/bench/ops.go index e5c2fcb4..3fc7329c 100644 --- a/pkg/bench/ops.go +++ b/pkg/bench/ops.go @@ -589,6 +589,20 @@ func (o Operations) AvgDuration() time.Duration { return total / time.Duration(len(o)) } +// StdDev returns the standard deviation. +func (o Operations) StdDev() time.Duration { + if len(o) <= 1 { + return 0 + } + avg := o.AvgDuration() + var total float64 + for _, op := range o { + delta := float64(avg - op.Duration()) + total += delta * delta + } + return time.Duration(math.Sqrt(total / float64(len(o)-1))) +} + // SizeSegment is a size segment. type SizeSegment struct { Smallest int64