help needed with VERY slow RabbitMQ

[Кирилл Марчук]

Hi all

I am trying to troubleshoot a mysterious RabbitMQ behaviour on a CentOS 7.2 system. The main issue is that Logstash does not connect (with TimeoutException) however this my message is about something different: namely, that all RabbitMQ interaction is painfully slow!

Any command I can think of, takes 30+ seconds to complete, like:

> time rabbitmqctl list_users
Listing users ...
admin   [administrator]
guest   [administrator]

real    0m32.765s
user    0m0.479s
sys     0m0.134s

On the other machine it takes less than one second!

"systemctl start/stop rabbitmq-server" also takes a LOT to complete, see in the broker log file, for example:

=INFO REPORT==== 27-Dec-2016::12:51:05 ===
Starting RabbitMQ 3.6.5 on Erlang R16B03-1
Copyright (C) 2007-2016 Pivotal Software, Inc.
Licensed under the MPL.  See http://www.rabbitmq.com/

=INFO REPORT==== 27-Dec-2016::12:51:05 ===
node           : rabbit@client170
home dir       : /var/lib/rabbitmq
config file(s) : /etc/rabbitmq/rabbitmq.config
cookie hash    : 77AaFkYld+gM4p59VDe7mA==
log            : /var/log/rabbitmq/rab...@client170.log
sasl log       : /var/log/rabbitmq/rab...@client170-sasl.log
database dir   : /var/lib/rabbitmq/mnesia/rabbit@client170

=INFO REPORT==== 27-Dec-2016::12:51:07 ===
Memory limit set to 1465MB of 3662MB total.

=INFO REPORT==== 27-Dec-2016::12:51:07 ===
Disk free limit set to 50MB

=INFO REPORT==== 27-Dec-2016::12:51:07 ===
Limiting to approx 924 file handles (829 sockets)

=INFO REPORT==== 27-Dec-2016::12:51:07 ===
FHC read buffering:  OFF
FHC write buffering: ON

=INFO REPORT==== 27-Dec-2016::12:51:07 ===
Priority queues enabled, real BQ is rabbit_variable_queue

=INFO REPORT==== 27-Dec-2016::12:51:15 ===
Management plugin: using rates mode 'basic'

=INFO REPORT==== 27-Dec-2016::12:51:15 ===
msg_store_transient: using rabbit_msg_store_ets_index to provide index

=INFO REPORT==== 27-Dec-2016::12:51:15 ===
msg_store_persistent: using rabbit_msg_store_ets_index to provide index

=INFO REPORT==== 27-Dec-2016::12:51:31 ===
started TCP Listener on [::]:5672

=INFO REPORT==== 27-Dec-2016::12:51:32 ===
accepting AMQP connection <0.306.0> (127.0.0.1:34586 -> 127.0.0.1:5672)

=INFO REPORT==== 27-Dec-2016::12:51:39 ===
Management plugin started. Port: 15672

=INFO REPORT==== 27-Dec-2016::12:51:39 ===
Statistics event collector started.

=INFO REPORT==== 27-Dec-2016::12:51:39 ===
Statistics channel stats collector started.

=INFO REPORT==== 27-Dec-2016::12:51:39 ===
Statistics queue stats collector started.

=INFO REPORT==== 27-Dec-2016::12:51:39 ===
Statistics database started.

=INFO REPORT==== 27-Dec-2016::12:51:39 ===
Statistics garbage collector started for table aggr_queue_stats_fine_stats with interval 5000.

=INFO REPORT==== 27-Dec-2016::12:51:39 ===
Server startup complete; 6 plugins started.
 * rabbitmq_management
 * rabbitmq_web_dispatch
 * webmachine
 * mochiweb
 * rabbitmq_management_agent
 * amqp_client

In an attempt to troubleshoot this, it's what I have put into /etc/rabbitmq/rabbitmq.config:

[
  {rabbit,
    [
      {log_levels, [{connection, debug}, {channel, debug}]},
      {mnesia_table_loading_timeout, 10000}
    ]
  }
].

My guess was that 30 seconds delay on almost every operation looks suspiciously similar to default 30 seconds mnesia_table_loading_timeout, but alas, setting this to 10000 did not change anything

Also, I am not sure that this config is even parsed ! Because it feels as if basically nothing changes neither in the logs, nor in a behavior, when I add something to this file. And I could not find a way to check if thic config is actually processed ! (besides a line in a broker log file, that tells a path to config file)

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

