sentry-python icon indicating copy to clipboard operation
sentry-python copied to clipboard

Tracing: Some concurrently created Spans are not recorded.

Open hishnash opened this issue 3 years ago • 4 comments

Environment

SaaS (https://sentry.io/)

Version

No response

Steps to Reproduce

Using the python SDK. version 1.5.4.

if you run multiple subtasks concurrently (with async await) within each of these subtasks there are a few nested spans.

async def _batch_task(task: Coroutine, pool: asyncio.Semaphore, span: Span, index: int):
    async with pool:
        # Sleep 0 means if we have been canceled we exit before calling the task
        # await asyncio.sleep(0)
        with span.start_child(op="batch", description=f'task-{index}'):
            await task


async def batch(items: List[Coroutine], size=10):
    with start_span(op="utils", description='batch') as span:
        span.set_data('size', size)
        span.set_data('number_of_coroutines', len(items))

        if len(items) == 0:
            return

        loop = asyncio.get_event_loop()

        pool = asyncio.Semaphore(value=size)

        tasks = [
            loop.create_task(
                _batch_task(coroutine_item, pool, span, index)
            ) for index, coroutine_item in enumerate(items)
        ]

        try:
            await asyncio.wait(
                tasks,
                return_when=asyncio.FIRST_EXCEPTION
            )
        finally:
            # loop over unfinished tasks canceling them.
            for task in tasks:
                task.cancel()
                try:
                    # To raise any exception it might have thrown
                    await task
                except asyncio.CancelledError:
                    pass

Expected Result

For each nested subtask to see the full tree of spans on sentry.io

Actual Result

image

See the attache screenshot here the 3 items labeled batch should have identical trees within them. Other code running on the server has validated that those nested code did in fact run so the issue is either in the python sdk not recording them or the sentry UI not display them.

when I inspect the json that I can download from the page, (not sharing here as it contained sensitive data) I see that the spans that should have children in the graph do not have any child entries in the json. image

hishnash avatar Feb 10 '22 21:02 hishnash

Routing to @getsentry/visibility for triage. ⏲️

getsentry-release avatar Feb 11 '22 18:02 getsentry-release

👋 Moving to the sentry-python repo since this sounds like a SDK issue rather than one with the UI

wmak avatar Feb 11 '22 18:02 wmak

hey, sorry for the (very) late reply on this. We're finally looking into possibly fixing the async problems in #1664. I think all the spans are there, they just have the wrong parents.

If you're still up for trying this out @hishnash, I'd love to get some feedback if you try this instead - basically cloning the Hub to each task and if it gets the correct nesting output.

async def _batch_task(task: Coroutine, pool: asyncio.Semaphore, span: Span, index: int):
    async with pool:
        # Sleep 0 means if we have been canceled we exit before calling the task
        # await asyncio.sleep(0)
        with sentry_sdk.Hub(sentry_sdk.Hub.current):
            with span.start_child(op="batch", description=f'task-{index}'):
                await task

sl0thentr0py avatar Oct 06 '22 13:10 sl0thentr0py

I have now created a reproduction script: https://github.com/getsentry/minimum_python_async/blob/main/task2.py (Notice that I do not create spans/children in _batch_task() anymore.)

I also created a new AsyncioIntegration that creates new spans for async tasks.

Image

And I guess this is the output we want to have. :)

antonpirker avatar Oct 10 '22 15:10 antonpirker