Super slow when enqueue messages to rabbitmq

[haosdent huang]

Hi, dear friends, we encounter a wired problem on rabbitmq: publish messages to rabbitmq is super slow.

We have queue A and queue B in rabbitmq-server. And we use celery with rabbitmq. The status of queues are

Queue Name	Ready Messages	Unacked Messages
Queue A	2	482,063
Queue B	3	31

We have 3 rabbitmq-servers, they are deployed in HA mode, all the queues are durable. And we deploy 9 consumers (celery workers) in 9 separate servers (didn’t run consumers in the same server with rabbitmq-servers).

When we publish the messages to Queue A, it is super slow which take more than 10s seconds. Sometimes it even takes more than 1 minute. We use tcpdump to track the packets between client side (celery.send_task) and rabbitmq-server. The client side ((celery.send_task)) indeed stuck more than 10 seconds when waiting for response from rabbitmq-server.

But at the meantime, publish the messages to Queue B is fast. And if we stop all the consumers, publish messages to Queue A would become fast as well. But if you start all consumers (9 consumers), publish messages to Queue A would stuck again.

We suspect it is because of network problems at first, but network should be fine according to ping/mtr result. All of them are located in the same private subnet. And we try to login rabbitmq servers and publish messages on rabbitmq servers directly, it is very slow when enqueue message as well. CPU/Memory/Disk IO/Network are fine in rabbitmq-servers/producer/consumer.

Is it a known issue? Anything I could help to troubleshoot this problem?

Our rabbitmq-servers are

ii  rabbitmq-server                    3.6.9-1                                    all          Multi-protocol messaging broker

Erlang version is

# dpkg -l|grep erlang
ii  esl-erlang                         1:19.3                                     amd64        Erlang

OS is

Ubuntu 16.04 (Kernel 4.4.0-21-generic)

Looking forward your response, thank you in advance.

​

[Michael Klishin]

We have seen this before and don't have profiler or internal flow control data to explain

it step by step but a good approximation of what's going on can be this (I failed to find a longer

version of this response in the archives).

A single queue uses one CPU core on its hot code path. In large part this is due to the ordering requirement.

So when a queue only has messages to accept, its total throughput goes towards that.

When it also has a consumer, it needs to do a certain amount of extra work and has a potentially slow

"downstream component" (the socket, the consumer, the channel prefetch [3]). It does not get twice the throughput,

of course, so internal flow control [1] makes sure that the publisher is throttled (or else the RAM usage

will keep growing and growing until the node is killed by the kernel).

If you can trade off ordering for parallelism, consumer using rabbitmq-sharding [2]. It does not guarantee

ordering but uses N "physical" queues behind one "logical" queue and thus can use multiple cores.

1. https://www.rabbitmq.com/blog/2015/10/06/new-credit-flow-settings-on-rabbitmq-3-5-5/

2. https://github.com/rabbitmq/rabbitmq-sharding/

3. https://www.rabbitmq.com/blog/2014/04/14/finding-bottlenecks-with-rabbitmq-3-3/

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

--

MK

Staff Software Engineer, Pivotal/RabbitMQ

[haosdent huang]

Hi, @Michael Klishin Thanks a lot for your quick response. 

> a queue only has messages to accept

Do you mean when there are a lot of unack messages in a queue, the throughout of this queue would become terrible without affect other queues?

> When it also has a consumer, it needs to do a certain amount of extra work and has a potentially slow

> "downstream component" (the socket, the consumer, the channel prefetch [3]). It does not get twice the throughput,

> of course, so internal flow control [1] makes sure that the publisher is throttled (or else the RAM usage

> will keep growing and growing until the node is killed by the kernel).

Yes, we check the state of connections via rabbitmqctl, but none of them is flow or blocked state. 

Would it become better that if we reduce consumers, for example only run 3 consumers instead of run 9 consumers? 

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.

[Michael Klishin]

MK

