Value of other_proc is extremely high

[Firm]

Hi,

Running 3.9.13 version with 5-10K rps. Set watermarks both for memory (0.7) and disk. Having other_proc value more than 60-70% (of 72GB) I see unresponsive server process. How could I determine what eats memory? And how to fix that.

Regards,

[mkuratczyk]

That's unexpected (we fixed a similar issue in 3.9.8 where connection-related memory usage would be classified as other). Could you run rabbitmq-diagnostics observer and then type "mm [ENTER]" and take a couple of screenshots over time? It should show which Erlang processes use the most memory and whether that changes over time or whether the same processes are continuously at the top.

Also, if you have the Grafana/Prometheus deployed, at least some screenshots from what's going on in the cluster would be helpful.

[Firm]

Thank you for reply, will provide this information once being hit again.

[Firm]

Got this:

`Memory

Total memory used: 4.1823 gb
Calculation strategy: rss
Memory high watermark setting: 0.7 of available memory, computed to: 72.1555 gb

other_proc: 1.2033 gb (24.81 %)
allocated_unused: 1.1272 gb (23.24 %)
binary: 0.7286 gb (15.02 %)
metrics: 0.6446 gb (13.29 %)
queue_procs: 0.6074 gb (12.52 %)
other_ets: 0.1621 gb (3.34 %)
connection_other: 0.1007 gb (2.08 %)
mgmt_db: 0.0733 gb (1.51 %)
plugins: 0.0444 gb (0.92 %)
other_system: 0.0423 gb (0.87 %)
connection_channels: 0.0408 gb (0.84 %)
code: 0.036 gb (0.74 %)
connection_readers: 0.0235 gb (0.48 %)
connection_writers: 0.0123 gb (0.25 %)
mnesia: 0.0015 gb (0.03 %)
atom: 0.0015 gb (0.03 %)
msg_index: 5.0e-4 gb (0.01 %)
quorum_ets: 0.0 gb (0.0 %)
stream_queue_procs: 0.0 gb (0.0 %)
stream_queue_replica_reader_procs: 0.0 gb (0.0 %)
queue_slave_procs: 0.0 gb (0.0 %)
quorum_queue_procs: 0.0 gb (0.0 %)
reserved_unallocated: 0.0 gb (0.0 %)
stream_queue_coordinator_procs: 0.0 gb (0.0 %)
`

[Firm]

System is somewhere unresponsive:
# rabbitmqctl list_queues Timeout: 60.0 seconds ... Listing queues for vhost / ... name messages {:badrpc, {:timeout, 60.0, "Some queue(s) are unresponsive, use list_unresponsive_queues command."}}

[Firm]

One more detail. When it (rabbitmq-server) hangs and is restarted, then it's very slow/unresponsive on startup with log messages like 2022-03-11 09:10:49.685847+00:00 [warning] <0.490.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_persistent": rebuilding indices from scratch

[Firm]

Was able to catch diagnostic data from almost unresponsive server.

[Firm]

Btw, interesting thing: number of async-threads is 1, although it was set to 64 in #212 (almost 7 years ago). Currently I'm running 3.9.13-1 with 24.3.2 erlang package version.

[michaelklishin]

Erlang's I/O subsystem has changed in recent years and some settings are ignored.

[Firm]

But why has async-threads default value changed from 64 to 1 once again?

[lhoguin]

Async threads are no longer used by the VM. The relevant option is now +SDio.

[lukebakken]

Questions / asks:

• Has this behavior always been in place in your RabbitMQ environment? If not, what changed or what triggered it?
• Are you using a cluster? If so, how many nodes? What sort of environment (physical hardware, VMs, cloud)?
• Are you using Kubernetes or any other cluster management?
• We need to know what kind of queues and mirroring you have in place. It's probably easiest to export your definitions and ATTACH the generated file to your response.

[michaelklishin]

Classic non-mirrored queues that expect to have 12M messages must be lazy, otherwise if their publishers ever publish messages as transient, RabbitMQ will be instructed to keep as many of them as possible in memory.

According to the top output, there is a bunch of queues at "init" stage which means they are just starting, and a process group
with a massive [Erlang] message backlog (no relation to RabbitMQ messages). Process groups are used for tracking of
exclusive queues on a connection, so my only guess is that there may be very high connection churn going on, or on-disk data
recovery in progress.

[Firm]

I have tried lazy queues but was stuck with high disk i/o (as lazy queue policy tries to store all messages to disk).

[michaelklishin]

Well, there is no option that doesn't incur either a high disk I/O or some form of memory pressure, which can eventually manifest itself as short-lived Erlang processes within the node piling up. Lazy queues or quorum queues or a stream are your only viable options for tens of millions of messages.

[michaelklishin]

@lukebakken is there a way for us to verify if these may be disk space monitoring processes piling up? We have seen this a couple of times in recent months.

[johanrhodin]

