【周年福利Round4】史诗级java低时延调优案例一

  

本文字数：6799字

预计阅读时间：17分钟

◆ ◆  ◆

序章

生产环境调优往往是一件复杂又痛苦的事，互联网公司尤其严重，主要表现在

• 人员流动大，工程师往往负责的是别人留下的代码

• 单个服务内部逻辑混乱，补丁繁多

• 服务之间依赖纠缠不清

• 服务分布式部署

近期作者刚好遇到了一个问题，由于排查此问题涉及

hystrix,链路追踪,分布式服务日志搜索,http,gc,thread pool,c3p0 connection pool,jdbc驱动,netty nio,cache,finalizer,Memory Aanlysis Tool,jvisualvm,yourkit

等诸多技术和工具，个人认为是一个非常好的复杂问题排查的示例。

作者并非意图借此文传达问题的解决方案。而是希望引领读者能探索出自己解决问题的思路，因此正文将采用问答式行文。

另外，本文也指出了国内技术网站上某些非常常见的错误结论，由于cv大法(copy and paste)盛行的原因，那些错误流传甚广。任何从事高并发编程的工程师都应该避免那些常见错误。

本文的相关链接和未出现在文中但在排查问题过程中参考的文章都会在文末给出，方便读者后续研读

◆  ◆  ◆

第1章 

源于告警

最近收到告警显示，某接口偶尔有超时情况，该接口调用链路复杂，从日志作为出发点去分析有种无从着力之感，好在最近刚部署了skywalking[????注1]，通过可视化页面可看到调用链路的耗时情况。

skywalking是Apache下的链路追踪工具

上图左方是接口名，右方横线表示执行开始至结束的时间。

从上图可以一目了然的看出，a接口超时，是因为调用b接口引起。接下来通过traceId分析日志，当时的情况是，ab项目都接入了skywalking，但是b项目没有打印traceId；b项目是分布式部署的，但没有使用elk收集日志。

如何通过上述调用信息，知道此次调用路由到b接口对应服务的哪台机器？通过时间戳去筛查日志显然不是一个好主意，尤其是在日志量非常大的情况下。虽然b没有接入skywalking，但是项目之间使用http协议进行交互，traceid将会通过http协议的header传给b。b中只要打印下请求的header即可。通过研究skywalking源码可知header名称，或者可以通过日志去大致推断。最终得到，traceid会使用base64编码后在header中传递。

b项目没有接入elk，如何搜索日志，要在所有机器挨个搜索吗？作者写了个python脚本，使用多线程执行ssh远程命令，并将命令的stdout重定向到当前程序的stdout(控制台)，临时解决了此问题。

感悟:

日志是最重要的技术之一，先把日志系统做好，才能避免996

◆  ◆  ◆

第2章 

心不唤物物不至，问题终于浮出水面

请求方使用的是Apache httpClient库，处理方使用公司自研框架，底层使用netty处理http协议。

从图中看出，a接口发出请求后，一段时间后b才开始执行，这个时间差是什么原因导致的？通过日志确认，请求方提交请求时间和图中链路开始时间一致。请求方提交请求时间指调用hystrix方法或者http库api(如httpClient.execute)的时间，提交后一定会被立刻执行吗？不一定，还要看库内部使用的连接池执行请求的策略。假如连接池无空闲时任务入队等待，就会出现提交时间和请求开始执行时间有较大时差的情况。同时日志显示，处理方任务处理开始时间和图中链路开始时间一致。在为自研框架写的skywalking的agent插件中，处理方任务处理开始时间是指netty通过eventloop机制接受到完整http报文后，处理方执行该请求对应任务的开始时间。

因此把问题转换为：

• a中的hystrix任务是否在线程池队列中排队？hystrix-dashboard提供线程池实时状态查看，查看时并不繁忙，没有任务在队列中，但不排除发生超时事件时恰巧出现了排队情况。

• a中的httpClient请求是否在线程池队列中排队？没有类似hystrix-dashboard的工具可以看线程池情况，但可以借助一些其他工具。作者猜测jmx也许可以，但并没有去研究。

• b中的netty eventloop是否出现排队情况 通过查看自研框架代码，发现框架使用bossGroup，workerGroup两个线程池。workerGroup线程进行非阻塞读写的同时还要处理任务，一旦任务阻塞，则会出现请求排队的情况。这个不太合理的设计可能是个突破口。继续查看代码private int workerThreadSize = Runtime.getRuntime().availableProcessors() * 2 - 1;登录服务器查看cpu信息，2个cpu，每个12核心，每个核心2个超线程，共48个逻辑processors，那么workerGroup的线程数为48*2-1=95，实际上非常多，因此排队的情况也不太可能出现。

由于没有足够的信息分析上述情况，因此暂时放弃从此方向探索。

更深入的思考: 也可以查看skywalking源码，确认hystrix和httpclient记录起始时间。

使用grep "xxxx-xx-xx xx:xx:xx" full.log > simple.log命令导出临近时间的日志。由于作者只关注超时请求的日志，因此花费了大量时间却什么都没有发现。直到作者想查看b执行任务之前发生了什么的时候，意外发现，有将近4s的时间没有打印任何日志，这和图中超时时间吻合。该服务24小时都有大量流量，不应该出现这种情况，除非发生了gc，也就是stop the world。

1074370.765: [GC (CMS Final Remark) [YG occupancy: 1161721 K (2831168 K)]
1074370.765: [Rescan (parallel) , 0.0282716 secs]
1074370.793: [weak refs processing, 3.9080203 secs]
1074374.701: [class unloading, 0.0895909 secs]
1074374.791: [scrub symbol table, 0.0193149 secs]
1074374.810: [scrub string table, 0.0073974 secs][1 CMS-remark: 4456982K(5242880K)] 5618704K(8074048K), 4.0599904 secs] 
[Times: user=3.06 sys=1.86, real=4.06 secs]

感悟:

问题总是偶然发现的，但它似乎听到了你的呼唤。

◆  ◆  ◆

第3章  

问题已经解决？

• 使用的垃圾回收器是？

  UseParNewGC + UseConcMarkSweepGC

• 这个日志的时间戳有什么问题吗？

  这个日志使用的时间戳是当前时间和应用启动时间的差值，非常不便于排查问题，后续将添加-XX:+PrintGCDateStamps参数打印日期格式的时间戳。

• 这个日志反映了gc的什么情况？

  细心的同事从gc日志看出，weak refs processing使用了相当多的时间。作者推断WeakReference往往用于缓存。可能该问题是应用程序中的缓存导致的。(但weak refs processing真的是处理WeakReference吗？)

更深入的思考：

• WeakRefrenc