Memory leaks in web2py : how do you track them ?

[Louis Amon]

I have a web2py server running on heroku.

So far my server had little traffic, and Heroku being a cloud PaaS service means they put processes to sleep if they're not used for a while.

Because of that, I never really noticed that the memory signature of my application was growing at every request until my server got put to sleep due to inactivity (at night most often), and thus the memory was reset upon restart.

This is no longer the case, and now my server often becomes unavailable due to memory quotas, which is a big issue on production.

I've been using several tools to track the memory usage of web2py, one of which is the logs of Heroku itself, eg:

2015-02-01T09:01:46.965380+00:00 heroku[web.1]: source=web.1 dyno=heroku.28228261.c4fede81-d205-4dad-b07e-2ad6dcc49a0f sample#memory_total=186.27MB sample#memory_rss=180.75MB sample#memory_cache=5.52MB sample#memory_swap=0.00MB sample#memory_pgpgin=71767pages sample#memory_pgpgout=24081pages

As far as I can tell, the "memory_cache" signature is rather small and is stable around 5MB (I don't use cache a lot on my website, precisely for fear of memory leaks).

Based on the documentation, "memory_rss" on Heroku refers to:

• Resident Memory (memory_rss): The portion of the dyno’s memory (megabytes) held in RAM.

 This variable keeps growing at every request, seemingly regardless of which page is accessed.

You will find attached the memory chart of my app, taken from Heroku's Metrics back-office : every vertical line is a hard reset I had to do manually to prevent the app from exceeding quotas. The red zone is a server downtime because of swap usage making requests to be served very very slowly.

I've tried using the "memory_profiler" library to decorate some functions in my code and try to track memory usage increase, but it is a very tedious task and so far I haven't managed to find the root of my problem.

I suspect my issue to be in models since those are loaded on every request, but I can't use memory_profiler on them since models aren't natively encapsulated in any function.

Is there a function somewhere in Gluon that loads every model, and which I could decorate to scope which model might have memory leaks ?

[Louis Amon]

Update:

I've tried running 2 dynos to see if splitting traffic in two would reduce the slope of my memory leak, and also to see if the garbage collector would somehow work better.

It seems not :

2015-02-01T09:23:50.049734+00:00 heroku[web.1]: source=web.1 dyno=heroku.28228261.c4fede81-d205-4dad-b07e-2ad6dcc49a0f sample#memory_total=242.09MB sample#memory_rss=236.50MB sample#memory_cache=5.59MB sample#memory_swap=0.00MB sample#memory_pgpgin=97398pages sample#memory_pgpgout=35422pages

2015-02-01T09:23:38.787009+00:00 heroku[web.2]: source=web.2 dyno=heroku.28228261.9b8464db-9ab7-42e3-a61a-604a765f38be sample#memory_total=239.23MB sample#memory_rss=233.64MB sample#memory_cache=5.59MB sample#memory_swap=0.00MB sample#memory_pgpgin=95938pages sample#memory_pgpgout=34694pages

The memory seems to grow at the same rate, regardless of the traffic being split between dynos.

[Louis Amon]

Udate 2:

I've tried switching from the Rocket server to Gunicorn : the memory's still increasing and quotas are reached in a matter of hours.

BTW I'm running web2py version 2.9.11. 

Has the new patch fixed anything that might help with memory leaks ? Should I try updating my server ?

[Anthony]

gluon.main.wsgibase calls gluon.main.serve_controller, which calls gluon.compileapp.run_models_in, which executes the models.

Anthony

[Leonel Câmara]

Do you have pool_size defined?

[Leonel Câmara]

If you have pool_size defined can you tell me if putting pool_size=0 in your DAL solves this problem?

Anyway I got really interested in this, for some unknown to me reason, and decided to create a VERY CRUDE decorator to memory check your controller functions for leaks, I guess with time we could refine this if there's a desire to have a memory leak checker for controller functions in web2py. I hope it helps, if it doesn't at least it was fun to code.

 

def memcheck(f):
    """
    A crude decorator to memory check your web2py controller's functions.


    False positives are possible if your controller function returns less than
    common stuff.


    Put it in your models and then decorate your controller functions.


    example:


    @memcheck
    def index():
        response.flash = T("Welcome to web2py!")
        return dict(message=T('Hello World'))


    BEERWARE - You should try to buy Leonel Câmara beers!
    """
    from functools import wraps
    from collections import Counter, Mapping, Iterable
    from gluon.languages import lazyT
    from gc import get_objects


    def get_value_objects(v):
        """
        Generate an object for each value in a value including itself.
        """
        if isinstance(v, basestring):
            yield v
        elif isinstance(v, lazyT):
            yield v
            yield v.s # Check lazyT symbols dict
            for i in v.s:  
                for new_v in get_value_objects(i):
                    yield new_v
        elif isinstance(v, Mapping):
            yield v
            for i in v.values():
                for new_v in get_value_objects(i):
                    yield new_v
        elif isinstance(v, Iterable):
            yield v
            for i in v:
                for new_v in get_value_objects(i):
                    yield new_v
        else:
            yield v


    @wraps(f)
    def wrapper(*args, **kwargs):
        before = Counter(type(obj) for obj in get_objects())
        result = f(*args, **kwargs)
        after = Counter(type(obj) for obj in get_objects())
        result_objs = Counter(type(obj) for obj in get_value_objects(result))
        count = after - before - result_objs - Counter([Counter])
        # This and other stuff put in the response or session is not a memory
        # leak.
        # So false positives may appear for what's not accounted here.
        if response.flash:
            count -= Counter(type(obj) for obj in get_value_objects(response.flash))
        if response.js:
            count -= Counter(type(obj) for obj in get_value_objects(response.js))
       
        # Finally we are ready to report what we have found.
        for k in count:
            print 'LEAKED: %d of type %s' % (count[k], k)
        return result


    return wrapper

[Paolo Valleri]

Hi,

the garbace collector is called once every 100 requests. 

See https://github.com/web2py/web2py/blob/5a0ee722605164f1eae4064d0d1dd0d72b5eb14b/gluon/main.py#L197

In addition try to pack a very basic app which can reproduce the issue, we'll have more info about what is going on wrong in your app or web2py

Paolo

[Michele Comitini]

@Leonel you should make a PR of this.  We have a program profiler, a memory profiler would be great!

@niplhod do you know if is there a way to integrate memory profiling in travis-ci??

[Massimo Di Pierro]

What application is this? Are you using cache.ram or a cache decorator? That would cause this.

[Richard Vézina]

appointment app where having memory leaks

https://github.com/mdipierro/web2py-appliances/tree/master/AppointmentManager

https://groups.google.com/d/msg/web2py/u-eU-2vhims/1u3fOnqPoUMJ

https://groups.google.com/d/msg/web2py/QbR7pY3xHuM/rOyuHhVmbjYJ

Richard

--
Resources:
- http://web2py.com
- http://web2py.com/book (Documentation)
- http://github.com/web2py/web2py (Source code)
- https://code.google.com/p/web2py/issues/list (Report Issues)
---
You received this message because you are subscribed to the Google Groups "web2py-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to web2py+un...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Niphlod]

@niplhod do you know if is there a way to integrate memory profiling in travis-ci??

 

I don't see it in any of the docs. if you have something in mind that will print out something as a value, we could print an alarm on a crafted build if some value passes a threshold, but that's pretty much all I can think of.

[Louis Amon]

I've installed this memory profiler and tried the "profile" decorator it provides, and the output is pretty awesome ! 

I've ran the exact same request twice, and these are the outputs of the profile on gluon.compileapp.run_models_in :

First run

Line #    Mem usage    Increment   Line Contents

================================================

   531  28.8945 MiB   0.0000 MiB   @profile(precision=4)

   532                             def run_models_in(environment):

   533                                 """

   534                                 Runs all models (in the app specified by the current folder)

   535                                 It tries pre-compiled models first before compiling them.

   536                                 """

   537                            

   538  28.8945 MiB   0.0000 MiB       folder = environment['request'].folder

   539  28.8945 MiB   0.0000 MiB       c = environment['request'].controller

   540                                 #f = environment['request'].function

   541  28.8945 MiB   0.0000 MiB       response = environment['response']

   542                            

   543  28.8945 MiB   0.0000 MiB       path = pjoin(folder, 'models')

   544  28.8945 MiB   0.0000 MiB       cpath = pjoin(folder, 'compiled')

   545  28.8945 MiB   0.0000 MiB       compiled = os.path.exists(cpath)

   546  28.8945 MiB   0.0000 MiB       if compiled:

   547                                     models = sorted(listdir(cpath, '^models[_.][\w.]+\.pyc$', 0), model_cmp)

   548                                 else:

   549  28.8984 MiB   0.0039 MiB           models = sorted(listdir(path, '^\w+\.py$', 0, sort=False), model_cmp_sep)

   550  28.8984 MiB   0.0000 MiB       models_to_run = None

   551  41.7812 MiB  12.8828 MiB       for model in models:

   552  41.7656 MiB  -0.0156 MiB           if response.models_to_run != models_to_run:

   553  37.3164 MiB  -4.4492 MiB               regex = models_to_run = response.models_to_run[:]

   554  37.3164 MiB   0.0000 MiB               if isinstance(regex, list):

   555  37.3320 MiB   0.0156 MiB                   regex = re_compile('|'.join(regex))

   556  41.7656 MiB   4.4336 MiB           if models_to_run:

   557  41.7656 MiB   0.0000 MiB               if compiled:

   558                                             n = len(cpath)+8

   559                                             fname = model[n:-4].replace('.','/')+'.py'

   560                                         else:

   561  41.7656 MiB   0.0000 MiB                   n = len(path)+1

   562  41.7656 MiB   0.0000 MiB                   fname = model[n:].replace(os.path.sep,'/')

   563  41.7656 MiB   0.0000 MiB               if not regex.search(fname) and c != 'appadmin':

   564                                             continue

   565  41.7656 MiB   0.0000 MiB               elif compiled:

   566                                             code = read_pyc(model)

   567  41.7656 MiB   0.0000 MiB               elif is_gae:

   568                                             code = getcfs(model, model,

   569                                                           lambda: compile2(read_file(model), model))

   570                                         else:

   571  41.7656 MiB   0.0000 MiB                   code = getcfs(model, model, None)

   572  41.7812 MiB   0.0156 MiB               restricted(code, environment, layer=model)

Second run

Line #    Mem usage    Increment   Line Contents

================================================

   531  44.2695 MiB   0.0000 MiB   @profile(precision=4)

   532                             def run_models_in(environment):

   533                                 """

   534                                 Runs all models (in the app specified by the current folder)

   535                                 It tries pre-compiled models first before compiling them.

   536                                 """

   537                            

   538  44.2695 MiB   0.0000 MiB       folder = environment['request'].folder

   539  44.2695 MiB   0.0000 MiB       c = environment['request'].controller

   540                                 #f = environment['request'].function

   541  44.2695 MiB   0.0000 MiB       response = environment['response']

   542                            

   543  44.2695 MiB   0.0000 MiB       path = pjoin(folder, 'models')

   544  44.2695 MiB   0.0000 MiB       cpath = pjoin(folder, 'compiled')

   545  44.2695 MiB   0.0000 MiB       compiled = os.path.exists(cpath)

   546  44.2695 MiB   0.0000 MiB       if compiled:

   547                                     models = sorted(listdir(cpath, '^models[_.][\w.]+\.pyc$', 0), model_cmp)

   548                                 else:

   549  44.2734 MiB   0.0039 MiB           models = sorted(listdir(path, '^\w+\.py$', 0, sort=False), model_cmp_sep)

   550  44.2734 MiB   0.0000 MiB       models_to_run = None

   551  45.0664 MiB   0.7930 MiB       for model in models:

   552  45.0625 MiB  -0.0039 MiB           if response.models_to_run != models_to_run:

   553  44.2891 MiB  -0.7734 MiB               regex = models_to_run = response.models_to_run[:]

   554  44.2891 MiB   0.0000 MiB               if isinstance(regex, list):

   555  44.2891 MiB   0.0000 MiB                   regex = re_compile('|'.join(regex))

   556  45.0625 MiB   0.7734 MiB           if models_to_run:

   557  45.0625 MiB   0.0000 MiB               if compiled:

   558                                             n = len(cpath)+8

   559                                             fname = model[n:-4].replace('.','/')+'.py'

   560                                         else:

   561  45.0625 MiB   0.0000 MiB                   n = len(path)+1

   562  45.0625 MiB   0.0000 MiB                   fname = model[n:].replace(os.path.sep,'/')

   563  45.0625 MiB   0.0000 MiB               if not regex.search(fname) and c != 'appadmin':

   564                                             continue

   565  45.0625 MiB   0.0000 MiB               elif compiled:

   566                                             code = read_pyc(model)

   567  45.0625 MiB   0.0000 MiB               elif is_gae:

   568                                             code = getcfs(model, model,

   569                                                           lambda: compile2(read_file(model), model))

   570                                         else:

   571  45.0625 MiB   0.0000 MiB                   code = getcfs(model, model, None)

   572  45.0664 MiB   0.0039 MiB               restricted(code, environment, layer=model)

My observations so far are :

1. The first run uses a lot more memory than each subsequent run
2. Every time my models are ran, the memory usage increases about 1MB
3. Between each request, another few MBs (usually about 1MB) are used apart from models

(I've done dozens of other tests and these observations are persistent)

I'll track down each model to look for the culprit (it's a big app so it'll take a while), but in the meantime do you know where I should look for the other memory increases ? I'm guessing "run_controller_in" and "run_view_in" in gluon.compileapp, but I'd like to confirm before spending a few hours on this :)

Regarding the "first run" vs "subsequent runs" memory differential, it got me wondering : is this due to imports, or are models actually kepts in memory between request (regardless of the lazy_table attribute in DAL) ?

[Michele Comitini]

I have been using this sometimes ago, if there is a cyclic reference or a stale reference of some sort, it help to spot it.

https://groups.google.com/d/msg/web2py-developers/Rd8hC5aFRZo/UTxZHjAwWcUJ
http://mg.pov.lt/objgraph/

...

[Louis Amon]

I have rather alarming news :

Just to make sure, I've pulled the latest Git checkout of web2py and created a new scaffolding app in which I put a memory usage logging statement.

Just by spamming refresh on my browser, the memory usage doubled over a few hundred requests.

You'll find attached the log file that basically prints "URL memory_usage" for each request + the application I used to make this test.

Can someone replicate this ?

Are memory leaks tested upon w2p releases ?

[c...@cemeren.com]

Hi,

performed the test on 2.9.11-stable+timestamp.2014.09.15.23.35.11

(Running on Apache/2.4.7 (Ubuntu), Python 2.7.6):

I utilised apache benchmark (ab), making 1130 request within a minute twice with and without log.close(). 

I did not notice any memory leak, (neither with the log nor with the os memory check). 

When I performed the test manually within the browser without adding "log.close()" I noticed the increase in memory usage but that was before the garbage collector interfered and normal I guess (as the size of the text file increases the memory consumed by it increases). 

I did this test just to be relevant with this post but I must admit I would notice a memory leak as I run several sites with web2py and my servers would complain about it long before, surely, I am talking within my configuration. I use apache2 and mod_wsgi both in development (OS X) and production (Ubuntu).

4 Şubat 2015 Çarşamba 21:27:11 UTC+2 tarihinde Louis Amon yazdı:

[Niphlod]

python 2.7.8 64bit, Linux.
My rig is "heavily armored" but it shouldn't matter for this case: just for completeness, it's a 6 core xeon x5660 , 24GB RAM, running *buntu 14.10.

test scenario1:
console1) python web2py.py -a mypwd
console2) ab -n 1000 http://127.0.0.1:8000/welcome/default/index

raises the memory usage from 24MB (before 1st request coming in) to ~60MB. stays that way (from 57 to 62) even after 100 rounds of 1000 requests, i.e. 100k requests. Tested versions ranging from 2.9.6 to 2.9.12 and trunk... behaviour is pretty much the same.

test scenario2:
console1) python web2py.py -a mypwd
console2) ab -n 1000 http://127.0.0.1:8000/memory_leak

raises the memory usage from 24MB (before 1st request coming in) to ~72MB. stays that way (from 69 to 72) even after 100 rounds of 1000 requests, i.e. 100k requests. Tested versions ranging from 2.9.6 to 2.9.12 and trunk... also here, behaviour is pretty much the same

my memory_usage.log reports something like this
http://127.0.0.1:8000/memory_leak 75.5234375
......
http://127.0.0.1:8000/memory_leak 77.25
http://127.0.0.1:8000/memory_leak 76.53125
.......
http://127.0.0.1:8000/memory_leak 77.44921875

in over 200k lines (restarted the 100k round two times, just to be sure) it never goes past 78.16015625