Why pubsub first data message latency has 1000us ?

[daoiqi]

Version: What redis-py and what redis version is the issue happening on?
pyredis: '5.0.5'
redis: 7.0

Platform: What platform / version? (For example Python 3.5.1 on Windows 7 / Ubuntu 15.10 / Azure)
client: python 3.11.7 / centos7

Description:

Why pubsub first data message latency has 1136.499 us ? and below data message is 300us?

The code is based on the official demo:
https://redis-py.readthedocs.io/en/stable/examples/asyncio_examples.html#Pub/Sub-Mode

subscriber

def get_redis():
    """
    get redis client
    """
    redis_host = '10.6.0.1'
    port = 6379
    paswword = 'r'
    client = redis.Redis(
        host=redis_host,
        port=port,
        # username='d',
        password=paswword,
        decode_responses=True,
        # protocol=3
    )
    return client

async def send_message(payload):
    # write real code here
    # logging.debug(f"Sending message to user {payload['time']}")
    c = time.time_ns()
    s = payload['time']
    cost = (c - s) / 1000
    print(f"Sending message time current = {c}, start = {s}, cost_time = {cost} us")
    # await asyncio.sleep(1)

CHANNEL_NAME = "channel:test"


async def handle_notification():
    pubsub = redis_client.pubsub()
    await pubsub.subscribe(CHANNEL_NAME)
    while True:
        try:
            message = await pubsub.get_message()
            # print(message)
            if message and message["type"] == "message":
                print(message)
                payload = json.loads(message["data"])
                # TODO: do validation on payload
                await send_message(payload)
        except (asyncio.TimeoutError, json.decoder.JSONDecodeError) as e:
            logging.error(e)

if __name__ == "__main__":
    asyncio.run(handle_notification())

Publisher

r = redis_util.get_redis()


CHANNEL_NAME = "channel:test"


async def main():
    async with r.pubsub() as pubsub:
        await pubsub.psubscribe(CHANNEL_NAME)

        for i in range(20):
            await r.publish(CHANNEL_NAME, json.dumps({"time": time.time_ns()}))
        # await r.publish(CHANNEL_NAME, json.dumps({"time": time.time()}))
        # await r.publish("channel:1", STOPWORD)

        # await future

asyncio.run(main())

Run Result

{'type': 'message', 'pattern': None, 'channel': 'channel:test', 'data': '{"time": 1719310968726495664}'}
Sending message time current = 1719310968727632163, start = 1719310968726495664, cost_time = 1136.499 us
{'type': 'message', 'pattern': None, 'channel': 'channel:test', 'data': '{"time": 1719310968727459818}'}
Sending message time current = 1719310968727762169, start = 1719310968727459818, cost_time = 302.351 us
{'type': 'message', 'pattern': None, 'channel': 'channel:test', 'data': '{"time": 1719310968727713361}'}
Sending message time current = 1719310968728001843, start = 1719310968727713361, cost_time = 288.482 us
{'type': 'message', 'pattern': None, 'channel': 'channel:test', 'data': '{"time": 1719310968727963764}'}
Sending message time current = 1719310968728227277, start = 1719310968727963764, cost_time = 263.513 us
{'type': 'message', 'pattern': None, 'channel': 'channel:test', 'data': '{"time": 1719310968728189318}'}
Sending message time current = 1719310968728468790, start = 1719310968728189318, cost_time = 279.472 us
{'type': 'message', 'pattern': None, 'channel': 'channel:test', 'data': '{"time": 1719310968728397832}'}
Sending message time current = 1719310968728647355, start = 1719310968728397832, cost_time = 249.523 us
{'type': 'message', 'pattern': None, 'channel': 'channel:test', 'data': '{"time": 1719310968728603366}'}
Sending message time current = 1719310968728880849, start = 1719310968728603366, cost_time = 277.483 us
{'type': 'message', 'pattern': None, 'channel': 'channel:test', 'data': '{"time": 1719310968728844040}'}
Sending message time current = 1719310968729099663, start = 1719310968728844040, cost_time = 255.623 us
{'type': 'message', 'pattern': None, 'channel': 'channel:test', 'data': '{"time": 1719310968729075423}'}
Sending message time current = 1719310968729337536, start = 1719310968729075423, cost_time = 262.113 us
{'type': 'message', 'pattern': None, 'channel': 'channel:test', 'data': '{"time": 1719310968729288847}'}
Sending message time current = 1719310968729542780, start = 1719310968729288847, cost_time = 253.933 us
{'type': 'message', 'pattern': None, 'channel': 'channel:test', 'data': '{"time": 1719310968729489132}'}
Sending message time current = 1719310968729759754, start = 1719310968729489132, cost_time = 270.622 us
{'type': 'message', 'pattern': None, 'channel': 'channel:test', 'data': '{"time": 1719310968729725845}'}
Sending message time current = 1719310968729996138, start = 1719310968729725845, cost_time = 270.293 us
{'type': 'message', 'pattern': None, 'channel': 'channel:test', 'data': '{"time": 1719310968729964509}'}
Sending message time current = 1719310968730236391, start = 1719310968729964509, cost_time = 271.882 us
{'type': 'message', 'pattern': None, 'channel': 'channel:test', 'data': '{"time": 1719310968730215552}'}
Sending message time current = 1719310968730467875, start = 1719310968730215552, cost_time = 252.323 us
{'type': 'message', 'pattern': None, 'channel': 'channel:test', 'data': '{"time": 1719310968730449685}'}
Sending message time current = 1719310968730719078, start = 1719310968730449685, cost_time = 269.393 us
{'type': 'message', 'pattern': None, 'channel': 'channel:test', 'data': '{"time": 1719310968730661889}'}
Sending message time current = 1719310968730949911, start = 1719310968730661889, cost_time = 288.022 us
{'type': 'message', 'pattern': None, 'channel': 'channel:test', 'data': '{"time": 1719310968730911643}'}
Sending message time current = 1719310968731166806, start = 1719310968730911643, cost_time = 255.163 us
{'type': 'message', 'pattern': None, 'channel': 'channel:test', 'data': '{"time": 1719310968731133936}'}
Sending message time current = 1719310968731406039, start = 1719310968731133936, cost_time = 272.103 us
{'type': 'message', 'pattern': None, 'channel': 'channel:test', 'data': '{"time": 1719310968731369580}'}
Sending message time current = 1719310968731631283, start = 1719310968731369580, cost_time = 261.703 us
{'type': 'message', 'pattern': None, 'channel': 'channel:test', 'data': '{"time": 1719310968731590744}'}
Sending message time current = 1719310968731862526, start = 1719310968731590744, cost_time = 271.782 us

[Harsh-Maheshwari]

In my experiments this latency is as high as 5 milliseconds, Not sure why though

[daoiqi]

In my experiments this latency is as high as 5 milliseconds, Not sure why though

Maybe is network latancy. Need use tcpdump capture network.

But I use localhost redis, the first package also has 400+us, second package is 100+us.