Improve reporting

client.go

@@ -11,52 +11,65 @@ import (
 )
 
 type clientStats struct {
-	mu         sync.Mutex
-	NumTotal   int           // Number of requests
-	NumErrors  int           // Number of errors
-	TimeErrors time.Duration // Duration of error responses specifically
-	TimeTotal  time.Duration // Total duration of requests
-	Errors     map[string]int
+	mu sync.Mutex
+
+	numTotal  int // Number of requests
+	numErrors int // Number of errors
+
+	timeErrors time.Duration // Duration of error responses specifically
+	errors     map[string]int
+
+	timing histogram
 }
 
 func (stats *clientStats) Count(err error, elapsed time.Duration) {
 	stats.mu.Lock()
 	defer stats.mu.Unlock()
 
-	stats.NumTotal += 1
+	stats.numTotal += 1
+	stats.timing.Add(elapsed.Seconds())
 	if err != nil {
-		stats.NumErrors += 1
-		stats.TimeErrors += elapsed
+		stats.numErrors += 1
+		stats.timeErrors += elapsed
 
-		if stats.Errors == nil {
-			stats.Errors = map[string]int{}
+		if stats.errors == nil {
+			stats.errors = map[string]int{}
 		}
-		stats.Errors[err.Error()] += 1
+		stats.errors[err.Error()] += 1
 	}
-	stats.TimeTotal += elapsed
 }
 
 func (stats *clientStats) Render(w io.Writer) error {
-	if stats.NumTotal == 0 {
+	// TODO: Use templating?
+	// TODO: Support JSON
+	if stats.numTotal == 0 {
 		fmt.Fprintf(w, "   No requests.")
 	}
 	var errRate, rps float64
 
-	errRate = float64(stats.NumErrors*100) / float64(stats.NumTotal)
-	rps = float64(stats.NumTotal) / stats.TimeTotal.Seconds()
-	reqAvg := stats.TimeTotal / time.Duration(stats.NumTotal)
+	errRate = float64(stats.numErrors*100) / float64(stats.numTotal)
+	rps = float64(stats.numTotal) / stats.timing.Total()
 
-	fmt.Fprintf(w, "   Requests/Sec: %0.2f", rps)
-	if stats.NumErrors > 0 && stats.NumErrors != stats.NumTotal {
-		errAvg := stats.TimeErrors / time.Duration(stats.NumErrors)
-		fmt.Fprintf(w, ", %s per error", errAvg)
+	fmt.Fprintf(w, "\n   Requests:   %0.2f per second", rps)
+	if stats.numErrors > 0 && stats.numErrors != stats.numTotal {
+		errAvg := float64(stats.numErrors) / stats.timeErrors.Seconds()
+		fmt.Fprintf(w, ", %0.2f per second for errors", errAvg)
 	}
+
 	fmt.Fprintf(w, "\n")
-	fmt.Fprintf(w, "   Average:      %s\n", reqAvg)
-	fmt.Fprintf(w, "   Errors:       %0.2f%%\n", errRate)
+	fmt.Fprintf(w, "   Timing:     %0.4fs avg, %0.4fs min, %0.4fs max\n", stats.timing.Average(), stats.timing.Min(), stats.timing.Max())
+
+	fmt.Fprintf(w, "\n   Percentiles:\n")
+	buckets := []int{25, 50, 75, 90, 95, 99}
+	percentiles := stats.timing.Percentiles(buckets...)
+	for i, bucket := range buckets {
+		fmt.Fprintf(w, "     %d%% in %0.4fs\n", bucket, percentiles[i])
+	}
+
+	fmt.Fprintf(w, "\n   Errors: %0.2f%%\n", errRate)
 
-	for msg, num := range stats.Errors {
-		fmt.Fprintf(w, "   * [%d] %q\n", num, msg)
+	for msg, num := range stats.errors {
+		fmt.Fprintf(w, "     %d × %q\n", num, msg)
 	}
 
 	return nil

histogram.go

@@ -0,0 +1,76 @@
+package main
+
+import "sort"
+
+// TODO: Replace histogram implementation with a sparse bucket based one so
+// it's memory-bounded.
+
+type histogram struct {
+	all   []float64
+	min   float64
+	max   float64
+	total float64
+}
+
+func (h *histogram) Add(point float64) {
+	h.all = append(h.all, point)
+	h.total += point
+	if len(h.all) == 1 || h.min > point {
+		h.min = point
+	}
+	if h.max < point {
+		h.max = point
+	}
+}
+
+func (h *histogram) Total() float64 {
+	return h.total
+}
+
+func (h *histogram) Min() float64 {
+	return h.min
+}
+
+func (h *histogram) Max() float64 {
+	return h.max
+}
+
+func (h *histogram) Average() float64 {
+	return h.total / float64(len(h.all))
+}
+
+func (h *histogram) Len() int {
+	return len(h.all)
+}
+
+// Percentiles takes buckets in whole percentages (e.g. 95 is 95%) and returns
+// a slice with percentile values in the corresponding index. Buckets must be
+// in-order.
+func (h *histogram) Percentiles(buckets ...int) []float64 {
+	r := make([]float64, len(buckets))
+	if len(h.all) == 0 {
+		return r
+	}
+
+	sort.Float64s(h.all)
+
+	for i, j := 0, 0; i < len(h.all) || j < len(buckets); i++ {
+		if i >= len(h.all) {
+			// Fill up the remaining buckets with the highest value.
+			r[j] = h.all[len(h.all)-1]
+			j++
+			continue
+		}
+
+		current := i * 100 / len(h.all)
+		if current >= buckets[j] {
+			r[j] = h.all[i]
+			j++
+		}
+
+		if j >= len(buckets) {
+			break
+		}
+	}
+	return r
+}

histogram_test.go

@@ -0,0 +1,38 @@
+package main
+
+import "testing"
+
+func TestHistogram(t *testing.T) {
+	h := histogram{}
+
+	for i := 1; i <= 1000; i++ {
+		h.Add(float64(i))
+	}
+
+	if got, want := h.Total(), 500500.0; got != want {
+		t.Errorf("got: %0.4f; want: %0.4f", got, want)
+	}
+	if got, want := h.Average(), 500.5; got != want {
+		t.Errorf("got: %0.4f; want: %0.4f", got, want)
+	}
+	if got, want := h.Min(), 1.0; got != want {
+		t.Errorf("got: %0.4f; want: %0.4f", got, want)
+	}
+	if got, want := h.Max(), 1000.0; got != want {
+		t.Errorf("got: %0.4f; want: %0.4f", got, want)
+	}
+
+	percentiles := h.Percentiles(5, 50, 99, 100)
+	if got, want := percentiles[0], 51.0; got != want {
+		t.Errorf("got: %0.4f; want: %0.4f", got, want)
+	}
+	if got, want := percentiles[1], 501.0; got != want {
+		t.Errorf("got: %0.4f; want: %0.4f", got, want)
+	}
+	if got, want := percentiles[2], 991.0; got != want {
+		t.Errorf("got: %0.4f; want: %0.4f", got, want)
+	}
+	if got, want := percentiles[3], 1000.0; got != want {
+		t.Errorf("got: %0.4f; want: %0.4f", got, want)
+	}
+}

main.go

@@ -30,6 +30,11 @@ type Options struct {
 
 	//Source      string `long:"source" description:"Where to get requests from (options: stdin-jsons, ethspam)" default:"stdin-jsons"` // Someday: stdin-tcpdump, file://foo.json, ws://remote-endpoint
 
+	// TODO: Specify additional headers/configs per-endpoint (e.g. auth headers)
+	// TODO: Periodic reporting for long-running tests?
+	// TODO: Toggle compare results? Could probably reach higher throughput without result comparison.
+	// TODO: Add latency offcheck set before starting
+
 	Verbose []bool `long:"verbose" short:"v" description:"Show verbose logging."`
 	Version bool   `long:"version" description:"Print version and exit."`
 }
@@ -146,7 +151,7 @@ func run(ctx context.Context, options Options) error {
 
 	if len(options.Verbose) > 0 {
 		r.MismatchedResponse = func(resps []Response) {
-			logger.Info().Msgf("mismatched responses: %s", Responses(resps).String())
+			logger.Info().Int("id", int(resps[0].ID)).Msgf("mismatched responses: %s", Responses(resps).String())
 		}
 	}
 

report.go

@@ -40,7 +40,7 @@ func (r *report) Render(w io.Writer) error {
 	fmt.Fprintf(w, "\n** Summary for %d endpoints:\n", len(r.Clients))
 	fmt.Fprintf(w, "   Completed:  %d results with %d total requests\n", r.completed, r.requests)
 	if r.requests > 0 {
-		fmt.Fprintf(w, "   Elapsed:    %s request avg, %s total run time\n", r.elapsed/time.Duration(r.requests), time.Now().Sub(r.started))
+		fmt.Fprintf(w, "   Timing:     %s request avg, %s total run time\n", r.elapsed/time.Duration(r.requests), time.Now().Sub(r.started))
 		fmt.Fprintf(w, "   Errors:     %d (%0.2f%%)\n", r.errors, float64(r.errors*100)/float64(r.requests))
 	}
 	fmt.Fprintf(w, "   Mismatched: %d\n", r.mismatched)
@@ -96,7 +96,12 @@ func (r *report) compareResponses(resp Response) {
 		}
 	}
 
-	logger.Debug().Int("id", int(resp.ID)).Int("mismatched", r.mismatched).Durs("ms", durations).Err(resp.Err).Msg("result")
+	// TODO: Check for JSONRPC error objects?
+
+	l := logger.Debug().Int("id", int(resp.ID)).Int("mismatched", r.mismatched).Durs("ms", durations).Err(resp.Err)
+	// For super-debugging:
+	// l = l.Bytes("req", resp.Request.Line).Bytes("resp", resp.Body)
+	l.Msg("result")
 }
 
 func (r *report) handle(resp Response) error {

transport.go

@@ -32,6 +32,7 @@ func NewTransport(endpoint string, timeout time.Duration) (Transport, error) {
 
 type Transport interface {
 	// TODO: Add context?
+	// TODO: Should this be: Do(Request) (Response, error)?
 	Send(body []byte) ([]byte, error)
 }