From 22488b3c3b69a5b371b7566371624d7c21f722df Mon Sep 17 00:00:00 2001 From: Umputun Date: Sun, 15 May 2022 15:35:12 -0500 Subject: [PATCH 1/6] add basic benchmarking middleware this thing is collecting and reporting performance metrics, i.e. number of request, req/sec, max/min resp time and average resp time for a given (last) duration --- benchmarks.go | 140 +++++++++++++++++++++++++++++++++++++++++++++ benchmarks_test.go | 90 +++++++++++++++++++++++++++++ 2 files changed, 230 insertions(+) create mode 100644 benchmarks.go create mode 100644 benchmarks_test.go diff --git a/benchmarks.go b/benchmarks.go new file mode 100644 index 0000000..7753b51 --- /dev/null +++ b/benchmarks.go @@ -0,0 +1,140 @@ +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 of requests speed and count 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 +} + +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(), + } + 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 := time.Now() + defer func() { + reqDuration := time.Since(st) + b.update(reqDuration) + }() + next.ServeHTTP(w, r) + } + return http.HandlerFunc(fn) +} + +func (b *Benchmarks) update(reqDuration time.Duration) { + now := time.Now().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(time.Now().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 { + 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(time.Now().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(), + } +} diff --git a/benchmarks_test.go b/benchmarks_test.go new file mode 100644 index 0000000..f141e04 --- /dev/null +++ b/benchmarks_test.go @@ -0,0 +1,90 @@ +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) + } +} + +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 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.MinRespTime >= 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.MinRespTime >= res.MinRespTime) + } +} From c5ac4064b6d2acb0108a16c2ef9becd47d922da8 Mon Sep 17 00:00:00 2001 From: Umputun Date: Sun, 15 May 2022 15:47:39 -0500 Subject: [PATCH 2/6] add cleanup test --- README.md | 6 ++++++ benchmarks.go | 13 +++++++++---- benchmarks_test.go | 32 +++++++++++++++++++++++++++----- 3 files changed, 42 insertions(+), 9 deletions(-) diff --git a/README.md b/README.md index 82ad44e..391dafc 100644 --- a/README.md +++ b/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) diff --git a/benchmarks.go b/benchmarks.go index 7753b51..34cae81 100644 --- a/benchmarks.go +++ b/benchmarks.go @@ -17,6 +17,8 @@ type Benchmarks struct { st time.Time data *list.List lock sync.RWMutex + + nowFn func() time.Time // for testing only } type benchData struct { @@ -42,6 +44,9 @@ func NewBenchmarks() *Benchmarks { res := &Benchmarks{ st: time.Now(), data: list.New(), + nowFn: func() time.Time { + return time.Now() + }, } return res } @@ -50,7 +55,7 @@ func NewBenchmarks() *Benchmarks { func (b *Benchmarks) Handler(next http.Handler) http.Handler { fn := func(w http.ResponseWriter, r *http.Request) { - st := time.Now() + st := b.nowFn() defer func() { reqDuration := time.Since(st) b.update(reqDuration) @@ -61,14 +66,14 @@ func (b *Benchmarks) Handler(next http.Handler) http.Handler { } func (b *Benchmarks) update(reqDuration time.Duration) { - now := time.Now().Truncate(time.Second) + 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(time.Now().Add(-maxTimeRange)) { + if b.data.Front().Value.(benchData).ts.After(b.nowFn().Add(-maxTimeRange)) { break } b.data.Remove(b.data.Front()) @@ -109,7 +114,7 @@ func (b *Benchmarks) Stats(interval time.Duration) BenchmarkStats { 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(time.Now().Add(-interval)) { + if bd.ts.Before(b.nowFn().Add(-interval)) { break } if minRespTime == 0 || bd.minRespTime < minRespTime { diff --git a/benchmarks_test.go b/benchmarks_test.go index f141e04..c220f05 100644 --- a/benchmarks_test.go +++ b/benchmarks_test.go @@ -11,7 +11,6 @@ import ( ) func TestBenchmark_Stats(t *testing.T) { - bench := NewBenchmarks() bench.update(time.Millisecond * 50) bench.update(time.Millisecond * 150) @@ -34,7 +33,6 @@ func TestBenchmark_Stats(t *testing.T) { } func TestBenchmark_Stats2s(t *testing.T) { - bench := NewBenchmarks() bench.update(time.Millisecond * 50) bench.update(time.Millisecond * 150) @@ -48,8 +46,32 @@ func TestBenchmark_Stats2s(t *testing.T) { MinRespTime: (time.Millisecond * 50).Seconds(), MaxRespTime: (time.Millisecond * 250).Seconds()}, res) } -func TestBenchmarks_Handler(t *testing.T) { +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) @@ -74,7 +96,7 @@ func TestBenchmarks_Handler(t *testing.T) { 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.MinRespTime >= res.MinRespTime) + assert.True(t, res.MaxRespTime >= res.MinRespTime) } { @@ -85,6 +107,6 @@ func TestBenchmarks_Handler(t *testing.T) { 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.MinRespTime >= res.MinRespTime) + assert.True(t, res.MaxRespTime >= res.MinRespTime) } } From 29795eb0e5b2be3b41523725b1327d505267fada Mon Sep 17 00:00:00 2001 From: Umputun Date: Sun, 15 May 2022 15:49:55 -0500 Subject: [PATCH 3/6] lint: simpler nowFn init --- benchmarks.go | 8 +++----- 1 file changed, 3 insertions(+), 5 deletions(-) diff --git a/benchmarks.go b/benchmarks.go index 34cae81..1713963 100644 --- a/benchmarks.go +++ b/benchmarks.go @@ -42,11 +42,9 @@ type BenchmarkStats struct { // NewBenchmarks creates a new benchmark middleware func NewBenchmarks() *Benchmarks { res := &Benchmarks{ - st: time.Now(), - data: list.New(), - nowFn: func() time.Time { - return time.Now() - }, + st: time.Now(), + data: list.New(), + nowFn: time.Now, } return res } From aeccbbfd3463334ad3b4e8a4a0465337c1d0fd21 Mon Sep 17 00:00:00 2001 From: Umputun Date: Sun, 15 May 2022 16:00:36 -0500 Subject: [PATCH 4/6] typo in comment --- benchmarks.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/benchmarks.go b/benchmarks.go index 1713963..b854f61 100644 --- a/benchmarks.go +++ b/benchmarks.go @@ -10,7 +10,7 @@ import ( var maxTimeRange = time.Duration(15) * time.Minute // Benchmarks is a basic benchmarking middleware collecting and reporting performance metrics -// It keeps track of the of requests speed and count in 1s benchData buckets limiting the number of buckets +// 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 { From 61551cbf7e02e164a3f5daaef3c04aee4a5cde85 Mon Sep 17 00:00:00 2001 From: Umputun Date: Sun, 15 May 2022 16:01:35 -0500 Subject: [PATCH 5/6] drop unneeded assignment --- benchmarks.go | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/benchmarks.go b/benchmarks.go index b854f61..1f8a24a 100644 --- a/benchmarks.go +++ b/benchmarks.go @@ -55,8 +55,7 @@ func (b *Benchmarks) Handler(next http.Handler) http.Handler { fn := func(w http.ResponseWriter, r *http.Request) { st := b.nowFn() defer func() { - reqDuration := time.Since(st) - b.update(reqDuration) + b.update(time.Since(st)) }() next.ServeHTTP(w, r) } From fe81bffa15f2a591d92852cde8791921714a278a Mon Sep 17 00:00:00 2001 From: Umputun Date: Sun, 15 May 2022 16:05:12 -0500 Subject: [PATCH 6/6] don't try to aggregate on under 1s range --- benchmarks.go | 4 ++++ benchmarks_test.go | 6 ++++++ 2 files changed, 10 insertions(+) diff --git a/benchmarks.go b/benchmarks.go index 1f8a24a..acccb20 100644 --- a/benchmarks.go +++ b/benchmarks.go @@ -99,6 +99,10 @@ func (b *Benchmarks) update(reqDuration time.Duration) { // 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() diff --git a/benchmarks_test.go b/benchmarks_test.go index c220f05..347ad75 100644 --- a/benchmarks_test.go +++ b/benchmarks_test.go @@ -30,6 +30,12 @@ func TestBenchmark_Stats(t *testing.T) { 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) {