joerick / pyinstrument

🚴 Call stack profiler for Python. Shows you why your code is slow!
https://pyinstrument.readthedocs.io/
BSD 3-Clause "New" or "Revised" License
6.44k stars 227 forks source link

Using a lock inexplicably doesn't protect against multiple profilers #307

Open datalogics-kam opened 3 months ago

datalogics-kam commented 3 months ago

I'm profiling a FastAPI app, and when I'm doing that, I know that multiple profilers can't have sync enabled. So I figured, I'd protect the profiler with a lock. It'd serialize the calls the front end is doing in parallel, but for profiling, I don't care. So I did:

profiler_lock = asyncio.Lock()

# https://pyinstrument.readthedocs.io/en/latest/guide.html#profile-a-web-request-in-fastapi
@app.middleware("http")
async def profile_request(request: Request, call_next):
    if request.method == "OPTIONS":
        return await call_next(request)
    async with profiler_lock:
        profiler = Profiler(
            interval=0.001, async_mode="enabled"  # settings.profiling_interval,
        )
        with profiler:
            retval = await call_next(request)
        now = datetime.datetime.now().isoformat(timespec="microseconds")  # noqa: DTZ005
        with Path(f"{now}.prof.txt").open("w") as f:
            f.write(profiler.output_text())
        with Path(f"{now}.speedscope.json").open("w") as f:
            f.write(profiler.output(SpeedscopeRenderer()))
    return retval

But still, I get an exception:

  File "/Users/kam/src/dl/pdfassistant-chatbot-async/.venv/lib/python3.11/site-packages/starlette/middleware/base.py", line 191, in __call__
    response = await self.dispatch_func(request, call_next)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/kam/src/dl/pdfassistant-chatbot-async/pdfassistant_chatbot/app.py", line 149, in profile_request
    with profiler:
  File "/Users/kam/src/dl/pdfassistant-chatbot-async/.venv/lib/python3.11/site-packages/pyinstrument/profiler.py", line 207, in __enter__
    self.start(caller_frame=inspect.currentframe().f_back)  # type: ignore
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/kam/src/dl/pdfassistant-chatbot-async/.venv/lib/python3.11/site-packages/pyinstrument/profiler.py", line 131, in start
    get_stack_sampler().subscribe(
  File "/Users/kam/src/dl/pdfassistant-chatbot-async/.venv/lib/python3.11/site-packages/pyinstrument/stack_sampler.py", line 62, in subscribe
    raise RuntimeError(
RuntimeError: There is already a profiler running. You cannot run multiple profilers in the same thread or async context, unless you disable async support.

I've tried everything; I've tried print statements, it doesn't appear the locked section is being entered twice.

Am I missing something really dumb, or did I find a subtle interaction between the locking and the profiing?

joerick commented 1 month ago

I'm not sure... are you sure your program doesn't start a profiler somewhere else? Or perhaps the middleware function is reentrant somehow?