Zenn
👨‍💻

fastapiにcProfileは使えない？

2025/02/13に公開
FastAPI
profile
pyinstrument
cprofile
tech

概要

fastapiのasyncなpathをプロファイリングしたい時は、cProfileを使わずにpyinstrumentを使う方が良さそうという話。

cProfileの問題点

cProfileだと何故asyncなpathの解析が上手くいかないか、実演したいと思います。

cprofile_middleware

最初にcProfileでプロファイルを行うためのmiddlewareを定義します。
リクエスト毎に解析用のpstatsファイルを吐き出します。

import cProfile
from fastapi import Request

async def cprofile_middleware(request: Request, call_next):
    with cProfile.Profile() as pr:
        response = await call_next(request)
        pr.dump_stats("profile.pstats")
    return response



appにmiddlewareをセット。

app = FastAPI()

app.middleware("http")(cprofile_middleware)


syncなpath

appにsyncなrootを定義してみます。

def child_function():
    for _i in range(10):
        time.sleep(1)
    return

def parent_function():
    for _i in range(10):
        time.sleep(1)
    child_function()
    return

@app.get("/sync")
def sync_root():
    parent_function()
    return {"Hello": "World"}


こちらを叩きます。

curl -X GET http://localhost:8000/sync



作成されたpstatsファイルをgprof2dotで可視化します。

poetry run gprof2dot -f pstats profile.pstats | dot -Tpng -o sync_output.png



とても分かり易いです。


asyncなpath

次にappにasyncなrootを定義してみます。

async def async_child_function():
    for _i in range(10):
        await asyncio.sleep(1)
    return

async def async_parent_function():
    for _i in range(10):
        await asyncio.sleep(1)
    await async_child_function()
    return

@app.get("/async")
async def async_root():
    await async_parent_function()
    return {"Hello": "World"}



こちらを叩きます。

curl -X GET http://localhost:8000/async



作成されたpstatsファイルをgprof2dotで可視化します。

poetry run gprof2dot -f pstats profile.pstats | dot -Tpng -o async_output.png



🤮🤮🤮🤮🤮
グチャグチャになっています。



非同期関数への出入りをcProfileは関数呼び出しと認識してしまう為の様です。
詳しくは以下の記事に記載されています。

https://blog.balthazar-rouberol.com/how-to-profile-a-fastapi-asynchronous-request

As an asynchronous function is "entered" and "exited" by the event loop at each await clause, every time the event-loop re-enters a function, cProfile will see this as an additional call, thus causing seemingly larger-than-normal ncalls numbers. Indeed, we await every-time we perform an SQL request, commit or refresh the SQLAlchemy session, or anything else inducing asynchronous I/O. Secondly, the reason that the get_character span appears to be free-floating is because it is executed outside of the main thread, by the Python event-loop.

pyinstrumentだとどうなるか

では上記の記事でもおすすめされているpyinstrumentを使ってプロファイリングしてみます。

pyinstrument_middleware

pyinstrumentでプロファイルを行うためのmiddlewareを定義します。
リクエスト毎に解析結果のhtmlファイルを吐き出します。

from fastapi import Request
from pyinstrument import Profiler

async def pyinstrument_middleware(request: Request, call_next):
    profiler = Profiler()
    profiler.start()
    response = await call_next(request)
    profiler.stop()

    with open("profile.html", "w") as f:
        f.write(profiler.output_html())
    return response


appにmiddlewareをセット。

app = FastAPI()

app.middleware("http")(pyinstrument_middleware)


syncなpath

syncなpathを叩きます。

curl -X GET http://localhost:8000/sync

open profile.html


syncなパスに対してpyinstrumentでプロファイリングしてもあまり有効な情報は得られないようです。
（この場合はcProfileで解析をするのが良さそう）



asyncなpath

次にasyncなpathを叩きます。

curl -X GET http://localhost:8000/async

open profile.html


😊😊😊😊😊
どこで処理に時間がかかっているか分かり易く出力されます。

まとめ

fastapiではsyncなpathとasyncなpathでプロファイリング方法が変わってくる。
asyncなpathではpyinstrumentなどのツールでプロファイリングするのが良い。

pyinstrument以外にもおすすめのツールがあればコメントください。

Discussion