Thanks, community !

[Michael Klishin]

Listing a large number of connections is a very expensive linear operation since each of the connection processes has to be involved.

In 3.7.0 this happens in parallel on all cluster nodes and results are streamed back.

If clients fail to connect  see how your nodes are doing on the open vs. used file handle front. Lastly it can be a backed up stats DB, so try resetting it.

--
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.

[Кирилл Марчук]

This RabbitMQ is listening to almost no one, it serves only localhost-based clients, and it seems as though no one of them cannot even establish connection !

this is what I also have in logs:

=INFO REPORT==== 27-Dec-2016::13:41:17 ===
accepting AMQP connection <0.25073.0> (127.0.0.1:35034 -> 127.0.0.1:5672)

=WARNING REPORT==== 27-Dec-2016::13:41:25 ===
closing AMQP connection <0.25073.0> (127.0.0.1:35034 -> 127.0.0.1:5672):
client unexpectedly closed TCP connection

=INFO REPORT==== 27-Dec-2016::13:41:34 ===
accepting AMQP connection <0.25206.0> (127.0.0.1:35036 -> 127.0.0.1:5672)

=WARNING REPORT==== 27-Dec-2016::13:41:42 ===
closing AMQP connection <0.25206.0> (127.0.0.1:35036 -> 127.0.0.1:5672):
client unexpectedly closed TCP connection


I've even grabbed a tcpdump for 5672 on lo interface, and there I see the same repetitive pattern:

client -> server: Protocol 0.9.1
server -> client: (in approx 15 seconds): Connection.Start
client -> server: TCP RST

in regards of "open vs used file handles", this is a "rabbitmqctl status":

 time rabbitmqctl status
Status of node rabbit@client170 ...
[{pid,14935},
 {running_applications,
     [{rabbitmq_management,"RabbitMQ Management Console","3.6.5"},
      {rabbitmq_web_dispatch,"RabbitMQ Web Dispatcher","3.6.5"},
      {webmachine,"webmachine","1.10.3"},
      {mochiweb,"MochiMedia Web Server","2.13.1"},
      {rabbitmq_management_agent,"RabbitMQ Management Agent","3.6.5"},
      {rabbit,"RabbitMQ","3.6.5"},
      {os_mon,"CPO  CXC 138 46","2.2.14"},
      {ssl,"Erlang/OTP SSL application","5.3.3"},
      {public_key,"Public key infrastructure","0.21"},
      {crypto,"CRYPTO version 2","3.2"},
      {amqp_client,"RabbitMQ AMQP Client","3.6.5"},
      {rabbit_common,[],"3.6.5"},
      {inets,"INETS  CXC 138 49","5.9.8"},
      {mnesia,"MNESIA  CXC 138 12","4.11"},
      {compiler,"ERTS  CXC 138 10","4.9.4"},
      {xmerl,"XML parser","1.3.6"},
      {syntax_tools,"Syntax tools","1.6.13"},
      {asn1,"The Erlang ASN1 compiler version 2.0.4","2.0.4"},
      {ranch,"Socket acceptor pool for TCP protocols.","1.2.1"},
      {sasl,"SASL  CXC 138 11","2.3.4"},
      {stdlib,"ERTS  CXC 138 10","1.19.4"},
      {kernel,"ERTS  CXC 138 10","2.16.4"}]},
 {os,{unix,linux}},
 {erlang_version,
     "Erlang R16B03-1 (erts-5.10.4) [source] [64-bit] [smp:4:4] [async-threads:64] [hipe] [kernel-poll:true]\n"},
 {memory,
     [{total,55621952},
      {connection_readers,6000},
      {connection_writers,0},
      {connection_channels,0},
      {connection_other,11488},
      {queue_procs,111072},
      {queue_slave_procs,0},
      {plugins,974768},
      {other_proc,18542464},
      {mnesia,89392},
      {mgmt_db,864576},
      {msg_index,57560},
      {other_ets,1457936},
      {binary,32368},
      {code,27157794},
      {atom,992409},
      {other_system,5324125}]},
 {alarms,[]},
 {listeners,[{clustering,25672,"::"},{amqp,5672,"::"}]},
 {vm_memory_high_watermark,0.4},
 {vm_memory_limit,1536327680},
 {disk_free_limit,50000000},
 {disk_free,882873597952},
 {file_descriptors,
     [{total_limit,924},{total_used,6},{sockets_limit,829},{sockets_used,1}]},
 {processes,[{limit,1048576},{used,246}]},
 {run_queue,0},
 {uptime,3361},
 {kernel,{net_ticktime,60}}]

