uvicorn icon indicating copy to clipboard operation
uvicorn copied to clipboard

Memory leak when using request.state

Open Kludex opened this issue 2 years ago • 15 comments

Discussed in https://github.com/encode/starlette/discussions/1748

Originally posted by galkahana July 10, 2022 Hi, I noticed that setting properties on request.state results in memory leak.

Originally an issue I reported in fastapi, it seems that the following server definition will cause memory usage to grow on every request:

from starlette.applications import Starlette
from starlette.responses import JSONResponse
from starlette.routing import Route
from starlette.requests import Request


async def homepage(request: Request):
    request.state.test = [x for x in range(999999)]
    return JSONResponse({'hello': 'world'})


app = Starlette(routes=[
    Route('/', homepage),
])

The array set as the test property of request.state is never released. There's a workaround that I can use to resolve this by setting the the property to none at the end of the request - request.state.test = None.

I created a repo to demonstrate the issue here.

Figured i'll report, so at least if someones getting a memory leak, this can help in possibly finding the cause.

Kludex avatar Jul 10 '22 06:07 Kludex

Investigating... I can see this:

https://github.com/encode/starlette/blob/e7717af33c8ae0cd8458886f7359c9753746ed5f/starlette/datastructures.py#L704-L705

Kludex avatar Jul 10 '22 06:07 Kludex

The above application starts with 22 MB. With 100 requests, I end up with 127 MB. Each request increases 7~8 MB of the memory footprint.

Deleting the key in the same endpoint, I have 66 MB at the end of 100 requests.

async def homepage(request: Request):
    request.state.test = [x for x in range(999999)]
    del request.state.test
    print(request.scope)
    return JSONResponse({'hello': 'world'})

An empty endpoint is able to come back to 22~23 MB:

async def homepage(request: Request):
    return JSONResponse({'hello': 'world'})

I'm not using the repository above on my debugging work. I'm only using top -pid <pid> to check the memory usage.

I need to leave now, I'll be back later. 👋

Kludex avatar Jul 10 '22 08:07 Kludex

The above results were on Mac. It looks like the garbage collector was more active there than on Ubuntu (?).

On Ubuntu, I see 3.7 GB with 100 requests.

Kludex avatar Jul 10 '22 13:07 Kludex

Given that request.state is stored in the request scope, does such a memory leak not have more to do with the lifecycle of the scope dictionary? Which would be more on the uvicorn side?

When do the last references to scope objects expire?

I do not think we can rely on the raw numbers returned by top to detect the presence of a memory leak, because Python's memory manager is known for keeping memory in order to reuse it later in case it is needed. (e.g. https://rushter.com/blog/python-garbage-collector/)

jhominal avatar Jul 10 '22 15:07 jhominal

The bug is confirmed to be on uvicorn. The behavior doesn't happen with hypercorn.

Kludex avatar Jul 10 '22 15:07 Kludex

I started doing some digging a bit on this issue and I noticed that if you run with logging in trace mode you can notice that memory increase only happens when establishing a new connection, so if you span requests in sequence it will be using the same connection so memory will not increase.

The data lives inside the protocol cycle.scope object and it's reset every time a new connection is made, something is still holding the closed connections and I couldn't be sure if it's just the request/response cycle that is being kept beyond the disconnection.

humrochagf avatar Jul 16 '22 16:07 humrochagf

In hypercorn it doesn't happen because the TCP server is always destructed per request so all references are destructed with the end of the request/response cycle. So in hypercorn case socket always changes per request since everything is torn down in every call.

humrochagf avatar Jul 16 '22 17:07 humrochagf

I have a similar issue, where memory grows from 260MB to 500MB within 3 days. The application itself was idle, except for handling 404 GetRequests or invalid http requests. Tried various things by using tracemalloc and comparing snapshots but without success.

florianfischer91 avatar Jul 18 '22 12:07 florianfischer91

More findings on the case: In fact, cycle is kind of ok because it's refreshed in every request cycle and so is the scope (that holds the state).

What's happening is that the protocol itself has a refcount of 11. Also on every new connection made, a new instance of the protocol is created and something must be holding the old instance (maybe asyncio reuses it in the server lifecycle for optimization purposes, not sure yet)

But one thing that can be done as good practice is to release the variables that are per-request, and maybe also the ones that are per connection at the connection_lost method.

For example, if we set both self.scope and self.cycle (because cycle also holds scope) to None at the end of connection_lost method, then this memory increase issue is solved.

I'll start a WIP PR so we can iterate on this.

humrochagf avatar Jul 22 '22 16:07 humrochagf

Since you're sharing... I'm going to give you more information...

The HTTP protocol object is not freed, as you said. It contains a reference cycle. The garbage collector is not able to clean it in time. The object goes to the third generation. The third generation needs a condition to be met to be cleaned (see Python docs), which takes time.

I've found the cycle, and removed the cycle.

image

The issue didn't disappear. I'm trying to find if there's another cycle.

I'm going to provide a full report when I'm able to fix this issue. @graingert (helping me a lot on this 🙏) and @euri10 are aware of everything that I've been doing.

Although this is an issue, and we need to solve it, I've confirmed that is an issue that uvicorn always had (since the framework was created). Also, it doesn't affect everybody in the same way, and the memory is cleaned at some point, it's just that it takes some time.

That said, it's still my priority.

Kludex avatar Jul 22 '22 16:07 Kludex

Yeah, I noticed that this was always there. Nice, thanks for the detailed info and the hard work on uvicorn :slightly_smiling_face: Since you are already on it I'll be geeking it just for fun, if find something that could help I'll let you know.

humrochagf avatar Jul 22 '22 16:07 humrochagf

I'll be a bit away for the next two weeks, so if you solve it, feel free to create a PR. 🙏

If not, when I'm back I'll continue on it.

Kludex avatar Jul 22 '22 16:07 Kludex

@Kludex do we have any update for this issue ?

ericazhao-china avatar Aug 09 '22 07:08 ericazhao-china

Well, considering that I said that I'd be away for two weeks... No updates.

Kludex avatar Aug 09 '22 07:08 Kludex

I've found the cycle, and removed the cycle

Do you have the PR for that or do you mean just locally?

graingert avatar Aug 09 '22 08:08 graingert

Alright, I gave it another try and I compared with h11 protocol that was well managing its memory, so in the end it seems that the way httptools decorates the protocol, it keeps a bunch of references to it in each decorated method and by stop referencing it during disconnection you remove the cyclic reference, so the garbage collector can do it's work :smiley:

humrochagf avatar Aug 19 '22 16:08 humrochagf

Humberto solved the issue. Thanks @humrochagf 🙏

The fix will be available in uvicorn 0.18.3.

Kludex avatar Aug 24 '22 06:08 Kludex

Thank you both :)

galkahana avatar Aug 24 '22 08:08 galkahana

No problem, I'm glad to be able to help 🙂

humrochagf avatar Aug 24 '22 10:08 humrochagf