On 2 Jun 2017, at 21:00, haosdent huang <haos...@gmail.com> wrote:

Hi, @Michael Klishin Thanks a lot for your quick response. 

> a queue only has messages to accept

Do you mean when there are a lot of unack messages in a queue, the throughout of this queue would become terrible without affect other queues?

I did not say that. Accepting a message involves a certain amount of work on queue process' (thread if you will) end, in particular if the message is persistent and the queue is durable.

When on top of that you have deliveries to consumer to make, publishers will experience back pressure.

> When it also has a consumer, it needs to do a certain amount of extra work and has a potentially slow

> "downstream component" (the socket, the consumer, the channel prefetch [3]). It does not get twice the throughput,

> of course, so internal flow control [1] makes sure that the publisher is throttled (or else the RAM usage

> will keep growing and growing until the node is killed by the kernel).

Yes, we check the state of connections via rabbitmqctl, but none of them is flow or blocked state. 

Would it become better that if we reduce consumers, for example only run 3 consumers instead of run 9 consumers? 

You are talking about resource-driven alarms that block publishers. RabbitMQ components internally use flow control (known as "credit flow"), and the blog post

covers that.

Internal flow control is not permanent, a process can go in and out of it many times a second.

See https://www.rabbitmq.com/flow-control.html and http://alvaro-videla.com/2013/09/rabbitmq-internals-credit-flow-for-erlang-processes.html.

[haosdent]

> You are talking about resource-driven alarms that block publishers. RabbitMQ components internally use flow control (known as "credit flow"), and the blog post

> covers that.

> Internal flow control is not permanent, a process can go in and out of it many times a second.

> See https://www.rabbitmq.com/flow-control.html and http://alvaro-videla.com/2013/09/rabbitmq-internals-credit-flow-for-erlang-processes.html.

Hi, Michael, really appreciate your detail explanations. After reading the articles you provided, I think it still could not explain why enqueuing message slow issue go away after we stop all consumers. If enqueue slow is because credit flow control, publish messages should become slower after stop all consumers, 

right? However, after we stop all consumers, enqueue message didn't slow anymore. Anything I miss here? Or I misunderstanding the credit flow? Looking forward your response, thank you in advance.

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.

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

--

Best Regards,

Haosdent Huang

[haosdent]

And I read the implementation of rabbit_reader.erl

Found

