Timer Middleware memory leak #230
Description
When investigating memory usage for an app that uses this project, I noticed that memory usage continually climbed over time with thousands of requests. After further investigation I think I have identified the problem being in the timer middleware.
Heap profile:
(pprof) top10
Showing nodes accounting for 1011.71MB, 88.76% of 1139.81MB total
Dropped 89 nodes (cum <= 5.70MB)
Showing top 10 nodes out of 46
flat flat% sum% cum cum%
214.05MB 18.78% 18.78% 298.56MB 26.19% $NAME_REMOVED/vendor/github.com/ant0ine/go-json-rest/rest.(*TimerMiddleware).MiddlewareFunc.func1
Memory Allocation List:
(pprof) list MiddlewareFunc.func1
ROUTINE ======================== $NAME_REMOVED/vendor/github.com/ant0ine/go-json-rest/rest.(*TimerMiddleware).MiddlewareFunc.func1 in $NAME_REMOVED/vendor/github.com/ant0ine/go-json-rest/rest/timer.go
214.05MB 298.56MB (flat, cum) 26.19% of Total
. . 11:
. . 12:// MiddlewareFunc makes TimerMiddleware implement the Middleware interface.
. . 13:func (mw *TimerMiddleware) MiddlewareFunc(h HandlerFunc) HandlerFunc {
. . 14: return func(w ResponseWriter, r *Request) {
. . 15:
22.50MB 22.50MB 16: start := time.Now()
189.55MB 189.55MB 17: r.Env["START_TIME"] = &start
. . 18:
. . 19: // call the handler
. 84.51MB 20: h(w, r)
. . 21:
. . 22: end := time.Now()
2MB 2MB 23: elapsed := end.Sub(start)
. . 24: r.Env["ELAPSED_TIME"] = &elapsed
. . 25: }
. . 26:}
It seemed odd that there was a large memory profile for a time allocation. Looking into this closer it seemed like the env values were escaping to the heap and is not garbage collected:
$ go test -gcflags '-m'
# github.com/snagles/go-json-rest-test
./example_test.go:44:9: func literal escapes to heap
./example_test.go:44:9: func literal escapes to heap
./example_test.go:43:63: leaking param: h to result ~r1 level=-1
./example_test.go:47:23: &start escapes to heap
./example_test.go:47:25: &start escapes to heap
./example_test.go:46:3: moved to heap: start
./example_test.go:44:40: leaking param: w
./example_test.go:44:40: leaking param: r
./example_test.go:54:25: &elapsed escapes to heap
./example_test.go:54:27: &elapsed escapes to heap
./example_test.go:53:3: moved to heap: elapsed
I've removed the reference and changed &start and &end to "start" and "end" and that kept the memory on the stack.
Test Program
package test
import (
"log"
"sync"
"testing"
"time"
"github.com/ant0ine/go-json-rest/rest"
"github.com/ant0ine/go-json-rest/rest/test"
)
func TestSimpleRequest(t *testing.T) {
api := rest.NewApi()
api.Use(&TimerMiddleware{})
router, err := rest.MakeRouter(
rest.Get("/r", func(w rest.ResponseWriter, r *rest.Request) {
}),
)
if err != nil {
log.Fatal(err)
}
api.SetApp(router)
var wg sync.WaitGroup
wg.Add(5000)
for i := 0; i < 5000; i++ {
go func(wg *sync.WaitGroup) {
test.RunRequest(t, api.MakeHandler(), test.MakeSimpleRequest("GET", "http://1.2.3.4/r", nil))
wg.Done()
}(&wg)
}
wg.Wait()
}
// TimerMiddleware computes the elapsed time spent during the execution of the wrapped handler.
// The result is available to the wrapping handlers as request.Env["ELAPSED_TIME"].(time.Duration),
// and as request.Env["START_TIME"].(time.Time)
type TimerMiddleware struct{}
// MiddlewareFunc makes TimerMiddleware implement the Middleware interface.
func (mw *TimerMiddleware) MiddlewareFunc(h rest.HandlerFunc) rest.HandlerFunc {
return func(w rest.ResponseWriter, r *rest.Request) {
start := time.Now()
r.Env["START_TIME"] = start
// call the handler
h(w, r)
end := time.Now()
elapsed := end.Sub(start)
r.Env["ELAPSED_TIME"] = elapsed
}
}
Unless I'm misunderstanding, should all r.Env values be set to non-pointers?