Benchmarks middleware (#22)

* add basic benchmarking middleware

this thing is collecting and reporting performance metrics, i.e. number of requests, req/sec, max/min resp time, and average resp time for a given (last) duration

* add cleanup test

* lint: simpler nowFn init

* typo in comment

* drop unneeded assignment

* don't try to aggregate on under 1s range

Author: umputun

README.md

@@ -119,6 +119,12 @@ Maybe middleware will allow you to change the flow of the middleware stack execu
 value of maybeFn(request). This is useful for example if you'd like to skip a middleware handler if
 a request does not satisfy the maybeFn logic.
 
+### Benchmarks middleware
+
+Benchmarks middleware allows to measure the time of request handling, number of request per second and report aggregated metrics. This middleware keeps track of the request in the memory and keep up to 900 points (15 minutes, data-point per second).
+
+In order to retrieve the data user should call `Stats(d duration)` method. duration is the time window for which the benchmark data should be returned. It can be any duration from 1s to 15m.
+
 ## Helpers
 
 - `rest.Wrap` - converts a list of middlewares to nested handlers calls (in reverse order)

benchmarks.go

@@ -0,0 +1,146 @@
+package rest
+
+import (
+	"container/list"
+	"net/http"
+	"sync"
+	"time"
+)
+
+var maxTimeRange = time.Duration(15) * time.Minute
+
+// Benchmarks is a basic benchmarking middleware collecting and reporting performance metrics
+// It keeps track of the requests speeds and counts in 1s benchData buckets ,limiting the number of buckets
+// to maxTimeRange. User can request the benchmark for any time duration. This is intended to be used
+// for retrieving the benchmark data for the last minute, 5 minutes and up to maxTimeRange.
+type Benchmarks struct {
+	st   time.Time
+	data *list.List
+	lock sync.RWMutex
+
+	nowFn func() time.Time // for testing only
+}
+
+type benchData struct {
+	// 1s aggregates
+	requests    int
+	respTime    time.Duration
+	minRespTime time.Duration
+	maxRespTime time.Duration
+	ts          time.Time
+}
+
+// BenchmarkStats holds the stats for a given interval
+type BenchmarkStats struct {
+	Requests        int     `json:"total_requests"`
+	RequestsSec     float64 `json:"total_requests_sec"`
+	AverageRespTime float64 `json:"average_resp_time"`
+	MinRespTime     float64 `json:"min_resp_time"`
+	MaxRespTime     float64 `json:"max_resp_time"`
+}
+
+// NewBenchmarks creates a new benchmark middleware
+func NewBenchmarks() *Benchmarks {
+	res := &Benchmarks{
+		st:    time.Now(),
+		data:  list.New(),
+		nowFn: time.Now,
+	}
+	return res
+}
+
+// Handler calculates 1/5/10m request per second and allows to access those values
+func (b *Benchmarks) Handler(next http.Handler) http.Handler {
+
+	fn := func(w http.ResponseWriter, r *http.Request) {
+		st := b.nowFn()
+		defer func() {
+			b.update(time.Since(st))
+		}()
+		next.ServeHTTP(w, r)
+	}
+	return http.HandlerFunc(fn)
+}
+
+func (b *Benchmarks) update(reqDuration time.Duration) {
+	now := b.nowFn().Truncate(time.Second)
+
+	b.lock.Lock()
+	defer b.lock.Unlock()
+
+	// keep maxTimeRange in the list, drop the rest
+	for e := b.data.Front(); e != nil; e = e.Next() {
+		if b.data.Front().Value.(benchData).ts.After(b.nowFn().Add(-maxTimeRange)) {
+			break
+		}
+		b.data.Remove(b.data.Front())
+	}
+
+	last := b.data.Back()
+	if last == nil || last.Value.(benchData).ts.Before(now) {
+		b.data.PushBack(benchData{requests: 1, respTime: reqDuration, ts: now,
+			minRespTime: reqDuration, maxRespTime: reqDuration})
+		return
+	}
+
+	bd := last.Value.(benchData)
+	bd.requests++
+	bd.respTime += reqDuration
+
+	if bd.minRespTime == 0 || reqDuration < bd.minRespTime {
+		bd.minRespTime = reqDuration
+	}
+	if bd.maxRespTime == 0 || reqDuration > bd.maxRespTime {
+		bd.maxRespTime = reqDuration
+	}
+
+	last.Value = bd
+}
+
+// Stats returns the current benchmark stats for the given duration
+func (b *Benchmarks) Stats(interval time.Duration) BenchmarkStats {
+	if interval < time.Second { // minimum interval is 1s due to the bucket size
+		return BenchmarkStats{}
+	}
+
+	b.lock.RLock()
+	defer b.lock.RUnlock()
+
+	var (
+		requests int
+		respTime time.Duration
+	)
+
+	stInterval, fnInterval := time.Time{}, time.Time{}
+	var minRespTime, maxRespTime time.Duration
+	for e := b.data.Back(); e != nil; e = e.Prev() { // reverse order
+		bd := e.Value.(benchData)
+		if bd.ts.Before(b.nowFn().Add(-interval)) {
+			break
+		}
+		if minRespTime == 0 || bd.minRespTime < minRespTime {
+			minRespTime = bd.minRespTime
+		}
+		if maxRespTime == 0 || bd.maxRespTime > maxRespTime {
+			maxRespTime = bd.maxRespTime
+		}
+		requests += bd.requests
+		respTime += bd.respTime
+		if fnInterval.IsZero() {
+			fnInterval = bd.ts.Add(time.Second)
+		}
+		stInterval = bd.ts
+	}
+
+	if requests == 0 {
+		return BenchmarkStats{}
+	}
+
+	return BenchmarkStats{
+		Requests:        requests,
+		RequestsSec:     float64(requests) / (fnInterval.Sub(stInterval).Seconds()),
+		AverageRespTime: respTime.Seconds() / float64(requests),
+		MinRespTime:     minRespTime.Seconds(),
+		MaxRespTime:     maxRespTime.Seconds(),
+	}
+}

benchmarks_test.go

@@ -0,0 +1,118 @@
+package rest
+
+import (
+	"net/http"
+	"net/http/httptest"
+	"testing"
+	"time"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+)
+
+func TestBenchmark_Stats(t *testing.T) {
+	bench := NewBenchmarks()
+	bench.update(time.Millisecond * 50)
+	bench.update(time.Millisecond * 150)
+	bench.update(time.Millisecond * 250)
+	bench.update(time.Millisecond * 100)
+
+	{
+		res := bench.Stats(time.Minute)
+		t.Logf("%+v", res)
+		assert.Equal(t, BenchmarkStats{Requests: 4, RequestsSec: 4, AverageRespTime: 0.1375,
+			MinRespTime: (time.Millisecond * 50).Seconds(), MaxRespTime: (time.Millisecond * 250).Seconds()}, res)
+	}
+
+	{
+		res := bench.Stats(time.Second * 5)
+		t.Logf("%+v", res)
+		assert.Equal(t, BenchmarkStats{Requests: 4, RequestsSec: 4, AverageRespTime: 0.1375,
+			MinRespTime: (time.Millisecond * 50).Seconds(), MaxRespTime: (time.Millisecond * 250).Seconds()}, res)
+	}
+
+	{
+		res := bench.Stats(time.Millisecond * 999)
+		t.Logf("%+v", res)
+		assert.Equal(t, BenchmarkStats{}, res)
+	}
+}
+
+func TestBenchmark_Stats2s(t *testing.T) {
+	bench := NewBenchmarks()
+	bench.update(time.Millisecond * 50)
+	bench.update(time.Millisecond * 150)
+	bench.update(time.Millisecond * 250)
+	time.Sleep(time.Second)
+	bench.update(time.Millisecond * 100)
+
+	res := bench.Stats(time.Minute)
+	t.Logf("%+v", res)
+	assert.Equal(t, BenchmarkStats{Requests: 4, RequestsSec: 2, AverageRespTime: 0.1375,
+		MinRespTime: (time.Millisecond * 50).Seconds(), MaxRespTime: (time.Millisecond * 250).Seconds()}, res)
+}
+
+func TestBenchmark_Cleanup(t *testing.T) {
+	bench := NewBenchmarks()
+	for i := 0; i < 1000; i++ {
+		bench.nowFn = func() time.Time {
+			return time.Date(2022, 5, 15, 0, 0, 0, 0, time.UTC).Add(time.Duration(i) * time.Second) // every 2s fake time
+		}
+		bench.update(time.Millisecond * 50)
+	}
+
+	{
+		res := bench.Stats(time.Hour)
+		t.Logf("%+v", res)
+		assert.Equal(t, BenchmarkStats{Requests: 900, RequestsSec: 1, AverageRespTime: 0.05,
+			MinRespTime: (time.Millisecond * 50).Seconds(), MaxRespTime: (time.Millisecond * 50).Seconds()}, res)
+	}
+	{
+		res := bench.Stats(time.Minute)
+		t.Logf("%+v", res)
+		assert.Equal(t, BenchmarkStats{Requests: 60, RequestsSec: 1, AverageRespTime: 0.05,
+			MinRespTime: (time.Millisecond * 50).Seconds(), MaxRespTime: (time.Millisecond * 50).Seconds()}, res)
+	}
+
+	assert.Equal(t, 900, bench.data.Len())
+}
+
+func TestBenchmarks_Handler(t *testing.T) {
+	handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		_, err := w.Write([]byte("blah blah"))
+		time.Sleep(time.Millisecond * 50)
+		require.NoError(t, err)
+	})
+
+	bench := NewBenchmarks()
+	ts := httptest.NewServer(bench.Handler(handler))
+	defer ts.Close()
+
+	for i := 0; i < 100; i++ {
+		resp, err := ts.Client().Get(ts.URL)
+		require.NoError(t, err)
+		assert.Equal(t, http.StatusOK, resp.StatusCode)
+	}
+
+	{
+		res := bench.Stats(time.Minute)
+		t.Logf("%+v", res)
+		assert.Equal(t, 100, res.Requests)
+		assert.True(t, res.RequestsSec <= 20 && res.RequestsSec >= 10)
+		assert.InDelta(t, 0.05, res.AverageRespTime, 0.1)
+		assert.InDelta(t, 0.05, res.MinRespTime, 0.1)
+		assert.InDelta(t, 0.05, res.MaxRespTime, 0.1)
+		assert.True(t, res.MaxRespTime >= res.MinRespTime)
+	}
+
+	{
+		res := bench.Stats(time.Minute * 15)
+		t.Logf("%+v", res)
+		assert.Equal(t, 100, res.Requests)
+		assert.True(t, res.RequestsSec <= 20 && res.RequestsSec >= 10)
+		assert.InDelta(t, 0.05, res.AverageRespTime, 0.1)
+		assert.InDelta(t, 0.05, res.MinRespTime, 0.1)
+		assert.InDelta(t, 0.05, res.MaxRespTime, 0.1)
+		assert.True(t, res.MaxRespTime >= res.MinRespTime)
+	}
+}