Possible Memory Leak

I have a very simple program that periodically retrieves an image from an IP camera. I've noticed that the working set of this program grows monotonically. I've written a small program that reproduces the issue.

``` python
import requests
from memory_profiler import profile


@profile
def lol():
    print "sending request"
    r = requests.get('http://cachefly.cachefly.net/10mb.test')
    print "reading.."
    with open("test.dat", "wb") as f:
        f.write(r.content)
    print "Finished..."

if __name__=="__main__":
    for i in xrange(100):
        print "Iteration", i
        lol()
```

The memory usage is printed at the end of each iteration. This is the sample output.
*\* Iteration 0 **

```
Iteration 0
sending request
reading..
Finished...
Filename: test.py

Line #    Mem usage    Increment   Line Contents
================================================
     5     12.5 MiB      0.0 MiB   @profile
     6                             def lol():
     7     12.5 MiB      0.0 MiB       print "sending request"
     8     35.6 MiB     23.1 MiB       r = requests.get('http://cachefly.cachefly.net/10mb.test')
     9     35.6 MiB      0.0 MiB       print "reading.."
    10     35.6 MiB      0.0 MiB       with open("test.dat", "wb") as f:
    11     35.6 MiB      0.0 MiB        f.write(r.content)
    12     35.6 MiB      0.0 MiB       print "Finished..."
```

*\* Iteration 1 **

```
Iteration 1
sending request
reading..
Finished...
Filename: test.py

Line #    Mem usage    Increment   Line Contents
================================================
     5     35.6 MiB      0.0 MiB   @profile
     6                             def lol():
     7     35.6 MiB      0.0 MiB       print "sending request"
     8     36.3 MiB      0.7 MiB       r = requests.get('http://cachefly.cachefly.net/10mb.test')
     9     36.3 MiB      0.0 MiB       print "reading.."
    10     36.3 MiB      0.0 MiB       with open("test.dat", "wb") as f:
    11     36.3 MiB      0.0 MiB        f.write(r.content)
    12     36.3 MiB      0.0 MiB       print "Finished..."
```

The memory usage does not grow with every iteration, but it does continue to creep up with `requests.get` being the culprit that increases memory usage.

By *\* Iteration 99 *\* this is what the memory profile looks like.

```
Iteration 99
sending request
reading..
Finished...
Filename: test.py

Line #    Mem usage    Increment   Line Contents
================================================
     5     40.7 MiB      0.0 MiB   @profile
     6                             def lol():
     7     40.7 MiB      0.0 MiB       print "sending request"
     8     40.7 MiB      0.0 MiB       r = requests.get('http://cachefly.cachefly.net/10mb.test')
     9     40.7 MiB      0.0 MiB       print "reading.."
    10     40.7 MiB      0.0 MiB       with open("test.dat", "wb") as f:
    11     40.7 MiB      0.0 MiB        f.write(r.content)
    12     40.7 MiB      0.0 MiB       print "Finished..."
```

Memory usage doesn't drop unless the program is terminated.

Is there a bug or is it user error? 


Thanks for raising this and providing so much detail!

Tell me, do you ever see the memory usage go down at any point?


I've not seen memory usage go down. I was wondering if it had to do with Python's garbage collector and perhaps it just hasn't had an opportunity to kick in, so I added a call to `gc.collect()` after each download. That made no difference. 


May I ask why this issue has been closed? 

My company has experienced this same issue, which became even more augmented when using pypy.  We spent several days tracing the origin of this issue in our code base to python-requests.

Just to highlight the seriousness of this issue, here's a screenshot of what one of our server processes looked like when running a memory profiler: 
http://cl.ly/image/3X3G2y3Y191h

The issue is still present with regular cpython, but is less noticeable. Perhaps, this is why this issue has been unreported, despite the grave consequences it has for those utilizing this library for long-standing processes.

At this point, we are desperate enough to consider using curl with a subprocess. 

Please let me know what you think and if this will ever be investigated thoroughly.  Otherwise, I hold the opinion that python-requests is too dangerous to use for mission critical applications (eg: health care related services).

Thanks,
-Matt


It was closed due to inactivity. If you believe you can provide useful diagnostics to point us in the right direction, we'd be happy to reopen. 


Well, allow me to help then.

