Java内存泄漏、性能优化、宕机死锁的N种姿势( 三 ) _Java

jaeger是Uber开源的一个基于Go的分布式追踪系统。jaeger基本原理是：用户在自己代码里插桩，并上报给jaeger ， jaeger汇总流程并在UI显示。非生产环境可安装jaeger-all-in-one[3] ，数据都在内存里，有内存溢出的风险。在需要追踪的服务的启动脚本里export JAEGER_AGENT_HOST={jaeger服务所在的host} 。
下图为jaeger的UI ，显示一次完整的流程，左边为具体的插桩名称，右边为每块插装代码耗时，可以看到最耗时的部分在including leader create container和including follower create container ，这部分语义是leader创建完container后，两个follower才开始创建container ，而创建container非常耗时，如果改成leader和两个follower同时创建container ，则时间减少一半。

文章插图

tcpdumptcpdump常用来抓包分析，但也能用来优化性能。在我们的场景中，部署Ozone集群（下一代分布式对象存储系统），并读数据，结果发现文件越大读速越慢，读1G文件，速度只有2.2M每秒，使用perf未发现线索。

文章插图

用命令tcpdump -i eth0 -s 0 -A 'tcp dst port 9878 and tcp[((tcp[12:1] & 0xf0) >> 2):4] = 0x47455420' -w read.cap ，该命令在读200M文件时会将所有GET请求导出到read.cap文件，然后用wireshark打开read.cap ，并过滤出HTTP协议，因为大部分协议都是TCP协议，用于传输数据，而HTTP协议用于请求开始和结束。
从下图的wireshark界面，可看到读200M文件，共有10个GET请求：GET /goofys-bucket/test.dbf HTTP/1.1 ，每个GET请求读20M文件，每个GET请求读完后回复：HTTP/1.1 200 OK 。第1个GET请求到达S3gateway时间为0.2287秒，第10个GET请求到达Ozone集群时间为1.026458秒。第1个GET请求完成时间为1.869579秒，第10个GET请求完成时间为23.640925秒。
可见10个GET请求在1秒内全部到达Ozone集群，但每个请求耗时越来越长。因此只需要分析后续的GET请求读同样大小的数据块，比前序GET请求多做了哪些事情即可。

文章插图

最后通过分析日志和阅读代码发现， Ozone采用的第三方库commons-io采用read实现skip 。例如读第10个GET请求时，实际只需要读[180M, 200M) ，但commons-io实现skip前180M时，会将前180M读出来，导致第10个GET请求读完整的[0M, 200M) ，因此GET请求越来越慢。优化后，性能提升一百倍。
jstackjstack用来查询线程状态，但在极端情况下也可以用于性能优化。在部署服务时，发现进程迅速占满所有CPU ， 24核的机器进程使用CPU达到2381% 。

文章插图

CPU使用如此之高，无法运行arthas进行perf分析，只能采用其他策略。首先用top -Hp pid命令打出进程pid的所有线程及每个线程的CPU消耗。如下图，第一列PID为线程号， %CPU列代表CPU消耗，注意该图只是展示作用，该图的进程并不是使用CPU达到2381%的进程，原进程的信息当初没保存。

文章插图

然后计算出使用CPU最高的线程号的十六进制表示0x417 ，再用jstack -l pid > jstack.txt命令打出所有线程状态，用0x417在jstack.txt查询消耗CPU最高的线程，即下图所示ThreadPoolExecutor里的线程，该线程一直处于RUNNABLE ，且队列为empty ，基本确认该部分线程出了问题，因为正常的线程不会一直空转，状态会有TIMED_WAITING的时刻。
因为线程堆栈不包含业务代码，都是JDK的源码，因此用线程堆栈搜索JDK相关问题，最终发现是JDK8的Bug：JDK-8129861 ，该Bug在创建大小为0的线程池时容易触发，因此在应用代码里，将大小为0的线程池修改即可。