Heartbeat improvements

[gescheit]

This is the part of #162

[dzen]

Thanks for splitting your PR ! that's easiest to read ! We will take a moment this PM to read your changes and understand what you're trying to resolve with this code.

[gescheit]

Any news on this patch?

[dzen]

We discussed your PR with @RemiCardona without giving you some inputs. did you manage to get some performaces tests on what is consuming CPU or what's slow on aioamqp ? To be honest I do not have a clear sights on the multiple changes you're proposing and why :)

[gescheit]

The goal of this changes is performance optimization. If program makes expensive actions especially in function which frequently called then this program works slowly. If you look at the patch you will see that _heartbeat_timer_recv_reset() did a expensive job with rescheduling of _heartbeat_timer_recv_timeout() task. And this work was done in every data_received() call. So this is all theory, what about practise? Test program:

import asyncio
import sys
import aioamqp

END = b"end"
END_EVENT = asyncio.Event()
EXCHANGE = "test"
QUEUE_NAME = "test"

async def callback(channel, body, envelope, properties):
    if body == END:
        END_EVENT.set()

async def test():
    transport, protocol = await aioamqp.connect()
    channel = await protocol.channel()
    await channel.queue(queue_name=QUEUE_NAME, exclusive=True)
    await channel.queue_bind(exchange_name=EXCHANGE, queue_name=QUEUE_NAME, routing_key="hello")
    await channel.basic_consume(callback, queue_name=QUEUE_NAME)

    for i in range(100000):
        await channel.basic_publish(payload=b"-", exchange_name=EXCHANGE, routing_key="hello")
    await channel.basic_publish(payload=END, exchange_name=EXCHANGE, routing_key="hello")
    await END_EVENT.wait()
    await channel.close()
    await protocol.close()
    transport.close()

asyncio.get_event_loop().run_until_complete(test())

Let is run under cProfile.

         35628272 function calls (35627377 primitive calls) in 30.008 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    101/1    0.009    0.000   30.008   30.008 {built-in method builtins.exec}
...
   300014    0.538    0.000    6.759    0.000 protocol.py:379(_heartbeat_timer_send_reset)
   300061    0.447    0.000    5.362    0.000 base_events.py:446(call_later)
   300061    0.871    0.000    4.685    0.000 base_events.py:467(call_at)
...

As you can see, call_later() took 5 second out of 30. My patch changes _heartbeat_timer_send_reset() content to one call - self._heartbeat_last_send = int(time()). And this call is executed in a jiff. cProfile outputs in my branch:

         27840145 function calls (27839250 primitive calls) in 22.954 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    101/1    0.010    0.000   22.955   22.955 {built-in method builtins.exec}
...
   300014    0.290    0.000    0.356    0.000 protocol.py:195(_heartbeat_timer_send_reset)

Does this convince you?

[gescheit]

Guys?

[gescheit]

Ping.

[gescheit]

@RemiCardona ping

[dzen]

Sorry @gescheit,

I was off the past month. I'll look into it next week.

[gescheit]

I rebased changes with master.

[gescheit]

Ping.

[dzen]

hi @gescheit

I'm currently reviewing this PR. would you please squash and rebase you commits ?

[dzen]

hi @gescheit.

Your PR is greatly appreciated, it improves the performance and helps fixing the heartbeat sent to the server but I've got a few critics :

• you merged master without cleanly rebase and the replacement of the async/await is not cleanly done ;
• your commits lacks some comments to understand what you're trying to fix and why
• imho tests lacks some assertions to fully tests what we want to fix or how the code should behave.

[gescheit]

I've rebased to master. Fixing bugs is my forte, not writing a verbose commit message. Can you please help with comment?

[gescheit]

Ping.

[gescheit]

Guys?

[gescheit]

@dzen ping.

[gescheit]

2 years has passed

[RemiCardona]

Closing in favor of #234.