pyinstrument icon indicating copy to clipboard operation
pyinstrument copied to clipboard

Nested asyncio tasks are not displayed as nested

Open mr-flannery opened this issue 2 months ago • 0 comments

Hi @joerick ,

I'm trying to profile a uvicorn/connexion based python webserver, but I'm having problems with making it display nested asyncio tasks correctly. I'm unsure whether this is a setup a issue on my part or if this is how it's supposed to work.

I tried to build a quick reproducer to illustrate this setup into the existing server, but I can't share the code since it's internal. If this doesn't suffice, I can also setup a separate public repo.

from pyinstrument import Profiler
from starlette.middleware.base import BaseHTTPMiddleware


class ProfilerMiddleware(BaseHTTPMiddleware):
    async def dispatch(self, request, call_next):
        profiler = Profiler(async_mode="strict")
        profiler.start()
        async with asyncio.TaskGroup() as tg:
            task = tg.create_task(call_next(request), name="profiler_task")
        
        response = task.result()
        
        profiler.stop()
        print(profiler.output_text(unicode=True, color=True))
        # Or save to file:
        with open(f"{datetime.datetime.fromtimestamp(time.time()).strftime('%Y-%m-%d %H:%M:%S')}_profile_{request.url.path.replace('/', '_')}.html", "w") as f:
            f.write(profiler.output_html())
        
        return response
    
from starlette.responses import PlainTextResponse
from starlette.requests import Request as StarletteRequest

async def nested_asyncio_tasks(request: StarletteRequest): 
    for i in range(2):    
        await asyncio.sleep(1.0)  # Simulate some initial work
        # async with asyncio.TaskGroup() as tg:
        #     tg.create_task(asyncio.sleep(1), name=f"outer_task_1-{i}")
        #     tg.create_task(asyncio.sleep(1.5), name=f"outer_task_2-{i}")
        #     tg.create_task(asyncio.sleep(2), name=f"outer_task_3-{i}")
        task1 = asyncio.create_task(asyncio.sleep(1), name=f"outer_task_1-{i}")
        task2 = asyncio.create_task(asyncio.sleep(1.5), name=f"outer_task_2-{i}")
        task3 = asyncio.create_task(asyncio.sleep(2), name=f"outer_task_3-{i}")
        await asyncio.gather(task1, task2, task3)
    return PlainTextResponse("OK")

def build_app(lifespan: Any) -> AsyncApp:
    app = AsyncApp(__name__, lifespan=lifespan)

    app.add_middleware(ProfilerMiddleware, MiddlewarePosition.BEFORE_EXCEPTION)
    app.add_url_rule("/profiling", 
                        endpoint="profiling", 
                        view_func=nested_asyncio_tasks, 
                        methods=["GET"])    
    return app

# lifespan omitted for brevity
app = build_app(lifespan=lifespan)

def main() -> None:
    app.run()

When calling localhost:8080/profiling, the following is roughly the flamegraph I would expect to see:

Image

The flamegraph that is being produced looks like this:

Image

2025-11-03 16:31:36_profile__profiling copy.html

Compared to what I would have expected as output, two things stand out:

  • the order of operation seems to be wrong. some of the middlewares are supposedly called at 3s, though all middlewares must have been called before nested_asyncio_tasks is being called
  • the nesting is lost, i.e. every new task that is being spawned (regardless of whether a TaskGroup is used or not) is nested under Runner.run

I saw the section in the docs that discussed where that where the Profiler is being instantiated makes a difference as to what is being profiled, but that also doesn't seem to change the behavior from what I can tell.

Is my expectation towards the output reasonable/possible to be configure? Or does this fundamentally not work with asyncio tasks? Let me know if you need any more input!

Thanks and best regards, Dennis

mr-flannery avatar Nov 03 '25 16:11 mr-flannery