Redis asyncio clients not correctly traced

[Vivanov98]

Currently the redis asyncio clients (Redis, Pipeline etc) are not being traced correctly. Every trace is a tiny fragment of the actual time, occurring around the start time of the redis command being called.

I narrowed this down to the instrumentor for redis not wrapping the async variants as expected (it uses the same sync approach that it uses for the sync redis - and as a result the span only traces the coroutine creation, but not the coroutine actually being awaited).

The result is a very short trace (< 1ms) at the start of the redis call that doesn't actually show the full time of the redis command.

I have fixed this in a follow up PR, which I will put up shortly and link.

Describe your environment
Python version: 3.11
redis-py version: 4.5.5
opentelemetry-instrumentation-redis version: current master or 0.39b0
OS: Ubuntu

Steps to reproduce

Here is an example script, which calls an async redis command, and an async redis pipeline.

For each async call:

• A parent span is started
• asyncio.sleep for 50 milliseconds (to create a time delta between the parent span and the actual redis span for visual clarity)
• call a redis command (debug-sleep) for 100 milliseconds

The data can then be visualised and the parent span compared to the redis-instrumentor generated span to see that the span doesn't encompass the full time of the command.

import asyncio

from opentelemetry.instrumentation.redis import RedisInstrumentor
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.resources import Resource
from opentelemetry.sdk.trace.export import BatchSpanProcessor, ConsoleSpanExporter
from redis.asyncio import Redis



tracer_provider = TracerProvider(
    resource=Resource.create({
        "service.name": "my-app",
        "service.instance.id": "my-app-4",
    }),
)
tracer = tracer_provider.get_tracer(__name__)


async def call_redis_command() -> None:
    redis_pool = Redis(host="0.0.0.0", port=6379)
    with tracer.start_as_current_span("redis-command-wrapper"):
        await asyncio.sleep(0.05)
        await redis_pool.execute_command("DEBUG", "SLEEP", "0.1")

async def call_redis_pipeline() -> None:
    redis_pool = Redis(host="0.0.0.0", port=6379)
    with tracer.start_as_current_span("redis-pipeline-wrapper"):
        await asyncio.sleep(0.05)
        p = await redis_pool.pipeline()
        p.execute_command("DEBUG", "SLEEP", "0.1")
        await p.execute()

exporter = ConsoleSpanExporter()
span_processor = BatchSpanProcessor(span_exporter=exporter)
tracer_provider.add_span_processor(span_processor)

RedisInstrumentor().instrument(tracer_provider=tracer_provider)

asyncio.run(call_redis_command())
asyncio.run(call_redis_pipeline())

Below I have used jaeger to visualise the traces for ease of reading

What is the expected behavior?
Expecting to see 100 milliseconds of a redis command, wrapped by the 150 milliseconds parent span

(This is a screenshot from when I fix the code)

What is the actual behavior?
Actually seeing a really tiny redis command span (< 0.2ms) wrapped by the 150millisecond parent span

(This is a screenshot from the results of the example provided script)