Memory leak in my site, *possibly* traced back to Bottle

Jwink3101 commented 3 years ago

My actual case

I have been rebuilding my website and I deployed it a few days ago. I noticed however that the memory kept growing and growing while never shrinking.

I am not storing any state between calls (to my knowledge). So I added a path that calls tracemalloc and takes memory snapshots. I then bombarded my site with requests and watched the memory grow then ran the trace and compared.

The following is my results

/...<user paths>.../bottle.py:3965: size=6221 KiB (+6221 KiB), count=53649 (+53649), average=119 B
/...<user paths>.../bottle.py:4134: size=2454 KiB (+2454 KiB), count=1483 (+1483), average=1695 B
/...<user paths>.../bottle.py:246: size=1628 KiB (+1627 KiB), count=2895 (+2893), average=576 B
/...<user paths>.../bottle.py:4007: size=1477 KiB (+1477 KiB), count=2889 (+2889), average=523 B
/...<user paths>.../bottle.py:4217: size=1467 KiB (+1467 KiB), count=1408 (+1408), average=1067 B

That line, which also somehow grew by ~50,000 for 500 calls, is

@cached_property
def co(self):
    return compile(self.code, self.filename or '<string>', 'exec')

I've tried with debug=False and debug=True BTW.

A possible test case

I am struggling with a meaningful example to show it but the following also shows some promise as having the problem. I also tested with the latest

"""
Simple test
"""
import bottle # Local downloaded on 2020-12-31, f5a9f765
import sys
import gc
print(bottle.__version__)
print(sys.version)

template = """\
<p>
This is my Bottle Template
</p>
% import random
<p>
Testing with {{random.random()}}
"""

# Make it a big template
with open('template.tpl','wt') as f:
    for _ in range(5000):
        f.write(template)
print('template written')

import tracemalloc
tracemalloc.start()

snapshot0 = tracemalloc.take_snapshot()

for ii in range(3000):
    res = bottle.template('template.tpl')
    if ii%100 == 0:
        print(ii,end=' ',flush=True)
print('')

# Make sure it's not just that Python hasn't done it's thing
gc.collect()

snapshot1 = tracemalloc.take_snapshot() 

top_stats = snapshot1.compare_to(snapshot0, 'lineno')    
print("[ Top 20 ]")
for stat in top_stats[:20]:
    print(f'{stat}' )

I am seeing one of the same lines show up here but I am honestly not sure if this test is testing the same issues:

/...<user paths>.../bottletest/bottle.py:4134: size=669 KiB (+669 KiB), count=1 (+1), average=669 KiB
/...<user paths>.../bottletest/bottle.py:4023: size=353 KiB (+353 KiB), count=1 (+1), average=353 KiB
/...<user paths>.../bottletest/bottle.py:3965: size=196 KiB (+196 KiB), count=9 (+9), average=21.8 KiB

The 3965 line is showing again

Thoughts

I am 100% not saying this can't be user error. Especially since the 50,000 calls surprises me. But even if I have some odd call, the template engine shouldn't be growing this much, right? I have all of 20 template files that are called at various times so even if it is the caching, it should be minimal.

Thanks!

defnull commented 3 years ago

Hmm,

@cached_property caches the return value of a getter method to the instance. It is used to cache the compiled template, which is exactly what you want. Template parsing and compiling is expensive.
bottle.template() caches template instances based on the file name. Calling it multiple times with template.tpl as a parameter creates exactly one instance of the template. These are never freed, but since there usually are only a couple of templates per application, that should not be an issue.
You create a template with 30.000 lines and roughly 500kb of text content. That pretty nicely fits the size=669 KiB, count=1 reporting in your test. The count is one, so you are not hitting the leak with your test.

Are you creating templates dynamically? If so, then the leak is easily explained. Passing an actual template string to bottle.template() instead of a file-name will cause it to be cached based on the template string itself. If you pass dynamically created strings to bottle.template(), each one will be compiled, cached and then never freed. If that is the case, why are you doing that? Templates are supposed to be dynamic already, dynamically creating templates is very unusual.

defnull commented 3 years ago

