JAVA疑难问题排查、解决经验总结（Linux系统）

Java疑难问题的排查、解决有一定的步骤可循。大概就是程咬金的三板斧。按照对应的步骤对着问题砍下去，很多问题就都迎刃而解了。接下来，就根据个人的理解和经验将几类问题的解决步骤总结一下。

1 先排查运行环境
首先要强调的是，有些问题不是疑难问题，或是伪疑难问题。其实就是些运行环境的问题，磁盘空间、内存大小、CPU占用、数据库连接、用户权限等问题。如果有人向我反馈某个软件启动不了、启动后运行很慢、启动了但整体功能都不正常等问题，首先会使用df -h命令查磁盘空间，使用free -m命令查内存使用情况，使用top命令查看CPU占用情况，使用mysql命令登录数据库show processlist命令查看数据库连接情况。不要以为这样做无意义。通过这些命令解决了问题，就知道这样做多重要。比如说磁盘满了的问题，一般是软件开始时运行是正常的。但是过了一段时间，比如几个月或几年，突然就出现运行慢、重启不了等怪问题了。

某年春节过后，四川移动报告MA（媒资）系统运行异常缓慢。登录到MA服务器排查，发现MA服务器一切正常。由于MA需要数据库，而数据库在另一台服务器上。先使用mysql命令登录数据库show processlist命令查看数据库连接情况。发现有大量链接处于“query end”状态。上网搜索“mysql query end”，说有可能是磁盘空间满了。然后登录数据库服务器，使用df -h命令查磁盘空间，果然满了。Mysql做同步时，会产生大量的二进制日志。不及时清理就会造成磁盘空间占满。Mysql的配置expire_logs_days，可以设置保留日志的天数。设置为30，就不用再为Mysql的日志过多而苦恼了。

从上面的例子可以看出，这些运行环境引起的问题，排查和解决都不难。这类问题解决的重点是要往运行环境上想。如果不查环境，而是看软件日志、查源码什么的。看了大半天也看不出问题。然后才想起查一下环境。然后发现果然是环境问题。那不是要吐血。

但是问题来了，什么样的问题是运行环境引起的问题呢？被定位了是运行环境引起的问题，就是运行环境引起的问题。也就是说运行环境引起的问题没什么特别的现象。所以正如前面强调过的，遇到整体性的软件问题，先查一下环境。

2 应用的CPU占用过高问题
这种问题的定位过程，网上说的比较多。对一般情况，本文只简单列一下定位过程。1、使用top命令查询出CPU使用率较高的进程ID。2、使用top -H -p 进程ID -c命令查询出CPU使用率较高的线程ID，注意是线程ID。一般情况只会有一个线程的CPU使用率较高。3、使用JDK带的jstack 进程ID >> java.txt命令，查出java进程的线程栈方法调用、运行情况。这个命令的结果记得要保存到文件中，而且最好重复三次，保存到3个文件中。4、由于文件中的线程号是十六进制，需要将第二步得到的线程ID转为十六进制，然后在文件中搜索，找到对应的线程栈信息。查看对应的方法调用、运行情况。大概都是应用不小心死循环了、排序算法效率不高、从数据库获取的数据太多等问题引起。

这种一般问题还是比较好定位的，解决的难易，就只能各由天命了。下面说说不一般的情况。上面第二步提到，一般情况只会有一个线程的CPU使用率较高。如果是好几个线程的CPU使用率不是特别高，但是几个加起来就很高的情况，怎么办？如某个Java进程CPU使用率达200%，而查线程时发现，前5个线程的CPU使用率都是30%多。这种情况，我只遇到过一次。我不清楚是否还有其它原因会导致这种情况。在这里，将我遇到的问题的定位、解决描述一下，其它情况用这个思路估计也有帮助。

2017年元旦后上班，发现公司有一台服务器上的tomcat进程占用CPU很高。重启tomcat也不行。使用top -H -p 进程ID -c命令查询，发现有好几个线程的CPU使用率比较高。后来测试也发现别的服务器有此现象。现场客户那里也发现了相同现象。用strace -p 进程ID命令查询系统调用，结果如图：

