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

[FancyJan]

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]

可以贴点数据出来么？

[FancyJan]

可以贴点数据出来么？

客户端耗时（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]

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

[FancyJan]

问下 有对应的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]

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

[Huixxi]

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

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

[FancyJan]

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

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

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