high cpu with ets

[rxjhfmf]

Describe the bug

I run a rabbitmq server in docker , sometimes it causes high cpu

Reproduction steps

rabbitmqctl status like below:

Status of node idc-uat-rabbitmq@rabbitmq-78cb67bc4c-7t6vc ...
Runtime

OS PID: 20
OS: Linux
Uptime (seconds): 327095
Is under maintenance?: false
RabbitMQ version: 3.11.11
RabbitMQ release series support status: supported
Node name: idc-uat-rabbitmq@rabbitmq-78cb67bc4c-7t6vc
Erlang configuration: Erlang/OTP 25 [erts-13.2] [source] [64-bit] [smp:8:8] [ds:8:8:10] [async-threads:1] [jit:ns]
Crypto library: OpenSSL 3.0.8 7 Feb 2023
Erlang processes: 3711 used, 1048576 limit
Scheduler run queue: 0
Cluster heartbeat timeout (net_ticktime): 60

Plugins

Enabled plugin file: /etc/rabbitmq/enabled_plugins
Enabled plugins:

• rabbitmq_prometheus
• accept
• prometheus
• rabbitmq_management
• amqp_client
• rabbitmq_web_dispatch
• cowboy
• cowlib
• rabbitmq_management_agent

Data directory

Node data directory: /var/lib/rabbitmq/mnesia/idc-uat-rabbitmq@rabbitmq-78cb67bc4c-7t6vc
Raft data directory: /var/lib/rabbitmq/mnesia/idc-uat-rabbitmq@rabbitmq-78cb67bc4c-7t6vc/quorum/idc-uat-rabbitmq@rabbitmq-78cb67bc4c-7t6vc

Config files

• /etc/rabbitmq/conf.d/10-defaults.conf

Log file(s)

• /var/log/rabbitmq/idc-uat-rabbitmq@rabbitmq-78cb67bc4c-7t6vc_upgrade.log

Alarms

(none)

Memory

Total memory used: 0.6033 gb
Calculation strategy: rss
Memory high watermark setting: 0.4 of available memory, computed to: 108.0799 gb

allocated_unused: 0.3238 gb (53.68 %)
reserved_unallocated: 0.0552 gb (9.15 %)
binary: 0.047 gb (7.78 %)
code: 0.036 gb (5.97 %)
other_proc: 0.0319 gb (5.29 %)
connection_other: 0.0281 gb (4.65 %)
plugins: 0.0266 gb (4.41 %)
other_system: 0.0191 gb (3.16 %)
mgmt_db: 0.0132 gb (2.19 %)
connection_channels: 0.0069 gb (1.15 %)
other_ets: 0.0033 gb (0.55 %)
metrics: 0.0028 gb (0.47 %)
connection_writers: 0.0028 gb (0.46 %)
connection_readers: 0.0027 gb (0.46 %)
queue_procs: 0.002 gb (0.33 %)
atom: 0.0015 gb (0.24 %)
mnesia: 0.0003 gb (0.05 %)
msg_index: 0.0001 gb (0.01 %)
quorum_ets: 0.0 gb (0.0 %)
quorum_queue_dlx_procs: 0.0 gb (0.0 %)
quorum_queue_procs: 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 %)
stream_queue_coordinator_procs: 0.0 gb (0.0 %)

File Descriptors

Total: 70, limit: 1048479
Sockets: 56, limit: 943629

Free Disk Space

Low free disk space watermark: 0.05 gb
Free disk space: 3870.0483 gb

Totals

Connection count: 56
Queue count: 40
Virtual host count: 2

Listeners

Interface: [::], port: 15672, protocol: http, purpose: HTTP API
Interface: [::], port: 15692, protocol: http/prometheus, purpose: Prometheus exporter API over HTTP
Interface: [::], port: 25672, protocol: clustering, purpose: inter-node and CLI tool communication
Interface: [::], port: 5672, protocol: amqp, purpose: AMQP 0-9-1 and AMQP 1.0

and runtime_thread_stats like below 

Will collect runtime thread stats on idc-uat-rabbitmq@rabbitmq-78cb67bc4c-7t6vc for 5 seconds...
Average thread real-time    :  5002491 us
Accumulated system run-time : 40037028 us
Average scheduler run-time  :  5001612 us

        Thread    alloc      aux      bifbusy_wait check_io emulator      ets       gc  gc_full      nif    other     port     send    sleep   timers

Stats per thread:
     async( 0)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
       aux( 1)    0.00%    0.02%    0.00%    0.00%    0.01%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%   99.96%    0.00%