这种情况在网上搜了半天也没有眉目。把截图发到了公司的大群里问，有人遇到过是闰秒造成的。查了一下，果然在2017年1月1日，闰秒了。重启服务器可以解决。如果不想重启服务器，执行/etc/init.d/ntpd stop; date -s now。

3 内存泄漏和内存溢出
轻微的内存泄漏一般不宜察觉。内存泄漏较严重，会造成应用速度变慢。更严重的就会造成内存溢出。黑龙江联通现场反馈某市的EPG响应超时较多，希望研发排查。登录到服务器检查运行环境正常。使用jstat -gc 进程ID命令查看堆内存占用情况，发现年老代内存使用率达近100%（OC和OU分别是年老代空间大小，和年老代已占用空间大小）。

jstat -gc 8052

S0C S1C S0U S1U EC EU OC OU PC PU YGC YGCT FGC FGCT GCT

138240.0 139392.0 0.0 0.0 769280.0 763627.3 5265408.0 5265408.0 262144.0 76198.7 851 135.059 16336 263263.054 263398.112

但是每次全量GC后，回收内存较少，还是90%多。初步判断是内存泄漏。使用jmap -histo 进程ID查看JVM中的对象数量和占用内存情况，如下：

num #instances #bytes class name

---

1: 40537430 1621497200 java.util.concurrent.ConcurrentHashMap$Segment

2: 40543201 1297382432 java.util.concurrent.locks.ReentrantLock$NonfairSync

