emqx接收消息延迟、内部转发延迟

EMQX
1

环境信息

  • EMQX 版本：4.2.14
  • 操作系统及版本：centos7.9
  • 其他 鉴权用的是 http auth插件

问题描述

500台设备每台开2个线程连接emqx发送消息，发现会存在问题：
1、emqx接收设备发送的消息的时候存在延迟的情况（开启emqx日志追踪，设备发送时间与emqx recive时间相差较大）
2、emqx内部转发存在1秒左右时间耗时情况（开启emqx日志追踪发现设备消息发送后的，recive时间和publish时间相差存在1秒的情况，我看正常的都是1ms）
3、emqx接收到后发送给其他服务端，发送后，其他服务端接收到的时间也存在延迟
以上是通过设备发送时间和日志追踪后recive和publish时间对比得到，不知道是哪里问题，耗时有时还存在10几秒情况，是不是emqx内部转发存在问题？

配置文件及日志

2 个赞
2

emqx用的是3台的集群

3

能看下你的追踪日志么？

ps1:

设备发送时间与emqx recive时间相差较大
这里要看设备的机器时间和服务器的时间是否对齐？

ps2:

是不是emqx内部转发存在问题？

这里可以追踪上 发布者，和订阅者的DEBUG日志。看发布者的 PUBLISH... 和 订阅者的 SEND ... 日志的时间差，这就是在 EMQX 内转发消耗的时间。

4

2022-03-05 20:09:57.882 [debug] <<“thing-4L751X05”>>@192.168.10.11:49126 [MQTT] RECV PUBLISH(Q2, R0, D0, Topic=eap/4L751X05/test04/event/FINAL_WELDING_SEMICELL, PacketId=58060, Payload=<<"{“body”:{\。。。。。。。。。。。。。。
2022-03-05 20:09:58.683 [info] <<“thing-4L751X05”>>@192.168.10.11:49126 PUBLISH to eap/4L751X05/test04/event/FINAL_WELDING_SEMICELL: <<"{"body\ 。。。。。。
存在这样转发耗时问题，还有1秒的，这个能怎么解决吗？

5

是不是 ACL 检查太慢了？关掉所有的 ACL 检查看看还会不会这样

6

这个是偶然的，出现的机率不大，但是存在，，一般是1ms

7

image
image1754×421 146 KB

上图 设备–>emqx—>服务器 然后返回的收发日志，这个应该是正常的，，但是存在存在好多延迟的，，有的甚至到10秒，，一般都是emqx收延迟，设备发了或者服务器发了，，但是emqx过了1秒才有recive日志。。。。。还有个问题，，能帮忙看下收的日志为什么没有recive 只有SEND PUBLISH。。。这延迟太大。。没法用了。。。

8

红色框中第一和第二行就是 EMQX 收到客户端发来的 PUBLISH 报文日志。

RECV PUBLISH ...
SEND PUBREC ...
RECV PUBREL ...
SEND PUBCOMP ...

这就是一个完整客户端到服务端的 PUBLISH (QoS2) 报文交互过程。
下面绿色框是将这个 PUBLISH 报文发送给订阅该主题客户端的交互过程。
不知道你说的 "没有recive 只有 SEND PUBLISH " 指的是？

注意到绿色框中， 时间点 55.676 与 55.677 处由客户端发送的两个 PUBRECV 报文使用了相同的 PacketId 并且打印了 warning 日志。
可以尝试抓包看一下客户端是否确实在同一时间发送了两个相同的 PUBREC 报文。

  • 如果是在同一时间发的，应该是客户端代码有问题。
  • 如果是发送一个后一段时间重发，那有可能是网络问题导致第一个报文延迟，与第二个报文同时到达了。

但大概率是前者，因为相同的 PUBCOMP 报文也几乎在同一时间收到了两个。

9

绿框中是 服务器（也可以看作客户端）收到信息后，返回给客户端的一个reply，我的理解是应该和红框中一致吧，，但是第一个不是reive（可红框一样）而第一个是SEND PUBLISH

10

红色框中是 客户端 -> 服务端 的发布流程
EMQX 的角色是接收者，所以log中是 RECV

绿色框中是 服务端 -> 客户端 的发布流程
EMQX 是作为发布者发出报文，所以是 SEND PUBLISH

在发布-订阅模型中，客户端到服务端的PUB，和服务端到客户端的PUB，是两个独立的过程。

另外这两个的 PUBLISH 报文的主题是不一样的。
似乎是启用了主题重写，在主题后面加了 reply ？

11

这个reply的主题是我们自己的服务器主动发送给emqx的一条内容为success的topic。所以我想，都是发送，为啥不一样。。

12

是发送给集群中的这个节点的吗？

13

image
image1789×508 34.4 KB

是的，是发给haproxy（3台集群）代理的，设备在这台emqx上，所以是这台设备的trace日志；
我好像发现哪里不对和这个图：
image
image631×636 62.6 KB

设备—》emqx—》服务器----》服务器发送reply主题返回----》emqx----》设备，这是个闭环，，理论上服务器发送额reply应该和设备发送的一样有recive，，，该绝 哪里理解错了。。。（重复详细确认好像确认的是服务器发送的reply主题。。。。）

14

这个地方一直存在emqx接收服务器reply延迟，，emqx发送给服务器信息 延迟的情况，，，一般 1秒 800ms 概率极大。。。

15

你这里应该是只 trace 了 thing-4L751X05 这一个 clientid 的日志？
所以 trace 中与它相关的，只有接收到它发送的 PUB 报文，和需要发送给它的 PUB 报文。
reply 消息从你的服务器发送到 haproxy ，到转发到 EMQX 的过程中，使用的是其他 clientid，所以这里的日志没有显示。

如果你的部署使用了 haproy，而 EMQX 的日志显示收到 PUBLISH 报文和发出 PUBLISH 中间的流转时间并不长。
并且 EMQX 收到报文的时间，与你的客户端发出的 reply 报文的时间差距比较大。那就应该从 haproxy 进行转发的过程中入手排查。

另外推荐一下我们的 EMQX Cloud 服务，把部署调优的事情交给专业团队，比自己部署维护方便得多，你只需要关心业务。

16

haproxy基本可以排除，因为试着直连emqx，和通过代理后测试，并没有较大改善，，，排查日志后明显的是客户端publish后，emqx recive 前，这段时间延迟。。。排查网络也没问题，，这就难解释了。。。
客户端发送看源码日志是01秒，emqx recive日志是3秒 5秒都有可能 是概率事件

17

请教下，emqx有内部的消息延迟统计工具吗（或者日志记录）？
意思就是 服务器发送消息---->emqx----->客户端订阅消息 这个路径的时间差

18

社区版/企业版 ？

我也遇到类似情况，但是是社区版本的