I created small git repo to help faciliate the examination of this issue.
https://github.com/mhjohnson/memory-profiling-requests

Here's a screenshot of the graph it generates:
http://cl.ly/image/453h1y3a2p1r

Hope this helps!  Let me know if I did anything incorrectly.

-Matt


Thanks Matt! I'm going to start looking into this now. The first few times I've run the script, (and variations I've tried) have shown this is easily reproducible. I'm going to have to start playing with this now.


So this grows at about 0.1MB/request. I tried sticking the `profile` decorator on lower level methods but they're all too long for the output to be remotely useful and using a higher interval than 0.1 seems to only serve to track the overall usage, not the per-line usage. Are there better tools than mprof?


So I decided instead to pipe it's output to `| ag '.*0\.[1-9]+ MiB.*'` to get the lines where memory is added and moved the `profile` decorator to `Session#send`. Unsurprisingly, most of it is coming from the call to `HTTPAdapter#send`. Down the rabbit hole I go


And now it's all coming from the call to `conn.urlopen` on L355 and `HTTPAdapter#get_connection`. If you decorate `get_connection`, there are 7 times it allocates memory when it calls `PoolManager#connection_from_url`. Now given the majority are being triggered by `HTTPResponse`s returned from urllib3, I'm going to see if there's something we _should_ be doing with them that we aren't to ensure that memory is released after the fact. If I can't find a good way to handle that, I'll start digging into urllib3.


@sigmavirus24 Wow.  Great work!   It looks like you may have pinpointed the hot spot in the code.
As for tracing the which object is responsible for the memory leak, you might get some extra hints by using objgraph like so:

``` python
import gc
import objgraph
# garbage collect first
gc.collect()  
# print most common python types
objgraph.show_most_common_types()
```

Lemme know if I can help in any way.

-Matt


My first guess as to the culprit would be socket objects. That would explain why it's worse on PyPy...


I'm sitting in an airport right now and I'll be on a plain for several hours soon. I probably won't be able to get to this tonight or until potentially later this week (if not next weekend/week). So far though, I tried using `release_conn` on the `HTTPResponse` we receive back. I checked with `gc.get_referents` what the Response object has that may be failing to be GC'd. It has the original httplib HTTPResponse (stored as `_original_response` and that (from what `get_referents` reported) only has an email Message (for the headers) and everything else is either a string or dictionary (or maybe lists). If it is sockets, I don't see where they wouldn't be garbage collected.

Also, using `Session#close` (I made the code use sessions instead of the functional API first) doesn't help (and that should clear the PoolManagers which clear the connection pools). So the other thing that was interesting was that `PoolManager#connection_from_url` would add ~0.8 MB (give or take 0.1) the first few times it was called. So that adds ~3MB but the rest of it comes from `conn.urlopen` in `HTTPAdapter#send`. The bizarre thing is that `gc.garbage` has some odd elements if you use `gc.set_debug(gc.DEBUG_LEAK)`. It has something like `[[[...], [...], [...], None], [[...], [...], [...], None], [[...], [...], [...], None], [[...], [...], [...], None]]` and as you'd expect `gc.garbage[0] is gc.garbage[0][0]` so that information is absolutely useless. I'll have to experiment with objgraph when I get the chance.


So I dug into urllib3 and followed the rabbit hole further earlier this morning. I profiled `ConnectionPool#urlopen` which lead me to `ConnectionPool#_make_request`. At this point, there's a lot of memory allocated from lines 306 and 333 in `urllib3/connectionpool.py`. L306 is `self._validate_conn(conn)` and L333 is `conn.getresponse(buffering=True)`. `getresponse` is the `httplib` method on a [HTTPConnection](https://docs.python.org/2/library/httplib.html?highlight=httplib#httplib.HTTPConnection.getresponse). Profiling further into that will not be easy. If we look at `_validate_conn` the line there that causes this is `conn.connect()` which is another [HTTPConnection](https://docs.python.org/2/library/httplib.html?highlight=httplib#httplib.HTTPConnection.connect) method. `connect` is almost certainly where the socket is being created. If I disable the memory profiling and I stick a `print(old_pool)` in `HTTPConnectionPool#close` it never prints anything. It would seem we're not actually closing pools as the session gets destroyed. My guess is this is the cause of the memory leak.


Would love to help debug this, I'll be in/out of IRC today and tomorrow.


So tracing this further, if you open up `python` with `_make_request` still decorated (with `profile`), and you create a session, then make requests every 10 or 20 seconds (to the same URL even), you'll see the conn has been considered dropped, so the `VerifiedHTTPSConnection` is closed and then reused. This means the `connection` class is reused, not the underlying socket. The `close` method is the one that lives on [`httplib.HTTPConnection`](https://hg.python.org/cpython/file/515331e0ca0c/Lib/httplib.py) (L798). This closes the socket object, then sets it to None. Then it closes (and sets to None) the most recent `httplib.HTTPResponse`. If you also profile `VerifiedHTTPSConnection#connect`, all of the memory created/leaked happens in `urllib3.util.ssl_.ssl_wrap_socket`.


So looking at this, what memory_profiler is using to report memory usage is the process' resident set size (rss). This is the size of the process in RAM (the vms, or virtual memory size, has to do with mallocs), so I'm looking to see if we're leaking virtual memory, or if we're just having pages allocated for memory that we're not losing.


So given that the all of the URLs we'd been using thus far were using verified HTTPS, I switched to using `http://google.com` and while there's still a consistent increase in memory, it seems that it consumes ~11-14MiB less on the whole. It still all comes back to the `conn.getresponse` line (and to a lesser degree now, `conn.request`). 

The interesting thing is that VMS doesn't seem to grow much when I'm examining it in the repl. I have yet to modify mprof to return that value instead of the RSS value. A steadily increasing VMS will certainly point to a memory leak while RSS could simply be a large number of mallocs (which is possible). Most operating systems (if I understand correctly) don't reclaim RSS eagerly, so until another application page faults and there's no where else to assign it from, RSS will never shrink (even if it could). That said, if we're consistently increasing without reaching a steady-state, I can't be certain if that's requests/urllib3 or just the interpreter


I'm also going to see what happens when we use urllib2/httplib directly because I'm starting to think that this isn't our problem. As far as I can tell, `Session#close` properly closes all sockets and removes references to them to allow them to be GC'd. Further, if a socket needs to be replaced by the Connection Pool, the same happens. Even SSLSockets seem to properly handle being garbage collected.


So urllib2 consistently seems to flatline around 13.3MiB. The difference is I had to wrap it in a try/except because it would consistently crash with a URLError after a short while. So perhaps it's not actually doing anything after a while.


@sigmavirus24 You're crushing it!  :)

Hmm... Python only releases memory to be reused by itself again, and the system doesn't get the memory back until the process terminates.  So, I would think the flatline you are seeing at 13.3MiB is probably indication there is not a memory leak present with urllib2, unlike with urllib3.

It would be nice to confirm that the problem can be isolated to urllib3.  Can you share the scripts you're using to test with urllib2?  


So I'm starting to wonder if this doesn't have something to do with the `HTTPConnection` objects. If you do

``` python
import sys
import requests

s = requests.Session()
r = s.get('https://httpbin.org/get')
print('Number of response refs: ', sys.getrefcount(r) - 1)
print('Number of session refs: ', sys.getrefcount(s) - 1)
print('Number of raw refs: ', sys.getrefcount(r.raw) - 1)
print('Number of original rsponse refs: ', sys.getrefcount(r.raw._original_response) - 1)
```

The first three should print 1, the last 3. [1] I already identified that an HTTPConnection has `_HTTPConnection__response` which is a reference to `_original_response`. So I was expecting that number to be 3. What I cannot figure out is what is holding the reference to the 3rd copy. 

For further entertainment, add the following

``` python
import gc
gc.set_debug(gc.DEBUG_STATS | gc.DEBUG_UNCOLLECTABLE)
```

to the beginning of the script. There are 2 unreachable objects after making the call to requests which is interesting, but nothing was uncollectable. If you add this to the script @mhjohnson provided and you filter the output for the lines with unreachable in them, you'll see that there are plenty of times where there are well over 300 unreachable objects. I don't yet know what the significance of unreachable objects it though. As always, I'll keep y'all posted.

[1]: `sys.getrefcount` always prints 1 more than the actual count. To verify this try: `o = object(); sys.getrefcount(o)`


@mhjohnson to test urllib3, just replace your call to `requests.get` with `urllib2.urlopen` (also I should probably have been doing `r.read()` but I wasn't).


So I took @mhjohnson's previous suggestion and used `objgraph` to figure out where the other reference was, but objgraph can't seem to find it. I added:

```
objgraph.show_backrefs([r.raw._original_response], filename='requests.png')
```

In the script 2 comments above and got the following: 
![requests](https://cloud.githubusercontent.com/assets/240830/4893019/97635df8-63ba-11e4-9518-c25704b4ce2e.png) which only shows that there would be 2 references to it. I wonder if there's something up with how `sys.getrefcount` works that's unreliable.


So that's a red herring. a `urllib3.response.HTTPResponse` has both `_original_response` and `_fp`. That combined with `_HTTPConection__response` gives us three refs.


So, `urllib3.response.HTTPResponse` has a `_pool` attribute which is also referenced by the `PoolManager`. Likewise, the `HTTPAdapter` used to make the request, has a reference on the `Response` requests returns. Maybe someone else can identify something from here:

![requests](https://cloud.githubusercontent.com/assets/240830/4893715/172a5356-63c6-11e4-8e9a-923dcc801246.png)

The code that generates that is: https://gist.github.com/sigmavirus24/bc0e1fdc5f248ba1201d


@sigmavirus24 
Yeah, I got a little lost with that last graphic.  Probably because I don't know the code base very well, nor am I very seasoned on debugging memory leaks.  

Do you know which object this is that I am pointing at with the red arrow in this screenshot of your graphic? 
http://cl.ly/image/3l3g410p3r1C


I was able to get the code to show the same slowly increasing memory usage
on python3 by replacing urllib3/requests with urllib.request.urlopen.

Modified code here: https://gist.github.com/kevinburke/f99053641fab0e2259f0

## 

Kevin Burke
phone: 925.271.7005 | twentymilliseconds.com

On Mon, Nov 3, 2014 at 9:28 PM, Matthew Johnson notifications@github.com
wrote:

> @sigmavirus24 https://github.com/sigmavirus24
> Yeah, I got a little lost with that last graphic. Probably because I don't
> know the code base very well, nor am I very seasoned on debugging memory
> leaks.
> 
> Do you know which object this is that I am pointing at with the red arrow
> in this screenshot of your graphic?
> http://cl.ly/image/3l3g410p3r1C
> 
> —
> Reply to this email directly or view it on GitHub
> https://github.com/kennethreitz/requests/issues/1685#issuecomment-61595362
> .


As far as I can tell making requests to a website that returns a
Connection: close header (for example https://api.twilio.com/2010-04-01.json)
does not increase the memory usage by a significant amount. The caveat is
there are multiple different factors and I'm just assuming it's a socket
related issue.

## 

Kevin Burke
phone: 925.271.7005 | twentymilliseconds.com

On Mon, Nov 3, 2014 at 9:43 PM, Kevin Burke kev@inburke.com wrote:

> I was able to get the code to show the same slowly increasing memory usage
> on python3 by replacing urllib3/requests with urllib.request.urlopen.
> 
> Modified code here:
> https://gist.github.com/kevinburke/f99053641fab0e2259f0
> 
> ## 
> 
> Kevin Burke
> phone: 925.271.7005 | twentymilliseconds.com
> 
> On Mon, Nov 3, 2014 at 9:28 PM, Matthew Johnson notifications@github.com
> wrote:
> 
> > @sigmavirus24 https://github.com/sigmavirus24
> > Yeah, I got a little lost with that last graphic. Probably because I
> > don't know the code base very well, nor am I very seasoned on debugging
> > memory leaks.
> > 
> > Do you know which object this is that I am pointing at with the red arrow
> > in this screenshot of your graphic?
> > http://cl.ly/image/3l3g410p3r1C
> > 
> > —
> > Reply to this email directly or view it on GitHub
> > https://github.com/kennethreitz/requests/issues/1685#issuecomment-61595362
> > .


@mhjohnson that seems to be the number of references to the metatype `type` by `object` which is of type `type`. In other words, I think that's all the references of either `object` or `type`, but I'm not quite sure. Either way, if I try to exclude those, the graph becomes something like 2 nodes.


I am also very concerned about this memory leak problem because we use Requests in our web crawling system in which a process usually runs for several days. Is there any progress on this issue?