RabbitMQ accepting AMQP connection is slow, more than 8seconds

[Alvin Zhang]

I am using rabbitmq-server-3.6.6 with Erlang R16B03-1 in CentOS 7. After installing the rabbitmq, and I am trying to use pika to build an rpc server. However, the pika.BlockingConnection() part to connec to 127.0.0.1 is so slow, which more than 8 seconds, which usually should be around 1~5ms. 

Here are a list of my rabbitmq-env.conf settings, and pika connection codes:

1. /etc/rabbitmq/rabbitmq-env.conf:
   NODENAME=rabbit@localhost
   ulimit -S -n 4096

2. def loop_rpc_1():
   import pika, time, uuid
   host = '127.0.0.1'
   port = 5672
   user = 'rpc_user'
   passwd = '123456'
   vhost = '/dev'
   credentials = pika.PlainCredentials(user, passwd)
   list = range(1, 100)
   for i in list:
   start_time = time.time()
   conn = pika.BlockingConnection(pika.ConnectionParameters(host, port, vhost, credentials, ))
   conn.close()
   print(i, time.time() - start_time)

The output:

loop_rpc_1()
1 7.42911958694458
2 5.011636972427368
3 0.008404970169067383
4 0.00924539566040039
5 8.006478071212769
6 2.010906934738159
7 0.008637666702270508
8 0.008483409881591797
9 5.0115368366241455
10 0.00960850715637207
11 0.008922576904296875
12 5.015120506286621
13 8.005479335784912
14 2.011262893676758
15 8.005752325057983
16 2.0079636573791504
17 8.006184816360474
18 2.0097343921661377
19 0.008991718292236328
20 8.00625205039978

The /var/log/rabbitmq/rabb...@localhost.log is like:

=INFO REPORT==== 17-Aug-2017::20:17:12 ===
accepting AMQP connection <0.5344.4> (127.0.0.1:44705 -> 127.0.0.1:5672)

=INFO REPORT==== 17-Aug-2017::20:17:14 ===
closing AMQP connection <0.5344.4> (127.0.0.1:44705 -> 127.0.0.1:5672)

=INFO REPORT==== 17-Aug-2017::20:17:14 ===
accepting AMQP connection <0.5371.4> (127.0.0.1:44706 -> 127.0.0.1:5672)

=INFO REPORT==== 17-Aug-2017::20:17:19 ===
closing AMQP connection <0.5371.4> (127.0.0.1:44706 -> 127.0.0.1:5672)

=INFO REPORT==== 17-Aug-2017::20:17:19 ===
accepting AMQP connection <0.5427.4> (127.0.0.1:44707 -> 127.0.0.1:5672)

=INFO REPORT==== 17-Aug-2017::20:17:19 ===
closing AMQP connection <0.5427.4> (127.0.0.1:44707 -> 127.0.0.1:5672)

=INFO REPORT==== 17-Aug-2017::20:17:19 ===
accepting AMQP connection <0.5434.4> (127.0.0.1:44708 -> 127.0.0.1:5672)

=INFO REPORT==== 17-Aug-2017::20:17:19 ===
closing AMQP connection <0.5434.4> (127.0.0.1:44708 -> 127.0.0.1:5672)

=INFO REPORT==== 17-Aug-2017::20:17:19 ===
accepting AMQP connection <0.5441.4> (127.0.0.1:44709 -> 127.0.0.1:5672)

=INFO REPORT==== 17-Aug-2017::20:17:27 ===
closing AMQP connection <0.5441.4> (127.0.0.1:44709 -> 127.0.0.1:5672)

=INFO REPORT==== 17-Aug-2017::20:17:27 ===
accepting AMQP connection <0.5515.4> (127.0.0.1:44710 -> 127.0.0.1:5672)

=INFO REPORT==== 17-Aug-2017::20:17:29 ===
closing AMQP connection <0.5515.4> (127.0.0.1:44710 -> 127.0.0.1:5672)

3. Besides, commands like "time rabbitmqctl list_users", "service rabbitmq-server start/stop/status" are also pretty slow.

What is a standard procedure for debugging this sort of issues ?
Thanks a lot!

[Luke Bakken]

Hi Alvin,

Is your CentOS server running in a virtual machine? Can you provide details about your environment?

Luke

[Alvin Zhang]

Hi Luke,

Thanks for the note. Here is the OS type running on an physical server (Dell R420 16G, 8core*2)

[root@alpha ~]#  cat /proc/version

Linux version 3.10.0-514.26.2.el7.x86_64 (bui...@kbuilder.dev.centos.org) (gcc version 4.8.5 20150623 (Red Hat 4.8.5-11) (GCC) ) #1 SMP Tue Jul 4 15:04:05 UTC 2017

[root@alpha ~]#  rpm -qa |grep glibc

glibc-2.17-157.el7_3.5.x86_64

glibc-headers-2.17-157.el7_3.5.x86_64

glibc-common-2.17-157.el7_3.5.x86_64

glibc-devel-2.17-157.el7_3.5.x86_64

[root@alpha ~]# erl

Erlang R16B03-1 (erts-5.10.4) [source] [64-bit] [smp:16:16] [async-threads:10] [hipe] [kernel-poll:false]

Eshell V5.10.4  (abort with ^G)

[root@alpha ~]# rpm -qa | grep rabbitmq

rabbitmq-server-3.6.6-1.el7.noarch

[root@alpha ~]# route

Kernel IP routing table

Destination     Gateway         Genmask         Flags Metric Ref    Use Iface

default             gateway         0.0.0.0         UG    100    0        0 em1

