频繁出现 long_schedule

EMQX
,
1

环境信息

  • EMQX 版本：5.8.4
  • Erlang/OTP：OTP 26
  • 部署方式：Kubernetes
  • 场景：设备连接压测期间
  • 系统监控日志：emqx_sys_mon 上报 long_schedule
info: {"timeout":299,"out":"undefined","in":"{emqx_connection,recvloop,2}"} msg: long_schedule procinfo: { "status":"waiting", "proc_lib_initial_call":"{emqx_connection,init,['Argument__1','Argument__2','Argument__3','Argument__4']}", "pid":"<0.284363.0>", "message_queue_len":0, "memory":110248, "reductions":93956, "current_stacktrace":[ "{emqx_connection,recvloop,2,[{file,\"emqx_connection.erl\"},{line,415}]}", "{proc_lib,wake_up,3,[{file,\"proc_lib.erl\"},{line,251}]}" ] }

info: {"timeout":285,"out":"{gen_server,loop,7}","in":"{gen_server,loop,7}"} msg: long_schedule procinfo: { "status":"running", "registered_name":"emqx_broker_helper", "pid":"<0.2697.0>", "message_queue_len":0, "memory":53781552, "total_heap_size":5154529, "heap_size":833026, "reductions":37046327, "current_stacktrace":[ "{gen_server,loop,7,[{file,\"gen_server.erl\"},{line,1001}]}", "{proc_lib,init_p_do_apply,3,[{file,\"proc_lib.erl\"},{line,241}]}" ] }

info: {"timeout":294,"out":"{erlang,port_command,3}","in":"undefined"} msg: long_schedule procinfo: { "status":"waiting", "proc_lib_initial_call":"{emqx_connection,init,['Argument__1','Argument__2','Argument__3','Argument__4']}", "pid":"<0.62741.0>", "message_queue_len":0, "memory":27032, "reductions":273289, "current_stacktrace":[ "{emqx_connection,recvloop,2,[{file,\"emqx_connection.erl\"},{line,415}]}", "{proc_lib,wake_up,3,[{file,\"proc_lib.erl\"},{line,251}]}" ] }

希望确认的问题

  1. 这些 long_schedule 可能对 EMQX 造成哪些实际影响
  2. 针对这类 long_schedule ，官方是否有推荐的排查方法和优化方案，例如 CPU、Scheduler、GC、订阅规模方面的优化？
  3. long_schedule 是否可能间接导致 Kafka 连接异常 频繁重连后最终出现 eaddrnotavail
2

long_schedule 的直接意思是 Erlang VM 发现某个进程/任务占用调度器时间过长。5.8.x 里 sysmon.vm.long_schedule 默认阈值是 240ms，日志中285~299ms 刚好越过阈值，所以会被 emqx_sys_mon 打出来。
你这几条堆栈集中在两个方向：

  • {emqx_connection,recvloop,2} / {erlang,port_command,3}：连接压测时 socket 收发路径被调度延迟影响。
  • emqx_broker_helper：broker 辅助进程也被采样到，但单看 memory: 53MB 和 message_queue_len: 0 还不能说明它卡死。

实际影响看持续时间和频率。偶发几条可以认为只是压测尖峰信号；如果持续刷，影响会是连接建立变慢、Keepalive/收发包延迟、规则和数据集成处理延迟，严重时会诱发客户端断连和重连风暴。

# 看 Pod 是不是 CPU 打满或被 CFS throttle
kubectl top pod -n <ns> -l app.kubernetes.io/name=emqx
# 如果有 Prometheus，看这两个
rate(container_cpu_usage_seconds_total{pod=~"emqx.*"}[5m])
rate(container_cpu_cfs_throttled_seconds_total{pod=~"emqx.*"}[5m])

K8s 里最常见的问题是 CPU limit 太小导致调度器被 throttle。压测时优先提高 CPU request/limit，或者至少确认 throttling 不是高峰时段同步出现。
连接压测再检查系统和 EMQX 入口参数：

