Performance problems

[umax]

Hi!

I want to get know NATS + asyncio-nats-client RPS (request-response case). The test scenario is simple:
server.py

import asyncio

import uvloop

from nats.aio.client import Client


async def main(loop):
    client = Client()
    await client.connect(io_loop=loop)
    print('connected')

    async def handler(msg):
        await client.publish(msg.reply, b'pong')

    await client.subscribe('test', queue='workers', cb=handler)
    print('subscribed')


if __name__ == '__main__':
    loop = uvloop.new_event_loop()
    asyncio.set_event_loop(loop)

    loop.run_until_complete(main(loop))
    print('start listening')
    loop.run_forever()
    loop.close()

client.py

import asyncio
import sys

import uvloop
from nats.aio.client import Client


async def main(loop):
    futures = [
        asyncio.ensure_future(client.timed_request('test', b'ping', 1))
        for i in range(int(sys.argv[1]))
    ]

    await asyncio.wait_for(asyncio.gather(*futures), 1.0)


if __name__ == '__main__':
    loop = uvloop.new_event_loop()
    asyncio.set_event_loop(loop)

    client = Client()
    loop.run_until_complete(client.connect(io_loop=loop))
    print('connected')

    loop.run_until_complete(main(loop))

How to run:

$ gnatsd
$ python3.6 server.py
$ python3.6 client.py 1000

I cant' get more than 1000 requests/responses in 1 second on my MacBook Pro (2.3 GHz Intel Core i5). Maybe I do something wrong or it's library limitations?

Thanks

[wallyqs]

You can take a look at the latency_perf that is in the repo to confirm the request/response roundtrip performance from the client: https://github.com/nats-io/asyncio-nats/blob/master/benchmark/latency_perf.py

You are right that there is room for improvements in the current roundtrip time, for example locally I'm getting the following:

python3 benchmark/latency_perf.py 
Sending 10000 request/responses on [test]
#########
Test completed : 1.628 ms avg request/response latency

$ nats-top
...
  In:   Msgs: 188.3K  Bytes: 308.2K  Msgs/Sec: 1356.1  Bytes/Sec: 0   
  Out:  Msgs: 188.3K  Bytes: 308.2K  Msgs/Sec: 1356.1  Bytes/Sec: 0  

While a similar test but for the Ruby library, the numbers are a bit higher:

ruby benchmark/latency_perf.rb 
Sending 10000 request/responses
Test completed : 0.35 ms avg request/response latency

$ nats-top
...
  In:   Msgs: 131.4K  Bytes: 308.2K  Msgs/Sec: 6232.8  Bytes/Sec: 0   
  Out:  Msgs: 131.4K  Bytes: 308.2K  Msgs/Sec: 6232.8  Bytes/Sec: 0 

I have some pending updates to do around the request/response handling from the library to follow the new style of request/response done like in the Go library, so will take a look at revising performance again soon.

[Gr1N]

@wallyqs nice to hear that you are working on performance improvements. In our company we are interesting in nats and python client.

Maybe you can share any estimates you have with us? Thanks!

[wallyqs]

Right now I'm planning a couple of releases, one minor release at the end of this month v0.6.6 and then a major version bump v0.7.0 middle of next month which would include updates in the request/response handling.

[Gr1N]

Nice! Can't wait for updates!

[umax]

@wallyqs does this diff may have a chance?

+++ b/nats/aio/utils.py
@@ -9,7 +9,7 @@ def hex_rand(n):
     """
     Generates a hexadecimal string with `n` random bits.
     """
-    return "%x" % random.SystemRandom().getrandbits(n)
+    return "%x" % random.getrandbits(n)

Before this diff:

python benchmark/latency_perf.py
Sending 10000 request/responses on [test]
#########
Test completed : 1.405 ms avg request/response latency

After this diff:

python benchmark/latency_perf.py
Sending 10000 request/responses on [test]
#########
Test completed : 0.430 ms avg request/response latency

Br,
Max

[umax]

Also, it make sense to use __slots__ for Msg, Subscription and other classes for memory save and faster access.

[Gr1N]

About random, better to use SystemRandom, but move part of code to the top of module:

