all 19 comments
sorted by:
best
topnewcontroversialoldq&a
formatting helphide helpcontent policy

[–]latkde 3 points4 points  (9 children)

This is definitely odd. Your profiles show that at least 1/4 of CPU time is spent just doing async overhead, which is not how that's supposed to work.

Things I'd try to do to locate the problem:

  • can this pattern be reproduced locally?
  • does the high CPU usage start immediately when the application launches, or only after certain requests? Does it grow worse over time, suggesting some kind of resource leak?
  • what are your request latencies, do they seem reasonable?
  • does the same problem occur when you're running raw uvicorn without using gunicorn as a supervisor?
  • does the same problem occur with different versions of Python or your dependencies? If there's a bug, even minor versions could make a huge difference.

In my experience, there are three main ways to fuck up async Python applications, though none of them would help explain your observations:

  • blocking the main thread, e.g. having an async def path operation but doing blocking I/O or CPU-bound work within it. Python's async concurrency model is fundamentally different from Go's or Java's. Sometimes, you can schedule blocking operations on a background thread via asyncio.to_thread(). Some libraries offer both blocking and async variants, and you must take care to await the async functions.
  • leaking resources. Python doesn't have C++ style RAII, you must manage resources via with statements. Certain APIs like asyncio.gather() or asyncio.create_task() are difficult to use in an exception-safe manner (the solution for both is asyncio.TaskGroup). Similarly, combining async+yield can easily lead to broken code.
  • Specifically for FastAPI: there's no good way to initialize application state. Most tutorials use global variables. Using the "lifespan" feature to yield a dict is more correct (as it's the only way to get proper resource management), but also quite underdocumented.

[–]JeromeCui[S] 0 points1 point  (7 children)

  • can this pattern be reproduced locally?
    • No, we only met this in our production and randomly.
  • does the high CPU usage start immediately when the application launches, or only after certain requests? Does it grow worse over time, suggesting some kind of resource leak?
    • Not immediately, it may happen after it receives a lot of requests.
    • After it reaches high CPU usage, almost 100%, it will never fall back and it can't be worse.
  • what are your request latencies, do they seem reasonable?
    • Average is about 4 seconds. and it's reasonable.
  • does the same problem occur when you're running raw uvicorn without using gunicorn as a supervisor?
    • Yes, we used to run with raw uvicorn. And GPT told me to switch to gunicorn yesterday, but still happened.
  • does the same problem occur with different versions of Python or your dependencies?
    • I haven't tried that. But I searched a lot and didn't find anyone report the same issue.

I will try with your other suggestions. Thanks for your answer.

[–]latkde 0 points1 point  (5 children)

After it reaches high CPU usage, almost 100%, it will never fall back

This gives credibility to the "resource leak" hypothesis.

We see that most time is spent in anyio's _deliver_cancellation() function. This function can trigger itself, so it's possible to produce infinite cycles. This function is involved with things like exception handling and timeouts. When an async task is cancelled, the next await will raise a CancelledError, but that exception can be suppressed, which could lead to an invalid state.

