search

gobuffalo / plush

The powerful template system that Go needs
MIT License
901 stars 56 forks source link

Memory leak issue potentially caused by rendering authenticity_token in meta tag #118

Closed segakazzz closed 3 years ago

segakazzz commented 3 years ago

Description

Memory usage in heap is increasing proportionately to the volume of access caused by the following memory allocations. pprof report shows as follows. 

With 10000 access 
$ go tool pprof -top  http://127.0.0.1:6060/debug/pprof/heap
      flat  flat%   sum%        cum   cum%
30285.50kB 92.21% 92.21% 30285.50kB 92.21%  bytes.(*Buffer).String (inline)
With 20000 access 
$ go tool pprof -top  http://127.0.0.1:6060/debug/pprof/heap
      flat  flat%   sum%        cum   cum%
   57.15MB 85.65% 85.65%    57.15MB 85.65%  bytes.(*Buffer).String (inline)

After many trials, I found that the issue doesn't happen by removing following meta tag in application.plush.html

<meta name="csrf-token" content="<%= authenticity_token %>" />

Steps to Reproduce the Problem

  1. Create new buffalo project 
    $ buffalo new buffalonew
  2. Prepare postgres database

  3. Add following code for pprof in main.go

    
import (
"fmt"
"net/http"
_ "net/http/pprof"

"github.com/gobuffalo/envy"
)

func init() { go func() { if envy.Get("GO_ENV", "development") == "development" { fmt.Println("start pprof on :6060") log.Println(http.ListenAndServe("127.0.0.1:6060", nil)) } }() }

   4. Launch the project

$ cd buffalonew $ buffalo dev

   5. Confirm it's running
![image](https://user-images.githubusercontent.com/23018308/101912464-22b93c00-3c05-11eb-88e0-5dd7cf4f8b39.png)

   6. Run pprof report

$ go tool pprof -top http://127.0.0.1:6060/debug/pprof/heap 


   7. Generate dummy access with ab command

$ ab -n 10000 -c 100 http://127.0.0.1:3000/


   8. Run pprof report again and compare with step gobuffalo/buffalo#6

$ go tool pprof -top http://127.0.0.1:6060/debug/pprof/heap 


   9. After a few hours later, try pprof again. The memory allocation is still there...

### Expected Behavior

The memory allocation with bytes.(*Buffer).String will be cleaned up in heap after decent durations

### Actual Behavior

The memory allocation with bytes.(*Buffer).String is not cleaned up until killing the buffalo process

### Info
- This leak seems to be caused by line 62 in plush/compiler It can be traced by pprof graphical report. 
https://github.com/gobuffalo/plush/blob/master/compiler.go 

### Environment
- macOS Big Sur Version 11.0.1
- go version go1.15.5 darwin/amd64
- Buffalo version is: v0.16.17 

### Question
Our real application seems working properly with removing authenticity_token in header. Forms are working with the token generated in input tag. Do you think if there are any issues with removing the token in header meta?

Please feel free to contact me for additional info. Thanks!
paganotoni commented 3 years ago

Moving this one to plush as it seems to be related to it. Thanks for reporting it @segakazzz

saurori commented 3 years ago

I'm also experiencing this memory leak. I removed csrf altogether and still see the memory leak in production, on buffalo v0.16.20.

saurori commented 3 years ago

I spent some time digging and found the source of the memory leak. It's not exactly a leak, but by design. Plush caches every template in an unbounded cache var cache = map[string]*Template{} which retains the template string data. Additionally, it uses the entire raw template input as the string in the map vs some hash, further increasing memory usage. Using a local modified version of plush with the caching removed, the problem goes away.

The reason why the problem goes away when removing the authenticity token meta tag in the example above is because that tag generates a unique token and causes the template to be different and thus a cache miss, then a cache creation.

This design does not work for applications with dynamic templates. For my sites, there are a lot of pages loading content from the DB and are highly variable, causing the cache to grow linearly until the host is OOM.

I'm not sure what the best solution here is, but caching at this level should not happen by default, or the cache should be bounded (e.g. fixed size LRU) - although as demonstrated by the CSRF example, that invalidates the cache entirely. Some sort of "partial" caching could work for expensive templates but it should be opt-in.

paganotoni commented 3 years ago

@saurori @segakazzz I did put this PR together, https://github.com/gobuffalo/plush/pull/119. thoughts? I think we could test it with :

go get github.com/gobuffalo/plush/v4@task-optin-cache
saurori commented 3 years ago

@paganotoni tested locally with that branch. Memory usage looks good. Hitting the same page with ab -n 1000 -c 2 before and after the fix, there is a small performance hit which is to be expected (165.51 [#/sec] (mean) -> 146.70 [#/sec] (mean)).

segakazzz commented 3 years ago

@paganotoni @saurori Thanks for the update. I compared before and after and memory allocation of bytes.(*Buffer).String was gone. Awesome!!!

I tried pprof after ab -n 10000 -c 100 http://127.0.0.1:3000/ and here is the result of both.


- After with github.com/gobuffalo/plush/v4@task-optin-cache

$ go tool pprof -top http://127.0.0.1:6060/debug/pprof/heap
Fetching profile over HTTP from http://127.0.0.1:6060/debug/pprof/heap Type: inuse_space Time: Jan 19, 2021 at 8:11pm (JST) Showing nodes accounting for 4655.46kB, 100% of 4655.46kB total flat flat% sum% cum cum% 1066.64kB 22.91% 22.91% 1066.64kB 22.91% sync.(Map).Store 1024.38kB 22.00% 44.92% 1024.38kB 22.00% runtime.malg 516.01kB 11.08% 56.00% 516.01kB 11.08% unicode.init 512.25kB 11.00% 67.00% 512.25kB 11.00% bytes.makeSlice 512.14kB 11.00% 78.00% 512.14kB 11.00% github.com/gobuffalo/plush/v4.(Context).Set 512.04kB 11.00% 89.00% 512.04kB 11.00% strings.(*Builder).grow (inline) 512.01kB 11.00% 100% 1578.64kB 33.91% mime.setExtensionType

paganotoni commented 3 years ago

Solved in v4.1.0. Thanks @segakazzz @saurori for the help with this one.

Mido-sys commented 3 years ago

@paganotoni, How about if we detect if there's a CSRF token & disable the cache accordingly? We're already parsing the file so it could be flagged during lexing.