[rabbitmq-discuss] Only 20 req-resps per second

Thu Nov 11 11:06:12 GMT 2010

>  > Performance is very low: the client.py script needs 4 seconds to
>  > finish which means only 25 requests+responses per second.
>
> That's not what I see. With everything running on localhost I see 100
> iterations in ~240ms on my laptop. Commenting out the print statements
> and increasing to 1000 iterations (to amortise Python's startup costs) I
> get 1000 in ~1200ms - or about 1.2ms each.

Hmm, I'm still getting this 20x slower than you. Log from "strace -r":

     0.000194 sendto(3, "\1\0\1\0\0\0\r\0<\0P\0\0\0\0\0\0\0\25\0\316",
21, 0, NULL, 0) = 21
     0.000371 sendto(3, "\1\0\1\0\0\0\34\0<\0(\0\0\namq.direct
\trrexamp"..., 36, 0, NULL, 0) = 36
     0.000196 sendto(3, "\2\0\1\0\0\0000\0<\0\0\0\0\0\0\0\0\0\2\22\0\1
amq.gen-n"..., 56, 0, NULL, 0) = 56
     0.000133 sendto(3, "\3\0\1\0\0\0\00221\316", 10, 0, NULL, 0) = 10
     0.000133 recvfrom(3, "\1\0\1\0\0\0[\0<\0<!amq.ctag-
jFAKf1Ix2Wc"..., 65536, 0, NULL, NULL) = 135
     0.038957 write(1, "Got response 21XXX\n", 19) = 19
     0.000196 sendto(3, "\1\0\1\0\0\0\r\0<\0P\0\0\0\0\0\0\0\26\0\316",
21, 0, NULL, 0) = 21
     0.000339 sendto(3, "\1\0\1\0\0\0\34\0<\0(\0\0\namq.direct
\trrexamp"..., 36, 0, NULL, 0) = 36
     0.000196 sendto(3, "\2\0\1\0\0\0000\0<\0\0\0\0\0\0\0\0\0\2\22\0\1
amq.gen-n"..., 56, 0, NULL, 0) = 56
     0.000133 sendto(3, "\3\0\1\0\0\0\00222\316", 10, 0, NULL, 0) = 10
     0.000134 recvfrom(3, "\1\0\1\0\0\0[\0<\0<!amq.ctag-
jFAKf1Ix2Wc"..., 65536, 0, NULL, NULL) = 135
     0.038953 write(1, "Got response 22XXX\n", 19) = 19
     0.000184 sendto(3, "\1\0\1\0\0\0\r\0<\0P\0\0\0\0\0\0\0\27\0\316",
21, 0, NULL, 0) = 21
     0.000336 sendto(3, "\1\0\1\0\0\0\34\0<\0(\0\0\namq.direct
\trrexamp"..., 36, 0, NULL, 0) = 36
     0.000198 sendto(3, "\2\0\1\0\0\0000\0<\0\0\0\0\0\0\0\0\0\2\22\0\1
amq.gen-n"..., 56, 0, NULL, 0) = 56
     0.000105 sendto(3, "\3\0\1\0\0\0\00223\316", 10, 0, NULL, 0) = 10
     0.000108 recvfrom(3, "\1\0\1\0\0\0[\0<\0<!amq.ctag-
jFAKf1Ix2Wc"..., 65536, 0, NULL, NULL) = 135
     0.039150 write(1, "Got response 23XXX\n", 19) = 19

So between receiving from RabbitMQ and printing reponse lasts 0.04
second, but no my code is executed there.
Log from profiling client.py: http://dpaste.com/hold/273869/ - almost
all is spent in socket.recv.

I'm using Ubuntu 10.10 64bit, I tried Python 2.6 and Python 2.7,
RabbitMQ 1.8.0 from distribution and 2.1.1 downloaded from
rabbitmq.org, EXT4 and XFS filesystem for Mnesia database.

How to debug it further?

> Pipelining would let things go faster still, but I understand why you'd not want that.

I'm simulating situation when web application makes one blocking RPC
call (using RabbitMQ) per request.

> That's a good question. What is the latency between client.py / Rabbit /
> server.py? But it can't all be latency, even your pipelined case seems
> very slow.

Everything is running on 127.0.0.1.

Regards,
Artur