real    0m32.722s
user    0m0.502s
sys     0m0.115s


I've almost bumped a hole in the wall near my desk :((

Now I'll seek how to reset backup stats db

Thanks

вторник, 27 декабря 2016 г., 15:04:16 UTC+7 пользователь Michael Klishin написал:

log            : /var/log/rab...@client170.log
sasl log       : /var/log/rab...@client170-sasl.log

[Кирилл Марчук]

I've reset statistics database by running:

 rabbitmqctl eval 'supervisor2:terminate_child(rabbit_mgmt_sup_sup, rabbit_mgmt_sup),rabbit_mgmt_sup_sup:start_child().'

which gave
 {ok,<9995.32484.0>}

however the effect is zero ! It has changed nothing, both before and after broker restart...

вторник, 27 декабря 2016 г., 15:04:16 UTC+7 пользователь Michael Klishin написал:

Listing a large number of connections is a very expensive linear operation since each of the connection processes has to be involved.

log            : /var/log/rab...@client170.log
sasl log       : /var/log/rab...@client170-sasl.log

[Michael Klishin]

You can see that the stats DB consumes 864576 bytes, which means it's nearly empty.

So it's probably something else. rabbitmq_top can show what processes are the busiest ones on a node

(note: that plugin is not supposed to be constantly running).

You can also restart the node and see if it at least temporary changes the outcome. If not then it's probably

something in the environment and not just a rogue process.

Then there are all the regular things to check: is there a multi-million message backlog? According to the RAM usage

breakdown, there shouldn't but it has to be mentioned.

Slow connections cannot be blamed on just the server. See https://groups.google.com/d/msg/rabbitmq-users/Lr2JGmSXNNk/JIXKpDFjr5YJ,

for example.

While probably unrelated, the file descriptor limit on this node seems to be the default (on most Linux distributions) 1024,

