Memory leak in request

[mpaolini]

Hi all,

Since I upgraded to 0.14.4 (from 0.9.0) I am experiencing memory leaks in a Dropbox-API longpoller. It is a single process that spawns a few thousands of greenlets. Each greenlet performs a request(), that blocks for 30 seconds, then parses the response and dies. Then a new greenlet is spawned.

I am running on python 3.4.0, Ubuntu 14.04. I use the connection pool feature, passing the same connector singleton to each .request() call.

I played with tracemalloc, dumping a <N>.dump stat file every minute and found out that the response parser instances keep increasing in number (look at the third line of each stat)

root@9330490eafc9:/src# python3 -c "import pprint; import tracemalloc; pprint.pprint(tracemalloc.Snapshot.load('5.dump').statistics('lineno')[:3])"
[<Statistic traceback=<Traceback (<Frame filename='/usr/lib/python3.4/ssl.py' lineno=648>,)> size=6130540 count=82650>,
 <Statistic traceback=<Traceback (<Frame filename='<frozen importlib._bootstrap>' lineno=656>,)> size=3679906 count=31688>,
 <Statistic traceback=<Traceback (<Frame filename='/usr/local/lib/python3.4/dist-packages/aiohttp/parsers.py' lineno=198>,)> size=2176408 count=4437>]
root@9330490eafc9:/src# 
root@9330490eafc9:/src# 
root@9330490eafc9:/src# python3 -c "import pprint; import tracemalloc; pprint.pprint(tracemalloc.Snapshot.load('6.dump').statistics('lineno')[:3])"
[<Statistic traceback=<Traceback (<Frame filename='/usr/lib/python3.4/ssl.py' lineno=648>,)> size=6130476 count=82649>,
 <Statistic traceback=<Traceback (<Frame filename='<frozen importlib._bootstrap>' lineno=656>,)> size=3679906 count=31688>,
 <Statistic traceback=<Traceback (<Frame filename='/usr/local/lib/python3.4/dist-packages/aiohttp/parsers.py' lineno=198>,)> size=2199704 count=4463>]
root@9330490eafc9:/src# 
root@9330490eafc9:/src# 
root@9330490eafc9:/src# python3 -c "import pprint; import tracemalloc; pprint.pprint(tracemalloc.Snapshot.load('7.dump').statistics('lineno')[:3])"
[<Statistic traceback=<Traceback (<Frame filename='/usr/lib/python3.4/ssl.py' lineno=648>,)> size=6130476 count=82649>,
 <Statistic traceback=<Traceback (<Frame filename='<frozen importlib._bootstrap>' lineno=656>,)> size=3679906 count=31688>,
 <Statistic traceback=<Traceback (<Frame filename='/usr/local/lib/python3.4/dist-packages/aiohttp/parsers.py' lineno=198>,)> size=2231064 count=4498>]

tracemalloc reports this stack trace:

