dubbo耗时偶尔无故增加 consumer端打印的耗时明显大于provider耗时

[wenhsh]

Environment

• Dubbo version: 2.6.1
• Operating System version:linux
• Java version: 1.8

Steps to reproduce this issue

1. 打印provider端执行耗时和consumer端调用provider耗时
2. 观察调用
3. 大概率consumer打印的调用耗时比provider端打印的耗时多跟多 已算上网络传输时间 并排查网络不存在问题 gc情况也已排除
   用的dubbo默认协议
   比如 provider端打印的执行耗时大约13ms 同机房网络约1-2ms consumer端也记录了整个dubbo调用的耗时 正常按理说consumer记录的耗时应该在15ms上下 但经常发现consumer记录的调用耗时在40ms以上 而且出现比例很高 约7-8% 这个调用改成普通http调用（不是指dubbo的http调用）后没这个现象 然后在业务低峰也是有同样的现象 说明也不是dubbo线程池或其他池相关的配置问题 初步判定是dubbo其它方面的问题 但具体原因排查没什么思路 不知各位大神有没有遇到过类型的情况 有的话麻烦请教下 谢谢

[lkj41110]

可以提供一下你统计耗时的方法么

[wenhsh]

ok，首页是提供方的代码（主业务代码我忽略了）

//provider端代码
public JSONObject getxxxx(JSONObject json) throws Exception {
	logger.info("requst parameter=" + json);

    long start = System.currentTimeMillis();
        //下面是主逻辑
    ......
        
    long end = System.currentTimeMillis();
    costLogger.info("xxx:{} costtime:{}", xxx, (end - start));

    return resultJson;
}

@Reference(version = "2.0", timeout = 100, url="dubbo://127.0.0.1:20888")//为了验证非网络原因，还特意相同一台机器直连调用
private IsssAPI isssAPI;

//consumer端调用代码
long start1 = System.currentTimeMillis();
JSONObject returnObject = isssAPI.getxxxx(params);
long end1 = System.currentTimeMillis();
costLogger.info("xxx  xxx:{} costtime:{}", dto.getFuin(), (end1 - start1));

以下打印出的日志（因为一些敏感信息，重新处理了下，但耗时未处理）：
provider端：
xxx: aaaaa costtime:14
consumer端：
xxx xxx: aaaaa costtime:46

[lkj41110]

这样统计没有统计到提供者拦截器，要确认下提供者的拦截器有没有费时操作。
建议可以给提供者最外面加一个统计时间的拦截器

[wenhsh]

你这里指的拦截器是dubbo层面的拦截器吗？在整个provider端层面没有拦截器，外面直接用spring boot + dubbo启动的，而且外面spring boot的拦截器就算有，对dubbo本身的rpc调用也是不起作用的，再者，我在排查问题的过程，试着直接provider不用dubbo，直接以http restful api的方式提供，调用端调用并不会出现耗时增加很多的情况，一直都很稳定，整合耗时也比较符合 ： 请求+网络 的情况

[wenhsh]

而且耗时增加，并不是必现，约10次里面有3-4次，而且耗时增加得都比较明显

[wenhsh]

如果是最外层的拦截器，应该是必现

[lkj41110]

是的，理论上默认拦截器也不会很长的耗时的，但个人理解目前你的时间统计方式是不准确的，可能会影响排查问题。
dubbo的调用顺序是
调用方 -> 调用方拦截器 -> 网络 -> 提供方拦截器 -> 提供方统计开始时间 -> 业务
调用方 <- 调用方拦截器 <- 网络 <- 提供方拦截器 <- 提供方统计结束时间 <- 业务

提供一个思路，可以看下是不是dubbo的拦截器造成的：

调用方记录时间 -> 调用方拦截器 ->增加一个拦截器(再次统计时间) -> 网络 -> 提供方统计开始时间(增加最外层拦截器统计) -> 提供方拦截器 -> 再次统计时间 -> 业务

[wenhsh]

按你的建议，provider和consumer端都加了logFilter，并且重新调整了时间的统计和打印，以下是一个有耗时变多的一个日志：

--consumer端发起，consumer端logFilter直接加的，默认执行顺序应该是dubbo自带的default->logFilter
2019-10-24 15:55:29,346,run-async-xxx-pool-MG48j-133,costtimeLog,INFO,consumer端开始dubbo调用时间， :xxxxx, startTime:1571903729346
2019-10-24 15:55:29,346,run-async-xxx-pool-MG48j-133,costtimeLog,INFO,consumer端dubbo拦截器调用rpc前，默认顺序（即default->logFilter），xxx, startTime:1571903729346

--到了provider端，logAlgFilter有调整顺序，配置这样配的：@Service(version="2.0", filter = "logAlgFilter,default")，那么执行顺序应该是：logAlgFilter->default
2019-10-24 15:55:29,346,DubboServerHandler-xxx.xx.xx.xx:20888-thread-193,costtimeLog,INFO,provider端dubbo拦截器调用rpc前，默认顺序（即logAlgFilter->default），xxx, startTime:1571903729346
2019-10-24 15:55:29,347,DubboServerHandler-xxx.xx.xx.xx:20888-thread-193,costtimeLog,INFO,alg---xxxx-执行主业务 running time (millis) = 12
2019-10-24 15:55:29,358,DubboServerHandler-xxx.xx.xx.xx:20888-thread-193,costtimeLog,INFO,provider端dubbo拦截器调用rpc后，默认顺序（即logAlgFilter->default），xxx, endTime:1571903729358, costTime:12

--看这里provider调用返回后，耗时从12变成了41ms，请注意，我都是直连127.0.0.1，网络原因可以排除，调用配置：@Reference(version = "2.0", timeout = 100, url="dubbo://127.0.0.1:20888", filter = "logFilter")
2019-10-24 15:55:29,387,run-async-xxx-pool-MG48j-133,costtimeLog,INFO,consumer端dubbo拦截器调用rpc后，默认顺序（即default->logFilter），xxx, endTime:1571903729387, costTime:41
2019-10-24 15:55:29,387,run-async-xxx-pool-MG48j-133,costtimeLog,INFO,consumer端结束dubbo调用时间， xxx, endTime:1571903729387, costtime:41
2019-10-24 15:55:29,388,http-nio-8080-exec-1,costtimeLog,INFO,consumer端整体耗时 = 42

麻烦帮看看，是不是可以确定是dubbo的filter造成耗时增加？
还有这里有个疑问，默认情况下filter的执行顺序，开始是default->自定义filter ，那么调用完回来呢？也是default->自定义filter吗？

[wenhsh]

调用量都很小，gc方面的原因也排除，ygc和fgc次数也并不频繁，内存也充足

[wenhsh]

调大了@reference的connections长连接数后解决，connections = 5，问题解决，是因为一条长连接不够用吗？这里面的原理不是很懂，望解答下

[wenhsh]

对比了下2.6.1和2.6.3的com.alibaba.dubbo.remoting.transport.netty.NettyServer类，2.6.3设置了bootstrap.setOption("child.tcpNoDelay", true); 而2.6.1并没有，是因为此参数的原因吗？该child.tcpNoDelay主要作用是？

[wenhsh]

已确认是由于tcpNoDelay没设置的问题，可以告知一下2.6.1（包含）以下的用户，升级到2.6.3版本

[funaiy]

这个问题有确认吗？我们这边在做业务压测时，发现provider 和conusmer之间的rt相差8ms，网络是相同机房内网，确认非网络耗时 ; 数据包较小，排除序列化和反序列化的耗时；增加connections是能降低rt耗时

[takeseem]

可以确认是tcpNoDelay=false的问题，dubbo我们基本是同机房，绝大多数情况tcpNoDelay=true是最佳选择。 CAS <notifications@github.com> 于2020年3月2日周一 下午4:36写道：

…

这个问题有确认吗？我们这边在做业务压测时，发现provider 和conusmer之间的rt相差8ms，网络是相同机房内网，确认非网络耗时 ; 数据包较小，排除序列化和反序列化的耗时；增加connections是能降低rt耗时 — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#5217?email_source=notifications&email_token=ABEMGCZDDLTQO3J2XG3HUILRFNVXLA5CNFSM4JDZ44YKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOENOMPBY#issuecomment-593282951>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ABEMGC4KE33WLO3H644NZRTRFNVXLANCNFSM4JDZ44YA> .

[CrazyHZM]

No feedback for a long time, please close the issue temporarily. If there is still a problem, you can reopen it.