which is VERY LOW AND DANGEROUS for data services (and yes, no major Linux distribution gives a shit since

1024 is ought to be enough for Linus' desktop). See http://www.rabbitmq.com/production-checklist.html

or archive threads such as https://groups.google.com/d/msg/rabbitmq-users/uNJAT_nKANI/mW176sOlDwAJ, for example.

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

[Кирилл Марчук]

1. rabbitmq_top - I don't even have such a plugin.

and quite frankly, those "time" measurements I provided initially were taken when broker was essentially standing, i.e. it had NO connections at all

2. (on file limits) "multiple the 95th percentile number of concurrent connections by 2 and add total number of queues to calculate": for my setup that would mean smth like ... 20. Because I'm going to have like 4 concurrent connections and it will have a 10-15 queues.

This broker is used by 3 local logstash instances and single PHP application running also locally (this is a kiosk). That's why such a delay is 100 % NOT a sign of any load, and that's why I worry that much about this. The delay is critical here because if the broker does not process "publish" and other typical operations instantaneously, the whole system appears to be very sluggish, which is unacceptable for the Customer..

3. about "multi-million message backlog" - nothing remotely similar :). The system (even when functioning, which it now isn't) generates like 10-20 messages per minute.

вторник, 27 декабря 2016 г., 15:48:37 UTC+7 пользователь Michael Klishin написал:

[Кирилл Марчук]

Machine reboot did not mitigate the issue.

what else could I possibly do ?


вторник, 27 декабря 2016 г., 15:48:37 UTC+7 пользователь Michael Klishin написал:

[Michael Klishin]

Collect a traffic dump on the machine your client is connecting from, open it with Wireshark [1]

and look for clues there.

1. https://www.rabbitmq.com/amqp-wireshark.html

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.

[Michael Klishin]

On Tue, Dec 27, 2016 at 12:11 PM, Кирилл Марчук <62m...@gmail.com> wrote:

1. rabbitmq_top - I don't even have such a plugin.

and quite frankly, those "time" measurements I provided initially were taken when broker was essentially standing, i.e. it had NO connections at all

You do: http://github.com/rabbitmq/rabbitmq-top.

rabbitmq_top is just one of the ways to obtain data, which is essential to effective and efficient debugging. You can

continue using guesses, of course. It can a very long time, doing things that way.

 

2. (on file limits) "multiple the 95th percentile number of concurrent connections by 2 and add total number of queues to calculate": for my setup that would mean smth like ... 20. Because I'm going to have like 4 concurrent connections and it will have a 10-15 queues.

This broker is used by 3 local logstash instances and single PHP application running also locally (this is a kiosk). That's why such a delay is 100 % NOT a sign of any load, and that's why I worry that much about this. The delay is critical here because if the broker does not process "publish" and other typical operations instantaneously, the whole system appears to be very sluggish, which is unacceptable for the Customer..

3. about "multi-million message backlog" - nothing remotely similar :). The system (even when functioning, which it now isn't) generates like 10-20 messages per minute.

As I've mentioned, I do not expect this to help with this particular concern but IT IS DANGEROUS to run any data service — any database,

any messaging broker, any distributed coordination service — with the default 1024 limit. The worst thing about

this is that since it's an OS limit, you cannot tweak it on the fly and all hell is breaking loose when your node is above the limit.

Do it at your own peril.

 

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.

[Michael Klishin]

Those "client unexpectedly closed TCP connection" log entries tell you
that either the client or an intermediary (e.g. a proxy) closes TCP
connection without properly closing AMQP 0-9-1 connection. One very common
reason for that on a nearly idle system is a proxy that has its idle connection timeouts configured

to be too low. In any case, these undeniably happen on a live system but if

it routinely happens at roughly the same interval, this is something to be concerned about

and investigate.

A workaround for that is to use a heartbeat interval of 6-10 seconds:

http://www.rabbitmq.com/heartbeats.html. Heartbeats serve a different purpose but TCP-level connection

activity is a nice side effect that helps in the above scenario.

On Tue, Dec 27, 2016 at 10:35 AM, Кирилл Марчук <62m...@gmail.com> wrote:

Hi all

I am trying to troubleshoot a mysterious RabbitMQ behaviour on a CentOS 7.2 system. The main issue is that Logstash does not connect (with TimeoutException) however this my message is about something different: namely, that all RabbitMQ interaction is painfully slow!

Any command I can think of, takes 30+ seconds to complete, like:

> time rabbitmqctl list_users
Listing users ...
admin   [administrator]
guest   [administrator]

real    0m32.765s
user    0m0.479s
sys     0m0.134s

On the other machine it takes less than one second!

"systemctl start/stop rabbitmq-server" also takes a LOT to complete, see in the broker log file, for example:

=INFO REPORT==== 27-Dec-2016::12:51:05 ===
Starting RabbitMQ 3.6.5 on Erlang R16B03-1
Copyright (C) 2007-2016 Pivotal Software, Inc.
Licensed under the MPL.  See http://www.rabbitmq.com/

=INFO REPORT==== 27-Dec-2016::12:51:05 ===
node           : rabbit@client170
home dir       : /var/lib/rabbitmq
config file(s) : /etc/rabbitmq/rabbitmq.config
cookie hash    : 77AaFkYld+gM4p59VDe7mA==

log            : /var/log/rabbitmq/rabbit@client170.log
sasl log       : /var/log/rabbitmq/rabbit@client170-sasl.log

--

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-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.

[Kirill Marchuk]

I've managed to figure it out (occassionally)

[ As long as the activity on this kiosk is strictly localhost-bound, I did not have a chance to notice this until I've decided to download the rabbitmq_top plugin ]

It appears that the host in question has non-functional internet access while connected to a VPN, and any attempt to resolve a DNS-name leads to 30 seconds timeout.

As soon as I've disabled VPN, global internet has become reachable and all the timing of 'rabbitmqctl' operations became reasonable at once (less than 1 seconds). So, it seems that some part of "beam", or whichever child process, is trying either to resolve some name/address, either to reach any other node on the internet, thus the delay.

Not sure if it's a bug or feature, but I guess it's worthy of mentioning on "Troubleshooting" webpage, what would you say ? This is at best not expected, that any trivial operation, while running locally, still requires a functioning internet connection.

Kirill

27.12.2016 19:16, Michael Klishin пишет:

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/4GPsBQDOIe4/unsubscribe.
To unsubscribe from this group and all its topics, send an email to rabbitmq-user...@googlegroups.com.

[Michael Klishin]

Right. We've seen this multiple times before, including in a thread linked to in this discussion.

We already cover hostname resolution requirements in the Clustering guide, I can't think of

where it would belong to. Networking seems to be most reasonable.

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/4GPsBQDOIe4/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.

--
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-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.

[Kirill Marchuk]

Hi Michael

I've read thru the Clustering section.. And it's not immediately clear, how to setup "hostname resolution" in this context (when both client and broker are on the same machine and communication over 127.0.0.1) ?

Can you help me work it out a bit ? Which name should be resolvable, in this context.

By the way, now it seems that all the "rabbitmq" tools are quite responsive; still, DNS subsystem does not work (but at least now it immediately return failures - guess that's why there's no visible delay).

28.12.2016 11:32, Michael Klishin пишет:

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

[Michael Klishin]

All hostname used by clients and RabbitMQ nodes.

[Hao Yao]

Your solution save my day. Thanks a lot

I meet similar circumstance. RabbitMQ responses slow, with 10 seconds delay in /api/overflow request. While all system statistics (cpu, memory, disk i/o), rabbitmq_top and network is fine.

Finally find out the reason is DNS name resolution. We use 8.8.8.8 as DNS, which is polluted by GFW and cannot be accessed. I changed it to 114.114.114.114, and after reboot all response turned into less than 1 second.

We use RabbitMQ in intranet environment, so I still don't know why DNS affects. Anyhow, the problem has been resolved.

[Michael Klishin]

All requests that use hostnames will use the configured hostname resolution mechanism (and DNS is the most popular one).

It doesn't matter if the environment is an intranet or not ;)

Thank you for reporting your case to the list.

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.

[Michael Klishin]

FTR, one thing that has changed since Dec 2016 is that we have a dedicated doc guide that covers our preferred

methodology of troubleshooting networking and related topics [1]. Networking is a broad topic but it should give

you an overview of the approach and the tools that will provide relevant information.

1. https://www.rabbitmq.com/troubleshooting-networking.html

[MangoCat]

I am having a very similar problem with rabbitmq-server 3.7.8 in its alpine-management docker container form: https://hub.docker.com/_/rabbitmq

When I run rabbitmq-server 3.6.10 installed with apt install direct on Ubuntu 18.04, I don't see the issue.

For me, our rabbitmq use case is very similar to what Kirill Marchuk describes above: we have a kiosk which may, or may not, be connected to an external network with DNS resolution services.  There are about 10 clients in the kiosk which connect to the rabbitmq-server, all using internally designated IP addresses, no name resolution requirements from the clients.

Both 3.6.10 and 3.7.8 perform fine when connected to an active external network, reasonable startup time, etc.

When the kiosk is not connected to an external network, 3.6.10 continues to perform the same, but 3.7.8 experiences a long delay at startup - 90 to 120 seconds, which throws off everything which is expecting the system to be up and running in 45 seconds or less.  My experience differs from Kirill Marchuk in that, once started, everything runs fine in all 4 cases described above (3.6.10 vs 3.7.8, connected vs air-gapped), the delay comes in how long it takes before the first client is able to connect to the rabbitmq-server, and the long delay is only experienced in the 3.7.8 air-gapped case.

Is this something that might be improved in 3.7.15?  I plan to try it, but wonder if there is some way I can affect the configuration to make the server not look for DNS resolutions on startup, or do whatever else it is trying to do that causes it to take so much extra time when not connected to an active network.

Thanks,

[MangoCat]

Update: just tried 3.7.15 alpine-management , it has the same (undesirable) behavior as 3.7.8

Also, for what it's worth, all of these RabbitMQ servers are configured with management and MQTT plugins, otherwise setup is very close to defaults.

[Luke Bakken]

Hello,

Please do not reply to stale message discussions. It is less likely that people will respond.

The RabbitMQ team does not create nor support docker images. Please try reproducing your issue without using Docker.

Thanks,

Luke

[Michael Klishin]

Nothing has changed in 3.7.15 w.r.t.  hostname resolution on startup. You can control hostname resolution

even if you don't have the means to change it in the OS [1]. I'd consider other options first, though.

1. http://erlang.org/doc/apps/erts/inet_cfg.html

--
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.

To view this discussion on the web, visit https://groups.google.com/d/msgid/rabbitmq-users/b3474f12-4687-4305-82d6-0917cbc0920e%40googlegroups.com.

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