Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Timer Middleware memory leak #230

Open
snagles opened this issue Apr 17, 2018 · 0 comments · May be fixed by #240
Open

Timer Middleware memory leak #230

snagles opened this issue Apr 17, 2018 · 0 comments · May be fixed by #240

Comments

@snagles
Copy link

snagles commented Apr 17, 2018

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?

@fieldAbyss fieldAbyss linked a pull request Jan 23, 2021 that will close this issue
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

1 participant