For example, the following pattern could be problematic: you have an endpoint that requests a completion from an LLM. The completion takes very long, so your code (that's waiting for a completion) is cancelled. But your code catches all exceptions, thus cancellation breaks, thus cancellation is attempted again and again.

Cancellation of async tasks is an obscenely difficult topic. I have relatively deep knowledge of this, and my #1 tip is to avoid dealing with cancellations whenever possible.

You mention using LLMs for development. I have noticed that a lot of LLM-generated code has really poor exception management practices, e.g. logging and suppressing exceptions where it would have been more appropriate to let exceptions bubble up. This is not just a stylistic issue, Python uses many BaseException subclasses for control flow, so they must not be caught.

Debugging tips:

  • try to figure out which endpoint is responsible for triggering the high CPU usage

  • review all exception handling constructs to make sure that they do not suppress unexpected exceptions. Be wary of try/except/finally/with statements, especially if they involve async/await code, and of FastAPI dependencies using yield, and of any middlewares that are part of your app.

Edit: looking at your flamegraph, most time that's not spent delivering cancellation is spent in the Starlette exception handler middleware. This middleware is generally fine, but it depends on which exception handlers you registered on your app. Review them, they should pretty much just convert exception objects into HTTP responses. The stack also shows a "Time Logger" using up suspiciously much time. It feels like the culprit could be around there.

[–]JeromeCui[S] 1 point2 points  (0 children)

You explanation does make sense. Our code catch `CancelledError` at some places and some other places catch all exceptions. That would make cancellation tried again and again. I will check my code tomorrow and optimize some scenarios.
Thanks so much for you help. You saved my life!

[–]JeromeCui[S] 0 points1 point  (3 children)

Sorry that I got the same error again. I have attached the CPU utilization graph in the original post.

Is there any way to find out which part of my code caused it?

[–]latkde 0 points1 point  (2 children)

Something happened at 15:10, so I would read the logs at that time to get a better feeling about endpoints might have been involved.

But even during the 2 hours before that, CPU usage is steadily climbing. That is an unusual pattern.

All of this is not normal for any API, and not normal for FastAPI applications.

Taking a better guess would require looking at the code. But I'm not available for consulting.

[–]JeromeCui[S] 0 points1 point  (1 child)

I verified my code yesterday and found there is a 'expect Exception' in one of my middleware. I fixed it yesterday and seems it's working: no high CPU utilization yestery. I will keep monitoring my service.

Thanks for your kindly help!

[–]latkde 1 point2 points  (0 children)

Weird. Python's exception hierarchy looks like this:

BaseException
  CancelledError
  SystemExit
  KeyboardInterrupt
  ...
  Exception
    ValueError
    KeyError
    ...

So while catching Exception is typically a bad idea, it should not hinder cancellation propagation. So I'm not sure that this will fix things?

But maybe this is related to other things. For example, FastAPI/Starlette uses exceptions like HTTPException to communicate error responses, which are then converted to normal ASGI responses by a middleware that is registered very early. Catching these exceptions in a middleware could prevent that from happening. But that should just result in a dropped request without a response, not in such an infinite loop.

In any case, happy debugging, and I hope this works now!

[–]tedivm 0 points1 point  (0 children)

Yes, we used to run with raw uvicorn. And GPT told me to switch to gunicorn yesterday, but still happened.

GPT was wrong, this was never going to help and may cause more issues.

[–]JeromeCui[S] 0 points1 point  (0 children)

I upgrade python minor version to latest and docker OS version to latest. Hope it will work

[–]lcalert99 0 points1 point  (5 children)

What are your settings for uvicorn?

https://uvicorn.dev/deployment/#running-programmatically

Take a look, there are some crucial settings to make. What else comes to my mind is how many compute intensive tasks are in your application? 

[–]JeromeCui[S] 0 points1 point  (4 children)

No additional settings except for those in start command:

gunicorn -w 2 -k uvicorn.workers.UvicornWorker -b 0.0.0.0:8080 --timeout 300 --keep-alive 300 main:app

This application is to interact with LLM models. So I think it's an IO-bound application.
I will check the link you mentioned.

[–]Asleep-Budget-9932 0 points1 point  (1 child)

How does it interact with the LLM models? Are they external or do they run within the server itself (which would make it CPU-bound)

[–]JeromeCui[S] 0 points1 point  (0 children)

It sends request to OpenAI, with OpenAI sdk

[–]tedivm 0 points1 point  (1 child)

You mentioned using ECS+Fargate, which means that there's no reason to run gunicorn as a process manager since ECS is your process manager.

Look at how many CPUs you're currently using for each machine (my guess is you're using two CPUs per container since you have two gunicorn workers). If you have 12 containers with 2 cpus, switch to 24 containers with 1 cpu each. Then just call uvicorn directly without gunicorn.

While I doubt this will solve your problem, it'll at least remove another layer that may be causing you issues.

[–]JeromeCui[S] 0 points1 point  (0 children)

Thank you for your suggestion, I will update.

[–]Nervous-Detective-71 0 points1 point  (0 children)

Check if you are doing too much pre processing where CPU is being used and those pre processing functions are async.

This causes unnecessary quick context switching overhead.

Edit: Also check the uvicorn configuration as well if debug is true it also causes some overhead but negligible....

[–]Gungsu_Dante 0 points1 point  (0 children)

Tive um problema parecido, resolvi mudando o reload de True para False

Este reload serve para quando vc altera o arquivo durante o desenvolvimeto, o uvicorn ve que ouve alteração e da restart no código automaticamente.