diff --git a/nats/aio/utils.py b/nats/aio/utils.py
index b289971..7aed392 100644
--- a/nats/aio/utils.py
+++ b/nats/aio/utils.py
@@ -2,6 +2,16 @@
 
 import random
 
+
+# Use the system PRNG if possible
+try:
+    random = random.SystemRandom()
+except NotImplementedError:
+    import warnings
+    warnings.warn('A secure pseudo-random number generator is not available '
+                  'on your system. Falling back to Mersenne Twister.')
+
+
 INBOX_PREFIX = "_INBOX."
 
 
@@ -9,7 +19,7 @@ def hex_rand(n):
     """
     Generates a hexadecimal string with `n` random bits.
     """
-    return "%x" % random.SystemRandom().getrandbits(n)
+    return "%x" % random.getrandbits(n)
 
 
 def new_inbox():

[Gr1N]

@wallyqs, PR with improvement: #55

[wallyqs]

Thanks for the tips, the SystemRandom change improves the latency test quite a bit. Sounds good on using __slots__ for Msg class as well, seems like would be more efficient... http://book.pythontips.com/en/latest/__slots__magic.html

[rudyryk]

We can also use os.urandom() here, as it produces "real" random numbers. Here's benchmarking results:

random.SystemRandom() x 10000 times:
2.0309601490153s

random.getrandbits() x 10000 times:
0.008057761995587498s

os.urandom() x 10000 times:
0.04249835800146684s

Code for benchmarks:

import timeit

if __name__ == '__main__':
    print('random.SystemRandom() x 10000 times:\n%ss' % timeit.timeit(
        stmt='"%x" % random.SystemRandom().getrandbits(256)',
        setup='import random',
        number=10000,
    ))

    print('random.getrandbits() x 10000 times:\n%ss' % timeit.timeit(
        stmt='"%x" % random.getrandbits(256)',
        setup='import random',
        number=10000,
    ))

    print('os.urandom() x 10000 times:\n%ss' % timeit.timeit(
        stmt='binascii.hexlify(os.urandom(32)).decode()',
        setup='import os, binascii',
        number=10000,
    ))

[rudyryk]

Ah, OK - with pre-created SystemRandom() generator it runs at almost the same speed:

random.SystemRandom() x 100000 times:
0.5566856279619969s

random.getrandbits() x 100000 times:
0.09096840699203312s

os.urandom() x 100000 times:
0.48127816000487655s

Updated code:

    print('random.SystemRandom() x 100000 times:\n%ss' % timeit.timeit(
        stmt='"%x" % sysrandom.getrandbits(256)',
        setup='import random; sysrandom = random.SystemRandom()',
        number=100000,
    ))

[wallyqs]

Thanks everyone for the feedback in this issue. In the next release v0.7.0 the inbox generation will be around twice as fast (although think implementation at https://github.com/nats-io/asyncio-nats/blob/master/nats/aio/nuid.py could be further optimized).

    print('NUID based inboxes x 100,000 times:\n%ss' % timeit.timeit(
        stmt='inbox = INBOX_PREFIX[:]; inbox.extend(nuid.next())',
        setup='from nats.aio.nuid import NUID; INBOX_PREFIX = bytearray(b"_INBOX."); nuid = NUID();',
        number=100000,
    ))

    print('Old style inboxes x 100,000 times:\n%ss' % timeit.timeit(
        stmt='new_inbox()',
        setup='from nats.aio.utils import new_inbox',
        number=100000,
    ))

Results:

NUID based inboxes x 100,000 times:
0.738977312023053s
Old style inboxes x 100,000 times:
1.3899898040108383s
```

Also with the internal changes to the request/response implementation (https://github.com/nats-io/asyncio-nats/pull/59) and using uvloop getting much results in the latency test:

```
# Before:

$ python3.6 benchmark/latency_perf.py 
Sending 10000 request/responses on [test]
#######################################
Test completed : 0.340 ms avg request/response latency

# After:

$ python3.6 benchmark/latency_perf.py 
Sending 10000 request/responses on [test]
#######################################
Test completed : 0.284 ms avg request/response latency
```