[rabbitmq-discuss] RabbitMQ perfomance testing & troubles

Wed Apr 16 12:45:53 BST 2008

В Срд, 09/04/2008 в 22:50 +0100, Matthias Radestock пишет:

Hello Matthias !

Fisrt off all many thank for help, second I am very sorry about my bad
written english.

We are continue testing RabbitMQ with Alexey Slynko and here the some
results.

> > Erlang version (stable debian distribution) :
> > 
> > # dpkg -l erlang\* | grep ii
> > ii  erlang-base      11.b.2-4       Concurrent, real-time, distributed
> > functiona
> > ii  erlang-nox       11.b.2-4       Concurrent, real-time, distributed
> > functiona
> 
> Any chance you could try the tests with R11B-5? Most of our testing has 
> been done on that. I doubt it will make much difference but at the very 
> least it will make it easier for us to compare results.

Chance is 100% . Just sey that we are have to rebuild. Current,
backported from Etch, Erlang is:

# dpkg -l erlang\* | grep ii
ii  erlang-base       11.b.5dfsg-12  Concurrent, real-time, distributed
functiona
ii  erlang-nox        11.b.5dfsg-12  Concurrent, real-time, distributed
functiona

as you say.

> > Another midfications were done for normal mnesia work (errors listed below)
> > 
> > ERROR REPORT==== 4-Apr-2008::18:29:14 ===
> > Error in process <0.20713.0> on node 'rabbit at altair' with exit value:
> > {{case_clause,{error,{system_limit,"Cannot create an ets table for
> > the local transaction
> > store",{system_limit,[{ets,new,[mnesia_trans_store,[bag,public]]},{mnesia_tm,doit_loop,1},{mnesia_sp,init_proc,4},{ 
> > 
> > proc_lib...
> 
> We have never seen this before. At what point during your tests did you 
> get this error?

Test starts, after 7-15 min Erlang eat a lot off memory and give the
errors, 
sometime crash.

> These should all be fine except I have some concerns about the "-smp 
> auto", given how old a version of Erlang/OTP are running. Did you test 
> that adding the flag indeed improves performance?

Yes. Then I use -smp flag the Erlang/OTP eating all 8 CPU core, without
- 1.

> 
> Note that RabbitMQ when running with Erlang/OTP R11B (rather than the 
> more recent R12) will not benefit much (if at all) from the multiple 
> cores when running with -smp. In our experiments we have been getting 
> much better results when configuring a local cluster of one non-smp node 
> per code. So I'd recommend you do that.

I am newbe man in Erlang/OTP system and correctly configuring a local
cluster 
is not easy for me. With SMP mode beam.smp can utilize up to 790% off
this server.

> The following will all impact performance:
> 
> - The queues are not auto-deleting and aren't being deleted explicitly, 
> and your queue/exchange naming scheme is deterministic. Unless you 
> restart the server between tests or subsequent tests will be affected by 
> the queues from earlier tests. I'd also recommend clearing the mnesia 
> dir prior to starting rabbit, just to make sure that there aren't any 
> stray exchanges, queues or persistent messages.

Well,

# invoke-rc.d rabbitmq-server stop
Stopping rabbitmq-server: rabbitmq-server.
# rm -f /var/lib/rabbitmq/mnesia/rabbit/*
# invoke-rc.d rabbitmq-server start
Starting rabbitmq-server: SUCCESS
rabbitmq-server.

> 
> - The consumer explicitly acknowledges each message. Would 
> bulk-acknowledgment or auto-acknowledgment be an option?

OK, I was delete the acknowledges each message code

- // channel.basicAck(envelope.getDeliveryTag(), false);

start the test

$ java -jar RabbitmqFastMessagingProducerTest.jar 1000 > client.log

after ~ 5 min the server side looks

top - 15:10:19 up 11 days, 21:39,  2 users,  load average: 5.93, 2.69,
1.09
Tasks: 115 total,   1 running, 114 sleeping,   0 stopped,   0 zombie
Cpu(s): 58.2%us, 18.9%sy,  0.0%ni, 21.4%id,  0.0%wa,  0.4%hi,  1.1%si,
0.0%st
Mem:   4139508k total,  2233588k used,  1905920k free,   286108k buffers
Swap:  4194296k total,        0k used,  4194296k free,   826336k cached

PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
16082 rabbitmq  25   0 1133m 900m 1696 S  615 22.3  16:55.04 beam.smp
23983 rabbitmq  15   0  1828  388  256 S    0  0.0   0:00.00 epmd
16078 rabbitmq  20   0  4172 1548 1080 S    0  0.0   0:00.00
rabbitmq-server
16404 rabbitmq  17   0  1824  472  368 S    0  0.0   0:00.00
inet_gethost
16405 rabbitmq  18   0  1868  592  472 S    0  0.0   0:00.00
inet_gethost       

and the client side

$ tail -f client.log | awk '/CLIENT_CONSUMER_THREAD_ID/{print "DELAY: "
$4-$8 " " $0}'

DELAY: 188894 CLIENT_CONSUMER_THREAD_ID: 2 TIME: 1208344442697 MESSAGE:
23 TIME: 1208344253803
DELAY: 187904 CLIENT_CONSUMER_THREAD_ID: 951 TIME: 1208344442697
MESSAGE: 22 TIME: 1208344254793
DELAY: 187807 CLIENT_CONSUMER_THREAD_ID: 871 TIME: 1208344442698
MESSAGE: 22 TIME: 1208344254891
DELAY: 188168 CLIENT_CONSUMER_THREAD_ID: 706 TIME: 1208344442698
MESSAGE: 22 TIME: 1208344254530
DELAY: 188267 CLIENT_CONSUMER_THREAD_ID: 630 TIME: 1208344442698
MESSAGE: 22 TIME: 1208344254431
DELAY: 189608 CLIENT_CONSUMER_THREAD_ID: 626 TIME: 1208344442698
MESSAGE: 23 TIME: 1208344253090
DELAY: 188127 CLIENT_CONSUMER_THREAD_ID: 113 TIME: 1208344442698
MESSAGE: 22 TIME: 1208344254571
DELAY: 188596 CLIENT_CONSUMER_THREAD_ID: 519 TIME: 1208344442698
MESSAGE: 22 TIME: 1208344254102

The delay is about 3 min. I can't understand why.

> You may also want to run one of the test programs supplied with the 
> RabbitMQ Java client packages, such as MulticastMain, e.g.
>    sh ./runjava.sh com.rabbitmq.examples.MulticastMain -h <host> -a
> which reports on throughput and latency.

Well, the I start signle producer/consumer thread all looks good:

$ sh ./runjava.sh com.rabbitmq.examples.MulticastMain -h host.domain.tld
-a
starting consumer #0
starting producer #0
recving rate: 7780 msg/s, min/avg/max latency: 4083/109443/165431
microseconds
sending rate: 10679 msg/s
recving rate: 9734 msg/s, min/avg/max latency: 109790/135292/163872
microseconds
sending rate: 9821 msg/s
recving rate: 9873 msg/s, min/avg/max latency: 109995/134968/160787
microseconds
sending rate: 9848 msg/s
recving rate: 9969 msg/s, min/avg/max latency: 107159/132702/158851
microseconds
sending rate: 10083 msg/s
recving rate: 9868 msg/s, min/avg/max latency: 108387/134192/160497
microseconds

But, then I start 100 producer/consumer threads latency going to be
high 0.3->20 sec:

$ sh ./runjava.sh com.rabbitmq.examples.MulticastMain
-h host.domain.tld -a -x 100 -y 100 | grep recving
recving rate: 0 msg/s, min/avg/max latency: 11195/11195/11195
microseconds
recving rate: 33217 msg/s, min/avg/max latency: 10113/345828/996901
microseconds
recving rate: 27192 msg/s, min/avg/max latency: 58042/1010474/1997839
microseconds
recving rate: 33569 msg/s, min/avg/max latency: 65700/1562317/2997350
microseconds
recving rate: 24304 msg/s, min/avg/max latency: 90050/2142151/3991946
microseconds
recving rate: 37388 msg/s, min/avg/max latency: 111498/2970700/4996836
microseconds
recving rate: 28715 msg/s, min/avg/max latency: 118559/3476202/5998178
microseconds
recving rate: 28453 msg/s, min/avg/max latency: 144319/4098792/6999516
microseconds
recving rate: 27348 msg/s, min/avg/max latency: 157363/4722565/7998155
microseconds
recving rate: 27508 msg/s, min/avg/max latency: 182090/5381463/9003343
microseconds
recving rate: 27007 msg/s, min/avg/max latency: 192525/6034385/9982716
microseconds
recving rate: 26638 msg/s, min/avg/max latency: 207776/6694654/10998061
microseconds
recving rate: 27001 msg/s, min/avg/max latency: 211793/7335019/12002072
microseconds
recving rate: 26616 msg/s, min/avg/max latency: 244324/7996319/13001783
microseconds
recving rate: 26056 msg/s, min/avg/max latency: 231526/8642121/13997488
microseconds
recving rate: 26521 msg/s, min/avg/max latency: 252036/9327910/15016590
microseconds
recving rate: 26018 msg/s, min/avg/max latency: 262150/10006353/16007951
microseconds
recving rate: 26431 msg/s, min/avg/max latency: 264835/10697607/17017128
microseconds
recving rate: 26018 msg/s, min/avg/max latency: 342075/11366371/18016090
microseconds
recving rate: 25545 msg/s, min/avg/max latency: 273541/11965135/18987288
microseconds
recving rate: 25902 msg/s, min/avg/max latency: 280084/12749721/20008257
microseconds
recving rate: 25449 msg/s, min/avg/max latency: 304305/13347575/21019395
microseconds
recving rate: 25473 msg/s, min/avg/max latency: 309149/13985349/22019055
microseconds
recving rate: 25658 msg/s, min/avg/max latency: 302950/14691935/23020086
microseconds
recving rate: 25564 msg/s, min/avg/max latency: 403575/15483426/24021188
microseconds
recving rate: 25639 msg/s, min/avg/max latency: 323600/15878397/25021019
microseconds
recving rate: 25553 msg/s, min/avg/max latency: 321453/16720349/25974209
microseconds
recving rate: 25747 msg/s, min/avg/max latency: 343184/17436193/27023608
microseconds
recving rate: 24954 msg/s, min/avg/max latency: 386340/17945129/28010304
microseconds
recving rate: 24919 msg/s, min/avg/max latency: 377575/18603424/29026385
microseconds
recving rate: 25226 msg/s, min/avg/max latency: 349285/19401619/30013216
microseconds
recving rate: 25074 msg/s, min/avg/max latency: 491382/20007042/31005415
microseconds
recving rate: 25906 msg/s, min/avg/max latency: 374276/20710481/32014250
microseconds
recving rate: 25153 msg/s, min/avg/max latency: 363636/21417328/33015581
microseconds

Here the result then I run this test in AQMP server host (localhost):

$ sh ./runjava.sh com.rabbitmq.examples.MulticastMain -h localhost -a -x
100 -y 100 | grep recving
recving rate: 0 msg/s, min/avg/max latency: 15532/15532/15532
microseconds
recving rate: 10911 msg/s, min/avg/max latency: 15538/358765/953624
microseconds
recving rate: 19022 msg/s, min/avg/max latency: 86565/907865/2021696
microseconds
recving rate: 18619 msg/s, min/avg/max latency: 116191/1471139/3014532
microseconds
recving rate: 21881 msg/s, min/avg/max latency: 112003/2051780/4021113
microseconds
recving rate: 19014 msg/s, min/avg/max latency: 139058/2687275/4929168
microseconds
recving rate: 18237 msg/s, min/avg/max latency: 184713/3311977/5929642
microseconds
recving rate: 18837 msg/s, min/avg/max latency: 213375/4023915/6917634
microseconds
recving rate: 21111 msg/s, min/avg/max latency: 177935/4640096/7928183
microseconds
recving rate: 16905 msg/s, min/avg/max latency: 167707/5139316/8939816
microseconds
recving rate: 16678 msg/s, min/avg/max latency: 209396/5903245/9921387
microseconds
recving rate: 19055 msg/s, min/avg/max latency: 241024/6477019/10940078
microseconds
recving rate: 17407 msg/s, min/avg/max latency: 309125/7134191/11945223
microseconds
recving rate: 18369 msg/s, min/avg/max latency: 232026/7839258/12949816
microseconds
recving rate: 18599 msg/s, min/avg/max latency: 246842/8434456/13956746
microseconds
recving rate: 18142 msg/s, min/avg/max latency: 261445/9040292/14955231
microseconds
recving rate: 19064 msg/s, min/avg/max latency: 253654/9718233/15976520
microseconds
recving rate: 19028 msg/s, min/avg/max latency: 274436/10391275/16977331
microseconds
recving rate: 17648 msg/s, min/avg/max latency: 339277/11079915/17959945
microseconds
recving rate: 18170 msg/s, min/avg/max latency: 662897/11848865/18972830
microseconds
recving rate: 19169 msg/s, min/avg/max latency: 307943/12328233/19945237
microseconds
recving rate: 17994 msg/s, min/avg/max latency: 342600/13105338/20889999
microseconds
recving rate: 18205 msg/s, min/avg/max latency: 359897/13805425/21926401
microseconds
recving rate: 18324 msg/s, min/avg/max latency: 439293/14389845/22942993
microseconds
recving rate: 16720 msg/s, min/avg/max latency: 409930/15036274/23980343
microseconds
recving rate: 18435 msg/s, min/avg/max latency: 928834/15825577/24938658
microseconds
recving rate: 19078 msg/s, min/avg/max latency: 401601/16257366/25940399
microseconds
recving rate: 17531 msg/s, min/avg/max latency: 445536/17090242/26952144
microseconds
recving rate: 18717 msg/s, min/avg/max latency: 842400/17750288/27990323
microseconds
recving rate: 19389 msg/s, min/avg/max latency: 374073/18312400/28965579
microseconds

It looks strange... like the "reciever" in rabbitmq working match
faster, then "processor" & "sender". Is this result correct ?

WBR,
Alter