Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

服务端latency统计时间可能有误 #2437

Closed
FancyJan opened this issue Nov 1, 2023 · 7 comments · May be fixed by #2886
Closed

服务端latency统计时间可能有误 #2437

FancyJan opened this issue Nov 1, 2023 · 7 comments · May be fixed by #2886

Comments

@FancyJan
Copy link
Contributor

FancyJan commented Nov 1, 2023

Describe the bug (描述bug)
写一个简单的client去压测单机server，获取如下两个指标：
client耗时：通过brpc::Controller::latency_us()获取
server耗时：通过bvar中的对应latency bvar获取

之前我们使用的版本是0.9.7，client侧耗时会明显大于server耗时，符合预期
最近升级到了1.5.0版本，client侧耗时基本不变，但是server侧耗时明显高于之前，甚至大于client侧耗时。
因此怀疑server端的耗时在新版本内有问题。

看了下用于计时的ConcurrencyRemover的逻辑并没有明显修改，
这块还有什么别的排查思路吗？Appreciate any help

To Reproduce (复现方法)
补充细节：
client就是简单的client，请求来自rpc dump采集，单线程使用同步接口去重复发请求。
server是我们的生产代码，特点是：会使用bthread做一些并行计算；使用了brpc的session_local_data。
client和server压测，正常负载下均可以复现

Expected behavior (期望行为)
在新版本中，client侧耗时不应该小于server耗时，预期会有明显的gap

Versions (各种版本)
OS:
Compiler:
brpc:
protobuf:

Additional context/screenshots (更多上下文/截图)
这里看的bvar统计就是取前几分钟的值，基本可以排除指标抖动影响
@Huixxi
Copy link
Contributor

Huixxi commented Nov 26, 2023

可以贴点数据出来么？

@FancyJan
Copy link
Contributor Author

FancyJan commented Nov 26, 2023 •
edited
Loading

可以贴点数据出来么？

客户端耗时（cntl->latency_us()）：
rpc_replay_latency : 59729
rpc_replay_latency_9999 : 112963
rpc_replay_latency_cdf : "click to view"
rpc_replay_latency_percentiles : "[68928,72482,112963,112963]"
rpc_replay_max_latency : 112963

服务端耗时：
rpc_server_6001_xx_service_search_concurrency : 1
rpc_server_6001_xx_service_search_count : 173520
rpc_server_6001_xx_service_search_eps : 0
rpc_server_6001_xx_service_search_error : 2
rpc_server_6001_xx_service_search_latency : 68115
rpc_server_6001_xx_service_search_latency_9999 : 121424
rpc_server_6001_xx_service_search_latency_cdf : "click to view"
rpc_server_6001_xx_service_search_latency_percentiles : "[81217,85360,121424,121424]"
rpc_server_6001_xx_service_search_max_concurrency : 10000
rpc_server_6001_xx_service_search_max_latency : 121424
rpc_server_6001_xx_service_search_qps : 10

可以看到server端的rt要明显比client侧要长

@Huixxi
Copy link
Contributor

Huixxi commented Nov 26, 2023

问下 有对应的0.97版本的耗时数据么

@FancyJan
Copy link
Contributor Author

FancyJan commented Nov 26, 2023 •
edited
Loading

问下 有对应的0.97版本的耗时数据么

看了一下升级前0.9.7的指标：
side avg 95% 99.9%
client 85.45 133.5 224.61
server 77.63 121.5 200.61

升级后1.0.5的指标是：
side avg 95% 99.9%
client 87.23 135.91 225.31
server 96.05 151.71 238.21

由于一些外部依赖可能导致时延的绝对值有波动，但是大小关系还是明确发生改变了

@FancyJan

This comment was marked as outdated.

Sign in to view
@Huixxi
Copy link
Contributor

Huixxi commented Nov 15, 2024

这个后来弄明白了，这块的逻辑在baidu_rpc_protocol.cpp的SendRpcResponse。 bvar中的latency是在ConcurrencyRemover析构的时候统计，但是由于析构顺序需要等req和res先析构完再统计，导致这里的时间比实际发送出去的时间要长。

所以是不是bvar这里的上报逻辑需要优化一下。

@FancyJan
Copy link
Contributor Author

FancyJan commented Nov 15, 2024 •
edited
Loading

这个后来弄明白了，这块的逻辑在baidu_rpc_protocol.cpp的SendRpcResponse。 bvar中的latency是在ConcurrencyRemover析构的时候统计，但是由于析构顺序需要等req和res先析构完再统计，导致这里的时间比实际发送出去的时间要长。

所以是不是bvar这里的上报逻辑需要优化一下。

刚刚加了个打点看了下析构应该不是很耗时，问题不大。之所以有这么大差异的原因是业务引入了这个变更：https://github.com/apache/brpc/pull/2328/files#diff-1c912dfbdb9b39d5f50ed77e1a415829bf908666ee98226bf60d138f507242e6
这个会导致bvar的统计多计入用户回调的时间，这个时间是比较长的。
可以考虑把ConcurrencyRemover最后声明，这样获得的latency就比较准了。

@chenBright chenBright mentioned this issue Jan 29, 2025
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Optimize server latency chenBright/brpc
2 participants
@Huixxi @FancyJan