Oh, if you are using a threading server and hitting it with an insane amount of requests in a short time, then the template is compiled more than once. That's a race condition, but not a leak: Only the last template for a given cache key will stay in the cache dict, all the others will be garbage-collected eventually. Note that tracemalloc tracks allocations, not de-allocations. You cannot find leaks with that. A leak would mean that objects are never freed by the garbage collector.

Jwink3101 commented 3 years ago

Are you creating templates dynamically?

I am not. What I am doing is (non-working) code like:

SNIPPETS = Path(__file__).parent.resolve() / 'snippets'
STATIC = Path(__file__).parent.resolve() / 'static'

def fill_snippet(name,**kwargs):
    """Get and fill a snippet as needed. See compile for full page"""
    # Redefine lookup here since config.TEMPLATES will be updated when config is parsed
    lookup = [str(Path(__file__).parent / 'views'),config.TEMPLATES]
    return  bottle.template(name,
                            template_lookup=lookup, # template fun
                            # Rest are defined
                            session=auth.getsession(),
                            mdformat=mdformat,
                            **kwargs)
def compile(content,**kwargs):
    """Compile the main body"""
    path = request.urlparts.path

    # Redefine lookup here since config.TEMPLATES will be updated when config is parsed
    lookup = [str(Path(__file__).parent / 'views'),config.TEMPLATES]

    # Set a cookie of where we last were. Not used at the moment
    # response.set_cookie('last',path)

    return bottle.template('main.html',
                           template_lookup=lookup,
                           # --------------
                           session=auth.getsession(),
                           content=content,
                           config=config,
                           breadcrumb=kwargs.pop('breadcrumb',breadcrumb(path)),
                           pagepath=path,
                           mdformat=mdformat,
                           **kwargs)

and then calling it like the following:

html = get_page_from_sqlite_db()
html += fill_snippet('footer.html',stuff=stuff) # Specific to this kind of page do not in the main template
return compile(html)

So the template itself is all file-based but the content is generated with two calls. I could probably improve that but I doubt that's the issue.

Oh, if you are using a threading server and hitting it with an insane amount of requests in a short time, then the template is compiled more than once

I am using cheroot which is threaded and I test with a lot of calls but I can refresh the page once and see the memory of the app grow. I added the following route to see it:

@app.route('/mem')
def mem():
    cmd = ['ps', '-p', f'{os.getpid()}', '-o', 'rss,etime,pid,command']
    return subprocess.check_output(cmd).decode().split('\n')[1].split()[0]

So ever call seems to grow it. I've also tried adding gc.collect() paths to see

defnull commented 3 years ago

Aha! You are dynamically creating the lookup list. That has the same effect. The lookup list is part of the cache key (because you cannot cache only based on file name if a different lookup directory is used). See https://github.com/bottlepy/bottle/blob/master/bottle.py#L4233

Mystery solved?

Jwink3101 commented 3 years ago

Yes!!! I think so. My initial run of 500 requests grows those lines (expected) but then another and they stay the same.

For anyone who makes the same mistake, I change the code to:

LOOKUP = []
def set_lookup():
    # Add to the global lookup list if it hasn't been done yet but only do this
    # once. Cannot do at instantiation since we don't know config.TEMPLATES.
    # see https://github.com/bottlepy/bottle/issues/1274 for why 
    if not LOOKUP:
        LOOKUP.extend([str(Path(__file__).parent / 'views'),config.TEMPLATES])

def fill_snippet(name,**kwargs):
    """Get and fill a snippet as needed. See compile for full page"""
    set_lookup()
    return  bottle.template(name,
                            template_lookup=LOOKUP, # template fun
                            # Rest are defined
                            session=auth.getsession(),
                            mdformat=mdformat,
                            **kwargs)
# ...

Thanks so much for the help! I was really not looking forward to migrating everything to mako or jinja2 only to have the same issue!

Quick Aside

I sincerely wasn't sure if this was a Bottle or user error so I thought it was okay to open an issue. Is there a better way to ask user support? Maybe a bottle subreddit would be an idea? Thoughts?

Anyway, thanks so much!!!

defnull commented 3 years ago

Opening an issue for strange behaviour in bottle is fine. This is a rare but also non-obvious and hard to debug issue. Bottle should perhaps emit a warning if the cache dict grows larger than a certain size.

There is a mailing-list, an IRC channel and also a (dead) subreddit. Not sure if these can be revived.

bottlepy / bottle