We (CloudAMQP) have seen this a few times: pg_local hugging a ton of memory. I don't have a clean way to reproduce, but it correlates with very high channel numbers (~100k). pg_local keeps an erlang monitor on each channel, so if something happens to many channels at once or faster than it can check in on them, it is possible that it's erlang mailbox just keeps backing up.

Check: recon:info(pg_local) and current_stacktrace and ets:info(pg_local_table, size)
So rabbitmqctl eval 'recon:info(pg_local).' and rabbitmqctl eval 'ets:info(pg_local_table, size).'

[Firm]

Another screenshot. 30 channels, 80 queues, around 40M messages total.

[michaelklishin]

See #4257 (reply in thread). We cannot tell exactly what those processes are but it usually correlates with a very large number of channels.
Which may mean the applications leak channels or use them in a very suboptimal way.

[Firm]

rabbitmqctl eval 'recon:info(pg_local).'

[{meta,
[{registered_name,pg_local},
{dictionary,
[{'$initial_call',{pg_local,init,1}},
{'$ancestors',[kernel_safe_sup,kernel_sup,<11948.47.0>]}]},
{group_leader,<11948.46.0>},
{status,running}]},
{signals,
[{links,[<11948.67.0>]},
{monitors,
[{process,<11948.5825.7579>},
{process,<11948.7616.2076>},
{process,<11948.12143.7755>},
{process,<11948.23067.3472>},
{process,<11948.16228.7658>},
{process,<11948.16041.7611>},
{process,<11948.7798.7731>},
{process,<11948.5933.7681>},
{process,<11948.11899.7783>},
{process,<11948.30597.7767>},
{process,<11948.25164.7659>},
{process,<11948.18595.7712>},
{process,<11948.1045.2008>},
{process,<11948.20532.7742>},
{process,<11948.13632.2017>},
{process,<11948.21329.7726>},
{process,<11948.19299.7817>},
{process,<11948.527.4169>},
{process,<11948.16483.1980>},
{process,<11948.838.7628>},
{process,<11948.32372.7648>},
{process,<11948.6585.7578>},
{process,<11948.21914.7720>},
{process,<11948.4114.7778>},
{process,<11948.27281.7411>},
{process,<11948.21600.7751>},
{process,<11948.18706.1973>},
{process,<11948.18754.2076>},
{process,<11948.19979.7626>},
{process,<11948.26916.1788>},
{process,<11948.21804.2022>},
{process,<11948.28872.2075>},
{process,<11948.4726.2033>},
{process,<11948.12335.2076>},
{process,<11948.11973.6928>},
{process,<11948.17017.7715>},
{process,<11948.13736.2027>},
{process,<11948.29373.2075>},
{process,<11948.31648.7654>},
{process,<11948.5272.7781>},
{process,<11948.2202.1961>},
{process,<11948.16262.7777>},
{process,<11948.16308.2026>},
{process,<11948.22915.7665>},
{process,<11948.19210.7600>},
{process,<11948.27270.7686>},
{process,<11948.8096.7564>},
{process,<11948.21384.7671>},
{process,<11948.308.7689>},
{process,<11948.6214.1885>},
{process,<11948.14985.7670>},
{process,<11948.4207.7818>}]},
{monitored_by,[]},
{trap_exit,false}]},
{location,
[{initial_call,{proc_lib,init_p,5}},
{current_stacktrace,
[{erts_internal,flush_monitor_messages,3,[]},
{pg_local,leave_group,2,[{file,"pg_local.erl"},{line,214}]},
{pg_local,handle_cast,2,[{file,"pg_local.erl"},{line,132}]},
{gen_server,try_dispatch,4,[{file,"gen_server.erl"},{line,695}]},
{gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,771}]},
{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,226}]}]}]},
{memory_used,
[{memory,101114447808},
{message_queue_len,689627269},
{heap_size,3046587130},
{total_heap_size,5053405482},
{garbage_collection,
[{max_heap_size,#{error_logger => true,kill => true,size => 0}},
{min_bin_vheap_size,46422},
{min_heap_size,233},
{fullsweep_after,65535},
{minor_gcs,0}]}]},
{work,[{reductions,3874362758659}]}]

[Firm]

rabbitmqctl eval 'ets:info(pg_local_table, size).'
7548

[Firm]

@ukebakken,

• happens once load raises (a lot of messages are injected at high rate)
• single RabbitMQ instance running in lxc container on ssd-backed devce
• no k8s or other tools
• all queues are simple, non-mirrored

rabbitmqctl list_policies

Listing policies for vhost "/" ...
vhost name pattern apply-to definition priority
/ limit length .* queues {"max-length":60000000} 0

[michaelklishin]

@Firm we don't see much evidence of that, although it can be an extra factor that aggravates the issue. The actual root cause more often than not ends up being channel or queue churn. A lot of
runtime CPU resources in the observer table is spent in queue process initialization.

So look for churn that your applications create.