opentelemetry-python-contrib icon indicating copy to clipboard operation
opentelemetry-python-contrib copied to clipboard

`opentelemetry-instrumentation-psycopg` claims to work for async queries, but doesn't record time

Open samuelcolvin opened this issue 1 year ago • 0 comments
trafficstars

This was orignally reported as https://github.com/pydantic/logfire/issues/65 which has version details etc.

But in summary, using opentelemetry-instrumentation-psycopg="0.45b0" to instrument asyncio queries, doesn't work properly.

The cause is as follows:

https://github.com/open-telemetry/opentelemetry-python-contrib/blob/5116305f77bcd4c8ab18ef302a4351bb5b724c1e/instrumentation/opentelemetry-instrumentation-psycopg/src/opentelemetry/instrumentation/psycopg/init.py#L335-L338

calls

https://github.com/open-telemetry/opentelemetry-python-contrib/blob/5116305f77bcd4c8ab18ef302a4351bb5b724c1e/instrumentation/opentelemetry-instrumentation-dbapi/src/opentelemetry/instrumentation/dbapi/init.py#L472-L475

calls

https://github.com/open-telemetry/opentelemetry-python-contrib/blob/5116305f77bcd4c8ab18ef302a4351bb5b724c1e/instrumentation/opentelemetry-instrumentation-dbapi/src/opentelemetry/instrumentation/dbapi/init.py#L408-L414

which isn't designed to support an awaitable query_method, so it immediately returns a future, which gets awaited after the span has closed, hence zero time spans:

From Logfire, we see: image

when we'd expect something similar to what's observed with sync calls: image

I'm not clear why TracedCursorProxy is required rather than just using CursorTracer, but either way, I'd suggest implementing an async varient of traced_execution which tries to share as much logic as possible with the sync method.

If you agree, I'll try to create a PR for this over the next week or so.

samuelcolvin avatar May 01 '24 14:05 samuelcolvin