192.*.0.0          0.0.0.0         255.255.255.0   U     100    0        0 em2

**.**.**.**          0.0.0.0         255.255.255.128 U     100    0        0 em1

I search a lot of related info on the web, and find a similar case: https://groups.google.com/forum/#!topic/rabbitmq-users/4GPsBQDOIe4, just have no idea how they fix it.

Best,

Alvin

--

You received this message because you are subscribed to a topic in the Google Groups "rabbitmq-users" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/rabbitmq-users/jbNJG9OevtY/unsubscribe.
To unsubscribe from this group and all its topics, send an email to rabbitmq-users+unsubscribe@googlegroups.com.
To post to this group, send email to rabbitmq-users@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Luke Bakken]

Hi Alvin,

I ran your Python code on my CentOS 7 virtual machine, using RabbitMQ 3.6.11 and Erlang 19.3. The test program works fine and every connection is established and closed in less than 0.01 seconds.

In the information you provided, your routing table looks very strange, especially the last entry. I'm not sure how **.**.**.** would affect connections to 127.0.0.1, but it might.

I recommend resetting your routing table to a "bare minimum" configuration. For instance, here is the output of ip route on my VM (ip address 10.0.2.15):

$ ip route

default via 10.0.2.2 dev eth0  proto static  metric 100

10.0.2.0/24 dev eth0  proto kernel  scope link  src 10.0.2.15  metric 100

Thanks,

Luke

[Alvin Zhang]

Thanks Luke. I will take a look, and here is my routing table which shows:

[root@alpha ~]# ip route

default via 222.**.**.** dev em1  proto static  metric 100 

192.168.0.0/24 dev em2  proto kernel  scope link  src 192.168.0.11  metric 100 

222.**.**.**/25 dev em1  proto kernel  scope link  src 222.**.**.**  metric 100 

yeah, it is kind of wired... will get you back soon.

Best,

Alvin

--

[Michael Klishin]

Are you on VPN by any chance?

VPN modifies hostname resolution. Please make sure there is an entry for localhost to /etc/hosts.

To unsubscribe from this group and all its topics, send an email to rabbitmq-user...@googlegroups.com.

To post to this group, send email to rabbitm...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To post to this group, send email to rabbitm...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

Staff Software Engineer, Pivotal/RabbitMQ

[Alvin Zhang]

Hi Mike,

Thanks for the remind. Here is the cat /etc/hosts:

[root@beta ~]# cat /etc/hosts

127.0.0.1   localhost localhost.localdomain localhost4 localhost4.localdomain4

::1         localhost localhost.localdomain localhost6 localhost6.localdomain6

The network administrator is trying to fix the route table, and will see if things can work out. 

Best,

Alvin

[Michael Klishin]

There can be a whole bunch of reasons for TCP connection initiation to be slower than usual,

some are mentioned in http://www.rabbitmq.com/networking.html. However, if it takes several seconds

for localhost it almost always comes down to one hostname resolution method (DNS) being used for "localhost",

then it times out, then another (e.g. /etc/hosts) is used.

Here's one archive thread where it didn't seem like a hostname resolution timeout at first but was ultimately traced down to that:

https://groups.google.com/d/msg/rabbitmq-users/Lr2JGmSXNNk/FuCUMKX3j1cJ. It even uses the same client library (Pika?)

and claims that connection time is about the same (~ 8 seconds).

You can try using an IP address to compare, for example. If it's no different with IP addresses, I'd use tcpdump and Wireshark to

see relative timestamps of more networking-related events.

To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-users+unsubscribe@googlegroups.com.
To post to this group, send email to rabbitmq-users@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

MK

Staff Software Engineer, Pivotal/RabbitMQ

[Alvin Zhang]

Hi Mike,

Thanks for your insight as always. We finally figure out after disable selinux, and reboot the OS, the connection speed turns out to be in 5~10ms.  Here is the trick；

$ cat /etc/selinux/config  

# This file controls the state of SELinux on the system.

# SELINUX= can take one of these three values:

#     enforcing - SELinux security policy is enforced.

#     permissive - SELinux prints warnings instead of enforcing.

#     disabled - No SELinux policy is loaded.

SELINUX=disabled

# SELINUXTYPE= can take one of three two values:

#     targeted - Targeted processes are protected,

#     minimum - Modification of targeted policy. Only selected processes are protected. 

#     mls - Multi Level Security protection.

SELINUXTYPE=targeted 

$ sudo reboot

$ time rabbitmqctl list_users

real 0m1.390s

user 0m1.206s

sys 0m0.394s

Best,

Alvin

To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.

To post to this group, send email to rabbitm...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

[Luke Bakken]

Hi Alvin,

Just for your information, the CentOS VM I used had the default SELinux policy enabled and active when I ran my tests. While disabling it fixed your specific issue, I don't think it should be considered a general solution, in case someone reads this thread in the future.

Here is the output of sestatus -

Last login: Thu Aug 17 15:30:58 2017 from 10.0.2.2

[vagrant@localhost ~]$ sestatus

SELinux status:                 enabled

SELinuxfs mount:                /sys/fs/selinux

SELinux root directory:         /etc/selinux

Loaded policy name:             targeted

Current mode:                   enforcing

Mode from config file:          enforcing

Policy MLS status:              enabled

Policy deny_unknown status:     allowed

Max kernel policy version:      28

On Friday, August 18, 2017 at 5:46:27 AM UTC-7, Alvin wrote:

Hi Mike,

[Alvin]

Thanks for the note, Luke. Yeah it could be my specific solution.

Have a good one,

Alvin