如何使用JDK剖析Java应用
在JDK中,我们接触最频繁的就是java和javac。其他工具,平时接触较少,看了文章也很难记住。如果单纯介绍每个工具的用途, 比较枯燥,也脱离实际,很难留下印象。刚好之前,公司的某个服务在线上出现了一个诡异的问题,本人借助jdk中的工具最终成功定位到了根本原因(root cause)。 本文以排查这个问题的过程为例,向大家介绍JDK中一些工具的作用和使用方式,以及总结从中学习到的经验教训。
线上报警
某一天,突然收到了报警,某台服务器的cpu负载过高。我第一时间登录机器,使用top命令,发现是服务A的进程导致的,而上层调用方也反馈服务A的接口有时响应缓慢,部分请求被拒绝。当时我先使用了之前部署好的脚本(后文给出)收集现场信息,然后重启服务。重启后负载就降下来了。这里我遵循了故障处理的重要原则:遇到故障时,首先保存现场环境,然后尽最大可能恢复服务。
如果没有保存现场环境,那么后面无法找到造成问题的原因。而下一步不是开始找出问题的根源,而是采取措施恢复服务。《SRE:google运维解密》一书中也提到同样的观点(参见中文版书第十二章定位这一节,P120)。书中举了飞行员的例子:
在紧急情况中,飞行员的首要任务是保持飞机飞行,相比保证乘客与飞机安全,故障定位和排除是次要的。
另一方面,服务A是多节点部署,前面使用负载均衡。因此只需要将出问题的节点从负载均衡中移除,进行重启,而不需要担心服务会中断。这说明了高可用的架构的重要性,保证了服务的质量,也让我们更从容地处理问题。
同样的问题当日又出现了几次,而且在另外一个节点也出现了。因为原因尚未找到,也是通过重启解决。而在接下来的几天,就都恢复正常了。
诡异的问题
服务A近期没有大的改动,如果是严重的bug,应该在测试环境、预发环境或者最近一次发布到线上的时候就暴露出来了。在日志中,只发现了消息队列的超时异常,一开始认为可能是消息队列服务异常导致的,但是看了消息队列客户端代码,也和消息队列的服务提供方进行沟通,并没有找到造成CPU使用率高的原因。日志中找不到线索,问题也只在当日出现了几次,后面再也没出现,看似偶现,那么如何进一步排查呢?这就必须借助当时采用的脚本保存的现场环境的信息了。
排查问题
使用jstack分析线程
当时使用了top -H 查看了导致高CPU使用率的线程,如下图所示:
如图所示,服务A的数个线程的CPU使用率相当高。那么我们如何知道这些线程在应用中是干什么的呢?这就必须借助jstack了。在脚本中的命令如下:
1
|
|
jstack将发生问题那一刻应用的线程堆栈信息保存下来了,结果如下图所示:
从图中可见,jstack的结果包含了线程的名字,状态,持有或者等待的锁等信息,而第一行中的nid则是线程id的十六进制。即将图1的pid转为十六进制,在文件中搜索,就可以找到造成问题的线程。如下图所示:
可以看到这些线程都是GC线程。假设找到的线程不是GC线程,而是图2中的线程,那么通过线程名字,我们无法知道这些线程属于哪个模块,这是一个重要的经验教训:要为所有线程池和线程合理的命名,这对定位问题十分重要。
如果没有取名,一般默认是pool-1-thread-23这样的名字。那么哪怕我们根据pid在dump文件中找到了这些线程,也不知道它们在应用中的作用。所以为线程池取名,可以帮助我们更好的定位问题。
使用jstat查看jvm指标
接下来的问题是为什么GC线程会造成CPU使用率过高。这时可以使用jstat来查看一些jvm的统计信息。脚本命令如下:
1 2 |
|
jstat -gcutil的结果如下:
jstat -gccapacity的结果如下:
上面两个图中的字段这里就不一一解释了,感兴趣的童鞋可以查看官方文档。可以看到,问题发生时应用的堆内存,不管是年轻代还是老年代,都基本耗尽了。因此JVM必须进行Full GC, 然而GC无法成功回收内存,应用就处于停滞了,同时GC线程不断尝试回收内存导致CPU上升。到这里,我们找到了导致了CPU过高的直接原因了。
使用jmap与MAT分析内存
为什么堆内存会不够呢? jmap可以用来查看堆内存中的对象数目、大小统计。脚本中命令如下:
1
|
|
结果如下图所示:
可以看到,当时应用中的Order类的实例一共有将近10万个!Order类有很多String类型的字段,因此char[]和String的实例相当多。三者占用的内存高达1.4G。对正常运行时的应用使用同样的命令,发现正常情况下内存中不会有这么多订单类实例。那为什么应用中的Order类实例突然变得如此之多呢?是因为请求量太大导致的吗?还是其他原因?这时候就可以用到剖析java应用的大杀器—jmap heap dump。脚本中的命令是:
1
|
|
jmap会把当时进程内存的详细情况dump到文件,可以使用jdk中的jhat或者VisualVM来查看。这里我们使用提供更加强大功能的eclipse MAT来查看。使用MAT打开heap dump文件,首页如下图所示:
这里我们主要使用的是dominator-tree这个功能。点击后如下图所示:
我们可以看到,排名前二的两个线程占用了超过50%的内存。我们点击展开,可以进一步查看线程内所引用的对象,如图所示:
线程内有org.apache.thrift.transport.TSocket对象,因此这是一个thrift服务的线程。而MyBatis相关的类说明线程对数据库进行了操作。其中org.apache.ibatis.executor.result.DefaultResultHandler对象基本占用了线程所有的内存,点击这个对象,如图所示:
可以看到,myBatis的查询结果里面,有多个Order对象。从这里我们可以知道是某个订单查询的thrift接口导致了问题。离真相只有一步之遥了,我们进一步查看线程中相关的类:
如上图所示,展开oracle.jdbc.driver.T4CPreparedStatement,对象中的oracle.jdbc.driver.OracleSql里的String的值就是这个接口查询数据库使用的SQL。
一看不由大吃一惊,查询的条件是把订单表的数据都查出来!怎么会这样呢?原来此订单接口的参数是一个结构体QueryParam,里面包含各种字段如orderId,uid,startData,endDate等。上层调用者可以根据设置不同的字段以获得不同结果。比如设置了orderId则是查询某个订单,设置了uid则是查询某个用户的订单。服务会根据QueryParam的字段,使用MyBatis拼装SQL的条件。但是服务犯了一个低级的错误,即没有校验参数组合有效性,当uid和orderId同时没有设置时,构造的查询语句就会查出全表数据! 恰恰上层的应用,在线上也出现了bug,在某个极端的情况下,调用接口时uid和orderId都没有设值。
至此,问题的根源已经水落石出了。解决这个问题十分简单,只需要加上参数校验,当uid和orderId都为空时直接返回错误就可以了。这个例子很好的说明了,越诡异越隐蔽的问题,往往是多个简单的错误联合起来造成的。这在安全领域更加明显,很多高危的漏洞,都是利用多个环节上存在的低级漏洞。因此提高代码质量,遵循规范,尽量杜绝低级的错误,对软件的健壮性和安全性有重要意义。
回顾与总结
简单回顾一下整个排查问题的过程:
1. 使用top -H找出造成问题的线程的pid。
2. 使用jstack的找出问题线程属于应用的GC线程。
3. 使用jstat查看应用JVM的GC指标。
4. 使用jmap和MAT分析内存,找出根本原因。
我们从中学习到的经验教训:
1. 遇到故障时,首先保存现场环境,然后尽最大可能恢复服务。
2. 服务应该采用高可用的架构。
3. 所有线程池和线程都要有合理的命名,这对定位问题十分重要。
4. 服务器必须校验请求参数的有效性。
5. 提高代码质量,遵循规范,尽量杜绝低级的错误,对软件的健壮性安全性有重要意义。
通过这个案例,我们可以看到jdk的工具十分强大,能够帮助开发人员深入剖析运行中的应用,在定位问题发挥重要作用。每个Java程序员都应该掌握和理解这些工具。