# OS/容器宿主机侧重点
ulimit -n
cat /proc/sys/net/ipv4/ip_local_port_range
cat /proc/sys/net/core/somaxconn
cat /proc/sys/net/ipv4/tcp_max_syn_backlog

EMQX 侧重点是把连接速率削平，不要让所有设备同一秒冲进来：

订阅规模方面，看这几项：总订阅数、通配符订阅数、共享订阅数、单条消息 fan-out 数、每秒 publish 数。通配符和高 fan-out 会把 broker 侧调度压力放大。

Kafka 的 eaddrnotavail 和 long_schedule 没有直接因果。eaddrnotavail 更像本机临时端口耗尽、源地址绑定异常、或者 Kafka 连接频繁重建后 TIME_WAIT 堆积。它可能和同一轮压测相关：CPU 调度延迟导致 Kafka connector 超时/重连，重连多了再把本地端口打爆。

在出现 eaddrnotavail 的节点上抓：

ss -ant state time-wait | wc -l
cat /proc/sys/net/ipv4/ip_local_port_range
cat /proc/sys/net/ipv4/tcp_fin_timeout

可以重点从以下几个方面进行排查

  1. EMQX Pod 的 CPU request/limit、压测期间 CPU usage 和 throttling 。
  2. 单节点连接数、连接建立速率、消息速率、订阅数/通配符订阅数。
  3. Kafka connector 的连接池大小、Kafka broker 地址数量、eaddrnotavail 完整日志前后 1 分钟。
  4. 同一时间有没有 busy_port、busy_dist_port、large_heap、long_gc。
3

确实出现了large_heap，其他的没有发现 busy_port 、busy_dist_port 、long_gc

info:
{"timeout":299,"out":"undefined","in":"{emqx_connection,recvloop,2}"}
level:
warning
line:
140
msg:
long_schedule
pid:
<0.2741.0>
procinfo:
{"trap_exit":false,"trace":0,"total_heap_size":13635,"suspending":[],"status":"waiting","stack_size":25,"sequential_trace_token":[],"registered_name":[],"reductions":93956,"proc_lib_initial_call":"{emqx_connection,init,['Argument__1','Argument__2','Argument__3','Argument__4']}","priority":"normal","pid":"<0.284363.0>","min_heap_size":233,"message_queue_len":0,"memory":110248,"last_calls":false,"initial_call":"{proc_lib,init_p,5}","heap_size":6772,"group_leader":"<0.2467.0>","error_handler":"error_handler","current_stacktrace":["{emqx_connection,recvloop,2,[{file,\"emqx_connection.erl\"},{line,415}]}","{proc_lib,wake_up,3,[{file,\"proc_lib.erl\"},{line,251}]}"],"catchlevel":1}
sysmon:
true
time:
1782973380973064

这个是其中的日志，为什么会出现这个问题，持续出现这个问题会导致什么问题，如何解决呢？

4

我只能告诉你，字面意义上，这就是Erlang调度器忙不过来了，如果需要更深入的话，你可以找一找Erlang调度器相关的内容。

timeout:299 表示这个连接进程在调度器上被延迟到接近 300ms，超过 5.8 默认 240ms 阈值，所以 sysmon 打了 long_schedule。
你贴的这条 message_queue_len:0、memory:110248，不像单个连接进程堆积；更像压测期间 CPU/调度资源不够，或者 Pod 被 K8s CFS throttle。

持续出现会有实际影响：

收发包延迟变大，PINGREQ/Keepalive 处理变慢，连接建立和重连抖动，严重时客户端会误判超时然后断连重连，进一步放大压力。

large_heap 是另一条线。它说明某个 Erlang 进程堆超过阈值，要看那条 large_heap 日志里的 registered_name、current_stacktrace、message_queue_len、total_heap_size。如果是 rule/bridge/broker 相关进程持续增长，再按规则、桥接、订阅 fan-out 去拆。

如果你的业务对300毫秒完全无感知，可以将该阈值调大以屏蔽掉；如果业务已产生感知，则需增加硬件资源或降低压测强度。当触及到硬件的限制时，EMQX 测就已经没有太多的参数可以再调优了。