-record(throttle, {
  %% never | timestamp()
  last_blocked_at,
  %% a set of the reasons why we are
  %% blocked: {resource, memory}, {resource, disk}.
  %% More reasons can be added in the future.
  blocked_by,

and

control_throttle(State = #v1{connection_state = CS,
                             throttle = #throttle{blocked_by = Reasons} = Throttle}) ->
    Throttle1 = case credit_flow:blocked() of
                  true  ->
                    Throttle#throttle{blocked_by = sets:add_element(flow, Reasons)};
                  false ->
                    Throttle#throttle{blocked_by = sets:del_element(flow, Reasons)}
             end,
    State1 = State#v1{throttle = Throttle1},
    case CS of
        running -> maybe_block(State1);
        %% unblock or re-enable blocking
        blocked -> maybe_block(maybe_unblock(State1));
        _       -> State1 
    end.

Is there any way I could get the value of last_blocked_at from rabbitmq api, rabbitmqctl, webui without change the rabbitmq-server code and print it into log?

​

--

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/HrbeWxst_TQ/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 rabbitm...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

Best Regards,

Haosdent Huang

[haosdent]

> You are talking about resource-driven alarms that block publishers.

This looks not true. Because in rabbit_reader.erl, if the connection is blocked by credit flow, it would update connection_state to blocked as well.

maybe_block(State = #v1{connection_state = CS, throttle = Throttle}) ->
    case should_block_connection(Throttle) of
        true ->
            State1 = State#v1{connection_state = blocked,
                              throttle = update_last_blocked_at(Throttle)},

​

[Michael Klishin]

My point is not that credit flow will not ultimately block the connection. Resource (e.g. disk space) driven

alarms usually do not last fractions of a second but internal flow control does, it can go in and out of effect

many times a second.

Consider this: you have some work to do. You can do it at a rate of X tasks per hour. Now someone asks

you to do the same amount of work and also look after a baby. Unless you completely ignore the baby,

your productivity will likely go down to a value lower than X.

When the baby's parent then comes back and picks the baby up, you can go back to doing X tasks per hour

(at least there is nothing obvious preventing you from doing so).

This is what a queue process has to deal with: "serving" publishers and also delivering to consumers.

When the latter takes time — and it will — the credit flow mechanism will slow publishers (channel processes)

down, which will in turn slow down connections (rabbit_reader processes) and apply TCP back pressure to publishing clients.

If a queue process was 2 processes, it could deliver and serve publishers in parallel but it would require a fair amount of non-trivial

coordination to preserve operation ordering.

rabbitmq-sharding is much less prone to this behavior because sharded "logical" queues are process groups (if you have more than one consumer).

To post to this group, send email to rabbitmq-users@googlegroups.com.

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

[haosdent]

Hmm, confirmed should not because by flow control. Because after we changed to

{credit_flow_default_credit,{10000000,1000000}},

in all rabbitmq servers, the issue still happen.

Now we have a new founding, when publish messages is slow, the memory usage of beam.smp always 10+GB. When publish messages is fast, the memory usage of beam.smp always 8GB. Our servers are 64G and always have 40GB available memory. And vm_memory_high_watermark and
vm_memory_high_watermark_paging_ratio are 0.9, so should not caused by no enough memory.

Is it because erlang stuck at gc and could not accept messages? Or the version of erlang we used would cause problem of rabbitmq

[haosdent]

Hi, @Michael Thanks a lot for your explanation. Sorry that just saw your message sent at "6:42 PM" after I sent last message.

>This is what a queue process has to deal with: "serving" publishers and also delivering to consumers.

Do you mean if not consumer, the queue process no need to worry about delivering messages to consumers, so it would faster, right?

>rabbitmq-sharding is much less prone to this behavior because sharded "logical" queues are process groups (if you have more than one consumer).

Because we find this issue still happen even we only start one consumer, this plugin would not help for our cases, right? 

The two factors we think cause issue are a lot of unacked message in queue and 10G memory usage of beam.smp.

Is there any bottleneck or known issues would happen for such situation? 

Best Regards,

Haosdent Huang

[Michael Klishin]

To give a well informed answer we need a way to reproduce and spend some time with various tools

that inspect process and runtime state. I cannot offer any ETA on when that might happen because

our team is under a lot of pressure to ship 3.7.0 RC1 and support Erlang 20.

You can head to the queue page in the management UI and learn a lot about where your

messages are (in RAM, on disk) as well as what "type" they are (persistent or transient).

Transient messages are moved to disk as needed. Persistent ones are moved

nearly instantaneously (as long as the queue is durable, otherwise they are treated as transient).

http://www.rabbitmq.com/lazy-queues.html will move both as if they were persistent in a durable queue.

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 Sat, Jun 3, 2017 at 1:57 PM, haosdent <haos...@gmail.com> wrote:

Hi, @Michael Thanks a lot for your explanation. Sorry that just saw your message sent at "6:42 PM" after I sent last message.

>This is what a queue process has to deal with: "serving" publishers and also delivering to consumers.

Do you mean if not consumer, the queue process no need to worry about delivering messages to consumers, so it would faster, right?

If there are no consumers, how can a queue spend any time delivering to them?

 

>rabbitmq-sharding is much less prone to this behavior because sharded "logical" queues are process groups (if you have more than one consumer).

Because we find this issue still happen even we only start one consumer, this plugin would not help for our cases, right? 

The two factors we think cause issue are a lot of unacked message in queue and 10G memory usage of beam.smp.

Is there any bottleneck or known issues would happen for such situation? 

The total amount of memory used is a useless metric. You need to know what exactly uses it (displayed in `rabbitmqctl status` and management UI).

rabbitmq-top can even display individual processes that consume the most RAM or VM scheduler time.

Erlang GC is per-process, not global, although if nearly all of that memory is used by a single process that is not very different from

a stop-the-world one such as on the JVM.

I have a generic piece of advice for you: do not use a single queue (regardless of whether you'd go with rabbitmq-sharding or not).

Single Giant Queue is an anti-pattern that has all kinds of problems, not just that a single queue will become a bottleneck.

Find a way to use 10, 30, 100, 2K queues in your system.

[haosdent]

Hi, @Michael Really appreciate your help when you are busy. Let me if lazy-queues and sharing plugin works. Would feedback here if they resolve our problems. Thank you for your helps again.

Best Regards,

Haosdent Huang

[Michael Klishin]

By the way, queue GC activity can be seen in the management UI 

(on the queue page) as well as the overall node GC activity (on the node page).

[Michael Klishin]

Sure thing.

We have seen this a couple of times in our own long running environments and would definitely

be interested in reproducing it and investigating what can be improved.

That said, single queue workloads run into a wall eventually, so avoiding them

(either with rabbitmq-sharding or by using multiple queues in your own code) is usually

the way to go anyway.

[haosdent]

>By the way, queue GC activity can be seen in the management UI 

>(on the queue page) as well as the overall node GC activity (on the node page).

WoW, the webui of rabbitmq is amazing! Let's try a stable way to reproduce and check if it caused by GC or other staffs. Thanks a lot.

Best Regards,

Haosdent Huang

[Michael Klishin]

I can't recommend rabbitmq-top enough as a source of "lower level" information

about the system:

https://github.com/rabbitmq/rabbitmq-top

It ships with RabbitMQ in recent versions (starting with 3.6.6 or so?)

[haosdent]

Yep, it starts from 3.6.3. Just need rabbitmq-plugins enable rabbitmq_top.

​

Best Regards,

Haosdent Huang

[Michael Klishin]

I've missed the "450K unacknowledged messages" part. We have seen a somewhat

similar issue reported before. It also needs profiling but in general,

there is channel (and queue/message store) state related to unacknowledged messages that is only kept in memory and it can increase GC activity for those processes.

This is also an area where I'm sure we can improve quite a few things but it's not a priority

because… well, keep reading :)

I haven't seen half a million of unacknowledged messages many times and we definitely recommend using channel prefetch with values that are < 1000. The reason is not necessarily

efficiency related, though: it simply makes no sense as the law of diminishing returns

kicks in well before you reach even 100K:

https://www.rabbitmq.com/blog/2014/04/14/finding-bottlenecks-with-rabbitmq-3-3/

Another reason for not having such massive numbers of unacknowledged messages is

that consumers are fairly likely to begin running out of memory without the effective flow control 

offered by manual acknowledgements and bounded prefetch.

Modern Java client releases apply TCP back pressure when they have too many unprocessed deliveries even in automatic acknowledgement mode, otherwise it's too common to see them

run out of heap.

I doubt Kombu, the client used in Celery, has the same mechanism. Historically it has been

a client that's one of the last to get support for various features.

So if it's possible, consider configuring Celery to use channel prefetch of 1K per channel

(and not use 100s of channels ;)).

[haosdent]

Thanks a lot for your help @Michael. I notice that the GC is more frequently and Reductions (rabbitmq-stop) is very high for those queues which publish messages are slows. Is Reduction high caused by Erlang GC?

> consider configuring Celery to use channel prefetch of 1K per channel

> (and not use 100s of channels ;)).

Gotcha, let me add this limit in all our celery consumers.

--

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

[Michael Klishin]

Reductions are units of work in the VM. A process with a lot of reductions is doing a lot of work and takes a lot of scheduler time.

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.