python3 -c "import pprint; import tracemalloc; pprint.pprint(tracemalloc.Snapshot.load('3.dump').filter_traces([tracemalloc.Filter(True, '*aiohttp/parsers.py')]).statistics('traceback')[0].traceback.format())"
['  File "/usr/local/lib/python3.4/dist-packages/aiohttp/parsers.py", line '
 '198',
 '    p = parser(output, self._buffer)',
 '  File "/usr/local/lib/python3.4/dist-packages/aiohttp/client.py", line 633',
 '    httpstream = self._reader.set_parser(self._response_parser)',
 '  File "/usr/local/lib/python3.4/dist-packages/aiohttp/client.py", line 108',
 '    yield from resp.start(conn, read_until_eof)',
 '  File "/src/xxxxxx/main.py", line 70',
 '    connector=LONGPOLL_CONNECTOR',

Looks like there is something keeping alive those parsers....

Using force_close=True on the connector makes no difference.

Then I tried calling gc.collect() after every single request, and is going much better but the leak has not the leak has disappeared completely-. This means (maybe is an unrelated issue) the library creates more reference cycles thant the CGC can handle.

It my well be my own bug, or maybe something to do with python 3.4.0 itself. I'm still digging into it.

[asvetlov]

Would you upgrade to Python 3.4.2?
I don't sure the upgrade will get rid of you problem but asyncio in 3.4.2 is significantly improved comparing to 3.4.0.

[ludovic-gasc]

@mpaolini CPython is easy to install via sources, you can install in /opt to avoid conflicts with your Python system.
You could also use Pythonz, an helper to do that for you.

[mpaolini]

@GMLudo @asvetlov doing it now

[mpaolini]

Upgraded to python 3.4.2, leak (or circular reference) still there. Same tracemalloc stats

[asvetlov]

Sorry, I have not many ideas without looking on your code.

Do you call yield from response.release() after request()?

[mpaolini]

@asvetlov no, I don't. I call read() (all responses are small) and that looks like it closes the response object.

Will try to setup a reproducing script this weekend

[asvetlov]

@mpaolini yes, in general read() should be enough.

[mpaolini]

BTW, unrelated, tracemalloc=20 doubles CPU usage for my python program

[mpaolini]

The leak disappears if I frequently gc.collect(). THis narrws down the causes to a reference cycle regarding the parser instance created in File "/usr/local/lib/python3.4/dist-packages/aiohttp/client.py", line 108'

[ludovic-gasc]

@mpaolini : maybe this issue should interest you, at least how to track your problem: #226
Maybe you could install Python 3.4.3 via hg.python.org. Victor Stinner has merged several fixes for asyncio.

[fafhrd91]

@mpaolini could you try latest master?

[mpaolini]

looks a bit better now. More data will be available in a few hours. Was it 8304f71 ?

[fafhrd91]

yes, that was it

[mpaolini]

The leak is still there. Will upgrade to 3.4.3 later

[mpaolini]

upgraded to python 3.4.3 and aiohttp master. Leak is still there. More tracemalloc cruft on its way

[mpaolini]

allocation stats recorded by tracemalloc in a 10 minutes time range

[<StatisticDiff traceback=<Traceback (<Frame filename='/pyenv/versions/3.4.3/lib/python3.4/_weakrefset.py' lineno=84>,)> size=439040 (+131072) count=2202 (+0)>,
 <StatisticDiff traceback=<Traceback (<Frame filename='/pyenv/versions/3.4.3/lib/python3.4/site-packages/aiohttp/protocol.py' lineno=210>,)> size=484508 (-51408) count=2862 (-102)>,
 <StatisticDiff traceback=<Traceback (<Frame filename='/pyenv/versions/3.4.3/lib/python3.4/site-packages/aiohttp/parsers.py' lineno=199>,)> size=1082600 (+33744) count=2189 (+38)>,
 <StatisticDiff traceback=<Traceback (<Frame filename='/pyenv/versions/3.4.3/lib/python3.4/site-packages/aiohttp/client.py' lineno=279>,)> size=118592 (+21504) count=1853 (+336)>,
 <StatisticDiff traceback=<Traceback (<Frame filename='/pyenv/versions/3.4.3/lib/python3.4/site-packages/aiohttp/client.py' lineno=558>,)> size=119080 (+18032) count=1110 (+23)>,
 <StatisticDiff traceback=<Traceback (<Frame filename='/pyenv/versions/3.4.3/lib/python3.4/re.py' lineno=245>,)> size=60664 (-16384) count=948 (-256)>,
 <StatisticDiff traceback=<Traceback (<Frame filename='/pyenv/versions/3.4.3/lib/python3.4/site-packages/aiohttp/protocol.py' lineno=308>,)> size=29232 (+16128) count=58 (+32)>,
 <StatisticDiff traceback=<Traceback (<Frame filename='/pyenv/versions/3.4.3/lib/python3.4/site-packages/aiohttp/protocol.py' lineno=600>,)> size=206016 (-8128) count=3219 (-127)>,
 <StatisticDiff traceback=<Traceback (<Frame filename='/pyenv/versions/3.4.3/lib/python3.4/site-packages/aiohttp/connector.py' lineno=354>,)> size=131952 (-5728) count=1005 (-19)>,
 <StatisticDiff traceback=<Traceback (<Frame filename='/pyenv/versions/3.4.3/lib/python3.4/site-packages/aiohttp/protocol.py' lineno=124>,)> size=125952 (-3904) count=1968 (-61)>]

[mpaolini]

looks like the params list we create at line 279 is never reclaimed...

   271      def update_path(self, params):
   272          Build path.
   273          # extract path
   274          scheme, netloc, path, query, fragment = urllib.parse.urlsplit(self.url)
   275          if not path:
   276              path = '/'
   277  
   278          if isinstance(params, dict):
   279              params = list(params.items())
   280          elif isinstance(params, (MultiDictProxy, MultiDict)):
   281              params = list(params.items())
   282  
   283          if params:
   284              params = urllib.parse.urlencode(params)
   285              if query:

[mpaolini]

oh! urlparse.parse.urlsplit has a parse cache

[fafhrd91]

interesting, but cache dict has only 20 entries.

[mpaolini]

true... have a look at the _safe_quoters cache in urlparse.parse. It is only ever cleared in urlsplit but it is populated also in quote_from_bytes that is called by urlencode .... do you see evil there?

[fafhrd91]

i don't think it is _safe_quoters, it is very small.
my feeling it is connections, try to print connector._conns or len(connector._conns)

[fafhrd91]

actually it should be something like:

for key, val in connector._conns.items():
   print(key, len(val))

[mpaolini]

still no luck:

('api.yyyyyyy.com', 443, True) 1

[fafhrd91]

hmm. could you also check how much opened connection you have ("netstat")

[mpaolini]

# netstat -nt | wc -l
2114

that's expected, this component asynchronously polls an external service for thousands of users

[mpaolini]

by the way, number of network connections does not grow

[fafhrd91]

@mpaolini Could you try aiohttp from master?

[mpaolini]

Just upgraded to aiohttp master (on python 3.4.3) leak is still there. It leaks 132 bytes every ~ 5 seconds

[mpaolini]

Leak is still happening after upgrade to aiohttp 0.17.3 on python 3.4.3 . It seems it only happens on long-polling requests. I am writing a script to reproduce

[fafhrd91]

@mpaolini could you check master, we fixed memory leak in 457a25e

[asvetlov]

I believe it can be closed.
Next found leak worth new issue

[mpaolini]

I am not sure this leak is solved, I haven't upgraded yet since 0.17.3

[asvetlov]

@mpaolini would you try?

[mpaolini]

@asvetlov I am trying on staging now, will let you know how it wokrs

[asvetlov]

Thanks a lot!

[mpaolini]

@asvetlov still no luck... it leaks around 48 bytes per minute in my staging environment with aiohttp==0.20.0

[asvetlov]

@mpaolini 48 bytes per minute looks like too slow value assuming you have moderate load for your environment.
It's close to sys.getsizeof(1).
I really cannot imagine what aiohttp object we are leaking.
Any ideas?

[mpaolini]

@asvetlov see my comment #271 (comment)

[mpaolini]

I am fetching tracecmalloc stats from the aiohttp 0.20.0 setup in staging. Is there an IRC or slack where we can discuss in real-time?

[mpaolini]

updated tracemalloc diffs in a 7 minutes span

 <StatisticDiff traceback=<Traceback (<Frame filename='/usr/local/lib/python3.4/site-packages/aiohttp/streams.py' lineno=247>,)> size=5440 (+3808) count=10 (+7)>,
 <StatisticDiff traceback=<Traceback (<Frame filename='/usr/local/lib/python3.4/site-packages/aiohttp/client.py' lineno=365>,)> size=30616 (+1696) count=86 (+2)>,
 <StatisticDiff traceback=<Traceback (<Frame filename='/usr/local/lib/python3.4/site-packages/aiohttp/client.py' lineno=174>,)> size=3984 (+1328) count=6 (+2)>,
 <StatisticDiff traceback=<Traceback (<Frame filename='/usr/local/lib/python3.4/site-packages/aiohttp/client_reqrep.py' lineno=599>,)> size=16856 (+1120) count=57 (+3)>,
 <StatisticDiff traceback=<Traceback (<Frame filename='/usr/local/lib/python3.4/site-packages/aiohttp/protocol.py' lineno=221>,)> size=15596 (+992) count=80 (+2)>,
 <StatisticDiff traceback=<Traceback (<Frame filename='/usr/local/lib/python3.4/site-packages/aiohttp/parsers.py' lineno=336>,)> size=14408 (+952) count=57 (+3)>,
 <StatisticDiff traceback=<Traceback (<Frame filename='/usr/local/lib/python3.4/site-packages/aiohttp/parsers.py' lineno=184>,)> size=29120 (+888) count=58 (+1)>,
 <StatisticDiff traceback=<Traceback (<Frame filename='/usr/local/lib/python3.4/site-packages/aiohttp/client.py' lineno=178>,)> size=17880 (+672) count=55 (+2)>,
 <StatisticDiff traceback=<Traceback (<Frame filename='/usr/local/lib/python3.4/site-packages/aiohttp/streams.py' lineno=578>,)> size=17384 (+592) count=58 (+2)>,
 <StatisticDiff traceback=<Traceback (<Frame filename='/usr/local/lib/python3.4/site-packages/aiohttp/streams.py' lineno=92>,)> size=12064 (+416) count=29 (+1)>,
 <StatisticDiff traceback=<Traceback (<Frame filename='/usr/local/lib/python3.4/site-packages/aiohttp/client_reqrep.py' lineno=533>,)> size=8640 (+384) count=48 (+3)>,

[asvetlov]

@mpaolini does google hangout chat works for you?
My account is andrew.svetlov@gmail.com

[asvetlov]

Finally fixed by #723
Released as 0.20.2

[mpaolini]

Yep fixed

[lock]

This thread has been automatically locked since there has not been
any recent activity after it was closed. Please open a new issue for
related bugs.

If you feel like there's important points made in this discussion,
please include those exceprts into that new issue.