Skip to content

Nested asyncio tasks are not displayed as nested #413

@mr-flannery

Description

@mr-flannery

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

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions