90% 开发都会忽略的性能调优点:针对返回大数据量的接口,10 分钟内找到提升带宽瓶颈的突破口

01 问题现象
前几天小编居家远程办公,在测试环境访问某返回 3.4M 数据的接口,响应速度远不如预期。一开始怀疑是用远程用 vpn 连接访问导致的。但回到公司之后,我再次通过内网多次访问该接口,响应时间依然不理想,在 600~700ms 左右,最快也需要 500ms 多。但办公室带宽 100M,打满带宽所需耗时为 3.4MB / (100MBit/s / 8) = 272ms,这里面存在至少 200 多 ms 的时间缺口,是什么原因导致的?又该如何调优?
02 常见但易被忽略的类似场景
我们可能从来没有注意到一个事情:在实际生产环境访问大数据量的接口时,我们自然而然地认为响应速度相对慢些是正常的,但真的完全是因为返回报文太大的缘故吗?现在的带宽大都是百兆,服务器之间的带宽更是上千兆,而往往查询十几 M 的数据也要几秒钟,这里面还有没有可调优的缺口?
我们突然意识到,如果能排查出该慢请求背后的根因,找到调优方法,这可能会对众多开发者提升生产环境接口的性能产生很大的价值和参考意义。
03 初步排查
我们用程序摄像头 Trace Profiling 捕捉了该慢请求,trace 的 span 信息如下:

我们发现该接口真正处理业务的时间只有 58.78ms,看来我们需要重点分析 2 处的 500ms 系统在干嘛?
点击 span 信息,从底层视角,查看线程事件分析:

我们发现,在 2 处,系统在 netwrite 写回报文给客户端的时候,发生了很多 lock 事件占用了大部分耗时。既然系统已经开始 netwrite 了,那我们可以断定这部分高耗时就是网络传输的原因导致的。再点击 lock 事件,查看具体堆栈信息:

可以看出这是 tomcat 的 nio 阻塞住了,这也再次佐证了我们的推测。
04 进一步排查
我们排除了硬件等网络资源问题,基本就可以定位问题就是在服务端与客户端的传输上。但是具体原因是什么呢?我们切换到程序摄像头 Trace Profiling 的复杂视图页面(简易视图仅展示工作主线程,复杂视图展示本次请求所有相关线程),通过查看与网络传输相关的线程事件,看看能不能找到进一步的线索:

我们发现,在主线程 lock 住的时候,tomcat 里的 poller 线程刚好在做 epoll(即线程在查询系统内核文件描述符的读写状态),通俗点来讲就是,主线程往客户端写回报文,被阻塞 lock 住的时候,poller 线程正好在帮主线程查询系统内核态是否可写。我们由此可推测,该慢请求是由于客户端接收数据窗口的 buffer 不够,导致服务端向其传输报文时,总是不可写,从而引发了阻塞等待。(有疑问的同学可以百度 Tomcat nio 原理、TCP 网络传输协议等相关知识,或添加文末小编微信,共同探讨)
上述结论推导可能需要开发者有一定的计算机网络基础知识和经验,考虑到这一点,Kindling 开源团队目前也已用探针采集到了每次慢请求对应的网络关键指标,比如 RTT、丢包率、TCP Window Full 等,后续程序摄像头的迭代发布时,会将这些指标关联到 Trace 上,效果如下图:

这样的话,比如就本次慢请求而言,当我们看到 TCP Window Full 数值较大,而其他指标无异常,我们果断能推断,客户端的接收窗口 buffer size 过小,导致它经常发生 Window Full。相对而言,当经验不足的开发者排查该问题也能简单很多。
05 实验论证
我修改了我自己这台电脑的 socket 接收缓存 buffer 大小,默认是 128k,调到了 4M,再次访问这个返回 3.4M 数据的接口,响应时间提升至 365.91ms,其中,向客户端传输报文的时间是 308.64ms,已经接近于 100M 带宽下的理想时间 274ms(Wifi 办公场景下存在网络存在抖动和占用)。

为排除其他因素的影响,我们再次使用服务器进行测试,继续用程序摄像头 Trace Profiling 捕捉分析请求,服务器间网络带宽为 1GB,多组实验结果如下:
06 总结
通过多组实验对比,显然,接口返回报文的速度并不是随着接收端 socket buffer 的大小成线性正比,这其中牵涉到 TCP 传输协议的算法逻辑,感兴趣的同学可以继续深入了解,或者添加小编微信共同探讨。当然,也不能将其盲目调到很大,这可能会给接收方造成处理压力,反而适得其反,大家可以借助程序摄像头 Trace Profiling 做实验,结合自己的业务场景合理调整。
我以前是一名普通开发,对于生产环境出现的网络传输、CPU、多线程等等问题都不太会排查,这对于我来说太高阶了。尤其当无法通过日志、本地复现、debug 等手段查出来的时候,我每次都只能求助 leader 或者架构师,更别说做性能调优,我能保障我负责项目的无故障运行就谢天谢地了。但是我也知道如果无法攻克这些问题的话,我永远只能当一名普通开发。
很多像我一样缺乏经验的普通开发,用市面上常见的的 Trace 追踪工具去排障、调性能,是存在很大的门槛的。对于异常 Trace,这些工具只能看到基础的耗时分析,但为什么花了这些时间,系统内核底层到底做了什么事情,问题的根因在哪儿,是回答不出来的。程序摄像头 Trace Profiling 就是为了帮开发者解决这一痛点而生,它通过线程事件分析,真实还原请求执行现场,实现分钟级定位全资源种类故障的根因,降低对专家经验的依赖。
以标准化流程,分钟级定位全资源种类故障的根因
kindling 开源团队,公众号:Kindling 云可观测程序摄像头Trace Profiling:生产环境10分钟黄金时间快速排障手册
CPU 分钟级快速排障实战
kindling 开源团队,公众号:Kindling 云可观测生产环境10分钟黄金时间快速排障:CPU不定时飙高怎么排查?
对本次实验感兴趣或想了解更多程序摄像头 Trace Profiling 的小伙伴可以添加小编微信:Xieyun-kindling

Kindling 官网:
http://kindling.harmonycloud.cn/
GitHub:
版权声明: 本文为 InfoQ 作者【KINDLING】的原创文章。
原文链接:【http://xie.infoq.cn/article/36fcc6706ace9c3603801ba56】。
本文遵守【CC-BY 4.0】协议,转载请保留原文出处及本版权声明。
评论