3: 40537430 989891192 [Ljava.util.concurrent.ConcurrentHashMap$HashEntry;

4: 5617075 553873688 [C

5: 7661447 245166304 java.lang.String

6: 2531665 222786520 org.apache.catalina.session.StandardSession

7: 2533600 202687328 [Ljava.util.concurrent.ConcurrentHashMap$Segment;

由于篇幅问题，没有贴出全部，只贴出问题相关的部分。从这段数据来看，内存占用排第一的对象是ConcurrentHashMap$Segment，这个其实就已经很不正常了。正常情况都是[B、[C、String、[I这些排在前面。而现在ConcurrentHashMap$Segment排在第一位，说明某个对象中有ConcurrentHashMap$Segment类型的变量。这个对象不能释放，导致ConcurrentHashMap$Segment越积越多。接着向下看，发现StandardSession对象排在第6位，对象数有253万个。这个是不正常的，应用中保留的Session太多了。查看StandardSession源码也发现，其确实有ConcurrentHashMap类型的变量：protected Map<String, Object> attributes = new ConcurrentHashMap();。看来问题就出在Session身上。查看tomcat的web.xml文件发现，设置的Session超时时间是24小时，这个太长了，改为2小时。同时了解到，客户端访问EPG时，没有带SessionID。导致每个请求，EPG服务器都会创建一个新的Session。

现在这个问题基本上是定位清楚了。但是现实的复杂总是超出你的想象。重启Tomcat，使用jmap -histo 进程ID查看JVM中的对象数量和占用内存情况。发现StandardSession对象还是200多万个，后来逐渐减少。预期情况是重启后StandardSession很少，后来逐渐增加。由于设置里2小时超时。后面GC时，就会释放掉一部分。最大数应该在20万左右。实际情况和预期完全不符。于是又上网搜索了Tomcat的session相关，才知道Tomcat有个配置控制是否持久化session，以防止重启Tomcat使session丢失。Tomcat默认是已经启用持久化配置，若要禁用持久化功能，则只需要在cof文件夹context.xml的节点里配置。

内存溢出分两种，堆内存溢出（java.lang.OutOfMemoryError: Java heap space）和永久层内存溢出（java.lang.OutOfMemoryError: PermGen space）。上面举的例子是堆内存溢出。永久层内存溢出是启动JVM时没有调整JVM永久层内存大小时，经常发生。一般永久层内存大小默认是64M。如果JVM启动时，加载的类较多，占用内存大小超过64M，就会造成永久层内存溢出。通过调整JVM的启动参数-XX:PermSize、 -XX:MaxPermSize，可以解决这个问题。这种情况之前经常碰到。现网在某个新服务器上安装Tomcat时，现场操作人员经常忘记调整JVM的启动参数。然后就会向研发抱怨应用启动不了，或启动了但运行很慢。现在现场操作文档中增加了调整JVM启动参数的步骤。这种问题几乎就没有了。

有的时候堆内存溢出是由于应用一次性从数据库加载数据过大，构建对象过多造成。这种情况就要具体问题，具体分析了。

4 CPU高，内存占满
黑龙江现场反馈EPG程序访问无应答。远程登录服务器，查看EPG的java进程CPU使用率达100%。top -Hp 进程ID，查看有一个线程的CPU使用率尽100%。使用jstack 进程ID>>1.txt命令导出java堆栈，查看对应线程是GC线程。这说明java在拼命回收内存。使用jstat -gc 进程ID命令查看内存使用情况，发现OC（年老代内存大小）、OU（年老代内存已使用大小）相等，内存果然被用光了。

通过以上信息，可以断定内存用完，java启动GC线程回收内存。但是由于内存对象都是活动状态，导致回收不掉。这个就出现了CPU高，内存占满的情况。CPU高不是主要问题，内存占满才是。内存占用率降下来，CPU使用率自然就会降下来。下面的工作就是找出内存占用率高的原因。

使用jmap -histo 进程ID命令查看java内存中的对象分布情况。如下（部分）：

num #instances #bytes class name

---

1: 18906326 1570239408 [C

2: 32879762 1415144440 [B

3: 25681574 821810368 java.util.HashMap$Entry

4: 7871687 639239680 [Ljava.util.HashMap$Entry;

5: 18972768 607128576 java.lang.String

6: 7863275 377437200 java.util.HashMap

7: 10942392 350140768 [[B

8: 10937478 262499472 com.mysql.jdbc.ByteArrayRow

9: 101997 87368360 [Ljava.lang.Object;

10: 57416 32392712 [I

从这个数据可以看出，[C和[B分别占了1.5G和1.4G，太多了。Java内存一共才5G。接着向下看com.mysql.jdbc.ByteArrayRow排在第8位，这个很不正常。ByteArrayRow是数据库查询时生成的对象。在前面导出的java堆栈文件1.txt中搜索ByteArrayRow，找到了好几处。都是查询连续剧剧头和分集对应关系的方法。使用mysql客户端登录mysql数据库，统计剧头和分集对应关系的数据有42万条。

排查到这里问题的原因已经很清楚了。剧头和分集对应关系的数据量较大，而且同时被调用了好几次。导致大量数据停留内存。Java虚拟机发现内存耗光，启动GC回收。由于都是活动对象，无法回收掉。

解决办法：之前想法是将剧头和分集对应关系全部查出，然后缓存起来，以便使用。现在看来数据量较大，不应该一次性全部查询出来。而且从应用场景看，这个关系不会全部都用到，只会用到极小的一部分。现改为按分集contentid查询对应关系，按需查询，并且缓存起来。这样数据量很小，而且很快。改好后，测试验证，没有问题了。

5 事务因超时而回滚
用媒资（MA）和某内容提供商对接C2注入。当只注入一两个C2工单时，一切正常。当一次注入十个工单时，MA日志里开始报错，同时Jboss的server.log中有数据库连接异常的记录。这是个怪问题。

研究了几个小时的日志和异常。发现每次都是工单下发后5分钟左右出现报错和异常。于是猜想可能跟某种超时有关。网上搜索了Jboss和时间相关的一些设置，果然有收获。Jboss的/server/default/conf下的jboss-service.xml中有TransactionTimeout（事务超时）配置项，默认是300秒，正好是5分钟。是由于开启了事务，但是5分钟内没有提交，导致超时。但是Jboss的server.log中抛数据库连接异常，这个异常对问题的定位帮助实在不大（还有误导的嫌疑）。有查看了MA日志，MA发送C2工单给内容提供商后，发现这个内容提供商返回响应居然要一分钟还多。这就很好解释了，为什么一两个C2工单正常，十个时就有问题。

解决办法就是要求对方提高响应速度。一个工单应该不到一秒钟才对。

6 JBOSS7的数据库驱动程序加载
由于现场需求，需要将在JBOSS5上的应用迁移到JBOSS7上。其它都还顺利，只有Mysql的数据库驱动程序一直无法加载，报链接数据库错误。网上搜索到了很多种方案。一一都试了，还是无效，搞了好几天。最后研究了一下java加载数据库驱动程序DriverManager的源码。发现可以通过设置启动参数打印日志。打印日志发现其实JBOSS7加载了好几个Mysql的驱动程序。但是由于JBOSS7有模块隔离的特性，导致java判断这些驱动和应用的加载类不是同一个，而不能使用。需要修改对应的module.xml文件，增加对Mysql驱动的依赖即可。由于应用使用了hibernate，所以在$JBOSS7_HOME/modules/org/hibernate/main/module.xml文件的后增加。保存后重启JBOSS7，链接数据库正常了。

7 数据库慢查询紧急解决办法
某现场报应用运行很慢，登录都要好几分钟。检查应用运行环境，一切正常。这个现场有个特殊情况是好几个应用的数据库都放到了一台数据库服务器上。使用mysql命令行客户端登录到数据库服务器的mysql上，使用show processlist查看。发现另一个应用的查询命令执行了十几分钟了，还在执行。这是非常不正常的。这个慢查询占用大量服务器资源，导致其它链接的查询变得很慢。其实查询超过一秒的，就算很慢了。

因为是现场应用，需要快速恢复，所以要kill掉慢查询的链接。先使用show full processlist命令，查询出慢查询的全部sql语句，并保存到文件中。然后使用kill 链接ID命令，杀掉慢查询的链接。链接ID就是show processlist命令中的Id列。注意，这个kill不是linux操作系统的，而是Mysql的，要在Mysql的命令行下运行。杀掉这个慢查询的链接后，所有的应用的运行速度都正常了。

8 FGC造成应用停止
对于要求实时响应客户请求的应用，JVM的FGC，会停止应用（stop-the-world）。这会造成用户请求超时。可以通过增加如下参数，将JVM年老代的GC改为CMS并发收集。

-XX:+UseConcMarkSweepGC -XX:CMSFullGCsBeforeCompaction=2 -XX:+UseCMSCompactAtFullCollection -XX:CMSInitiatingOccupancyFraction=70

-XX:+UseConcMarkSweepGC 设置年老代为CMS并发收集。并行GC方式在进行Full GC时，会停止整个应用，会造成外部请求无响应的情况。此CMS并发GC方式可减少应用的暂停时间，主要适合场景是对响应时间的重要性需求大于对吞吐量的要求。

-XX:CMSFullGCsBeforeCompaction=5 由于CMS并发收集器不对内存空间进行压缩,整理,所以运行一段时间以后会产生"碎片",使得运行效率降低.此值设置运行多少次GC以后对内存空间进行压缩,整理.

-XX:+UseCMSCompactAtFullCollection 在FULL GC的时候， 对年老代的压缩

-XX:CMSInitiatingOccupancyFraction=70 年老代内存使用率到70％后开始CMS收集

这里需要强调的是，这样设置并不是将FGC变为了CMS，FGC还是存在的。如果JVM判断有必要的话，还是会启动FGC。Tomcat的某些版本有个设置，每隔一个小时调用一次System.gc()，这个会触发FGC。可使用如下操作之一：

1、增加JVM参数-XX:+DisableExplicitGC，这个参数会使显示的调用System.gc()空转，不会执行垃圾回收

2、不增加JVM参数-XX:+DisableExplicitGC，换成增加-XX:+ExplicitGCInvokesConcurrent，使FULL GC使用并发垃圾回收器CMS，提高回收效率（CMS并发GC，stop-the-world时间较短）

3、修改server.xml配置，gcDaemonProtection参数改为false，默认是true

<Listener className=“org.apache.catalina.core.JreMemoryLeakPreventionListener”

gcDaemonProtection=“false”/>

4、修改server.xml配置，去掉JreMemoryLeakPreventionListener监听器

9 其它一些问题
1).Java Integer(-128_{127)使用==或equals比较，都会返回true。不在这个范围的，如Integer（200）使用equals返回true，使用==返回false。原因是Java预建了-128}127的int变量。在这个范围内都会使用这些预建的，所以都会返回true。超过这个返回就会新建对象，所以==返回false。所以Integer之间判断是否相等，使用equals最保险。

2).SimpleDateFormat不是线程安全的。多线程情况下，如web，一个请求就是一个线程，使用同一个SimpleDateFormat会报错（也不是每次都报错，概率比较低的。）。解决办法是不使用同一个。每个线程要格式化日期时，自己新建一个SimpleDateFormat对象。

3).集合中的对象要排序时，一定要在对象都放到集合中后再排序。不要在向集合中放对象的循环内写排序语句，效率会非常差。可以考虑TreeSet，其底层使用的是红黑树算法，边放入变排序，效率很高。

4).Tomcat/webapps目录下相同工程的目录应该只放一个。之前遇到过，现场维护人员为了方便，直接将备份放到Tomcat/webapps目录下，导致各种功能异常。定位起来还挺费劲。

10 sql语句调优
1).EPG系统中的相似性推荐接口，是以某个内容为依据，返回这个内容同栏目下的其它内容。写sql语句时，开始使用的是exist关键字，片段如下：WHERE m.mediaType = ? AND (m.contentId > ? OR m.contentId < ? ) AND m.status = 12 AND EXISTS (SELECT 1 FROM minimetadata_category mc1 WHERE mc1.contentId = m.contentId AND EXISTS(SELECT 1 FROM minimetadata_category mc2 WHERE mc1.category_id = mc2.category_id AND mc2.contentId = ?))。

这里使用了两个exist关键字，实际测试发现效率较差。1万条数据时，要3秒多。改成了使用left join，片段如下：left join minimetadata_category mc1 on mc1.contentId = m.contentId left join minimetadata_category mc2 on mc2.category_contentId = mc1.category_contentId WHERE m.status = 12 AND m.mediaType=? AND m.language = ? AND mc2.contentId = ? 。

这里同样使用了两个left join，1万条数据时，要0.1秒左右，效率提升很明显。Sql中的in、not in、exist、not exist关键字，如果数据量不大，如几百条，可以使用。如果数据量上万，最好用表连接代替。

2. .某现场要求内容能按黑白名单过滤。测试数据是1.5万。开始使用内连接，效率较差，要4秒多。内连接调整手段较少，改为左连接，在WHERE中过滤掉多余数据。WHERE的过滤条件开始时是validData.contentId is not null。效率和内连接差不多。改为validData.contentId is null，所用时间变为0.2秒左右。这样得到的数据，和想要的数据是相反的。不过，这至少说明，修改过滤条件可以提高效率。在过滤条件上做了一些尝试，最后选择了ifnull( validData.contentId,1) != 1。所用时间在0.5秒左右，效率基本达标。

为什么内连接查询效率这么慢？自己研究，也在网上搜索。Explain结果显示内连接时，数据库的优化器对链接表的顺序做了调整。按照这个思路使用STRAIGHT_JOIN关键字。果然所用时间也在0.5秒左右。分析了一下explain，原来mysql的优化器在安排表的关联顺序时，有时是直接按小表驱动大表来选择连接的顺序，而不管是否有索引。STRAIGHT_JOIN也不能乱用。大部分情况mysql优化器的结果都是比较好的。这次效率不好，主要是关联的表格比较多，有9个。

后记：时间在0.5秒，感觉还是有点多。Mysql中设置set profiling=1，然后查询执行语句后，执行show profile for query 1，显示converting HEAP to MyISAM 占用0.331078。这个可以通过增加tmp_table_size和max_heap_table_size这两个参数值得到优化。将这两个参数值扩大10倍（记得要设置全局的），果然查询时间缩短为0.18秒。