dirty_cpu_( 1)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_cpu_( 2)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_cpu_( 3)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_cpu_( 4)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_cpu_( 5)    0.02%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.34%    0.04%    0.00%    0.00%    0.00%    0.00%   99.60%    0.00%
dirty_cpu_( 6)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_cpu_( 7)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_cpu_( 8)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_io_s( 1)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_io_s( 2)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_io_s( 3)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_io_s( 4)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_io_s( 5)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_io_s( 6)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_io_s( 7)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.01%    0.00%    0.00%    0.00%   99.98%    0.00%
dirty_io_s( 8)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_io_s( 9)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_io_s(10)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
      poll( 0)    0.00%    0.00%    0.00%    0.00%    0.01%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%   99.98%    0.00%
 scheduler( 1)    5.23%    0.02%    0.91%    0.00%    0.08%    8.61%   83.87%    0.94%    0.03%    0.00%    0.16%    0.03%    0.10%    0.01%    0.03%
 scheduler( 2)    4.79%    0.06%    0.75%    0.00%    0.08%    8.25%   83.36%    0.82%    0.00%    0.00%    0.15%    1.49%    0.14%    0.06%    0.04%
 scheduler( 3)    4.92%    0.06%    0.71%    0.00%    0.08%    8.04%   83.29%    0.90%    0.02%    0.00%    0.16%    1.66%    0.10%    0.02%    0.04%
 scheduler( 4)    4.85%    0.07%    0.75%    0.00%    0.08%    8.10%   83.08%    0.90%    0.03%    0.00%    0.15%    1.86%    0.10%    0.01%    0.04%
 scheduler( 5)    4.67%    0.02%    0.51%    0.00%    0.07%    7.93%   85.60%    0.91%    0.04%    0.00%    0.12%    0.03%    0.08%    0.00%    0.02%
 scheduler( 6)    4.68%    0.03%    0.51%    0.00%    0.07%    7.76%   85.42%    0.88%    0.04%    0.00%    0.11%    0.39%    0.08%    0.00%    0.02%
 scheduler( 7)    4.77%    0.03%    0.55%    0.00%    0.07%    7.85%   85.51%    0.87%    0.04%    0.02%    0.10%    0.06%    0.10%    0.00%    0.02%
 scheduler( 8)    4.85%    0.07%    0.90%    0.00%    0.08%    8.64%   82.00%    1.01%    0.04%    0.00%    0.16%    2.05%    0.14%    0.02%    0.04%

Stats per type:
         async    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
           aux    0.00%    0.02%    0.00%    0.00%    0.01%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%   99.96%    0.00%
dirty_cpu_sche    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.04%    0.01%    0.00%    0.00%    0.00%    0.00%   99.95%    0.00%
dirty_io_sched    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
          poll    0.00%    0.00%    0.00%    0.00%    0.01%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%   99.98%    0.00%
     scheduler    4.84%    0.04%    0.70%    0.00%    0.08%    8.15%   84.02%    0.90%    0.03%    0.00%    0.14%    0.95%    0.11%    0.02%    0.03%




### Expected behavior

why does ets cause high cpu?

### Additional context

_No response_

[mkuratczyk]

Hi. There are no reproduction steps beyond "running RabbitMQ". Please provide information about what you are doing (workload).
Judging by memory used, it seems like the instance is mostly idle so high ETS usage is a bit surprising indeed, but this usage suggests it's doing something. Please let us know what.

Some screenshots from rabbitmq-diagnostics observer can also be helpful.

A bit more involved, but this would be an even better method to understand what RabbitMQ is busy with: https://blog.rabbitmq.com/posts/2022/05/flame-graphs/

[michaelklishin]

All those channels will emit metrics and that involves updating several ETS tables. On a node that is very lightly loaded otherwise it can show up as a major CPU usage contributor.

Use a few channels per connection, 60+ is indeed difficult to justify. Note that you can have consumer parallelism without having a channel for each consumer. Multiple consumers can be registered on a single channel, just make sure they do not double ack (e.g. by using multi-message acks concurrently).

[rxjhfmf]

Why would you have 60+ channels per connection on average? That's just wrong.

yes, i know that is not recommended. in my project , there are 2 rabbitmq nodes and used for different case . But , one node is low cpu in use

[michaelklishin]

See Reducing CPU Usage on Lightly Loaded Nodes in the Runtime guide.

[rxjhfmf]

Ok, then not churn but just many channels for (almost certainly) no good reason. Plus, 20k msg/s (I assume you're talking per second) is a significant workload. Topic exchanges can be expensive (also use ETS heavily). If you can move (at least some of) the traffic to use direct exchanges, this will be easier to handle.

If you want to continue this discussion please:

1. Follow https://blog.rabbitmq.com/posts/2022/05/flame-graphs/ so that we can see what's going on in your system
   and/or
2. provide reproduction steps: use https://perftest.rabbitmq.com/ to simulate your workload (+ definitions JSON file if needed to declare the topology).

thank you . I'll try to reduce the channel and observe again

[rxjhfmf]

All those channels will emit metrics and that involves updating several ETS tables. On a node that is very lightly loaded otherwise it can show up as a major CPU usage contributor.

Use a few channels per connection, 60+ is indeed difficult to justify. Note that you can have consumer parallelism without having a channel for each consumer. Multiple consumers can be registered on a single channel, just make sure they do not double ack (e.g. by using multi-message acks concurrently).

thank you, I'll adjust my code and try

[rxjhfmf]

And i want to know the performance about Federation and Shovel plugin , is there any doc introducing?