记录一个上周五的一个java服务的异常排查及分析过程，以备将来参考。

java服务的异常主要表现为3点：
1.cpu使用率高；
2.内存占用较大；
3.本机telnet访问服务被拒绝

具体情况：
1.cpu高。启动时会打到800%以上，访问量不大的时段，top看到使用率在100-400%之间，基本稳定在100%-200%左右。

2.内存高。启动后java服务占用的内存不断增大，服务器12G物理内存，增大到12*26%=3G左右时，不再增大，但服务器物理内存也已接近用尽。

3.telnet服务端口没响应。应用刚启动时，telnet 可通，但过10-20分钟左右，服务开始不响应本机测试的telnet 请求。

分析步骤：
1.定位占用cpu高的java线程。
top -H -p 21382 -d 1 -n3 > test_top_thread_20131221_12.log

通过top命令将java进程中占用cpu高的线程进行排序，并输出到文件。通过查看可以很容易的定位线程21397占用了较高的cpu和内存，分别为100.6%和物理内存的26.7%，相当异常。

2.查看该线程的执行时间。
ps -mp 21382 -o THREAD,tid,time > test_cpu_time_20131221_12.out

通过命令查询线程的执行时间，并将输出保存到文件。可以看到线程21397已经运行了13个小时左右，从服务重启到排查的时候刚好13个小时左右，说明该线程一直在繁忙，于是通过pstack看看该线程在忙啥呢。

3.通过pstack查看进程的栈信息。
【主题（java服务，cpu高，内存高，telnet不通排查及分析）】pstack 21382 > test_pstack_20131221_12.out

从pstack的输出找到对应线程的信息，如下：

Xml代码
文章图片

1. Thread 150 (Thread 0x7f3aa7fff700 (LWP 21397)):
2. #00x00007f3ae62fcdc4 in instanceKlass::oop_follow_contents(oopDesc*) () from /usr/java/jdk1.6.0_31/jre/lib/amd64/server/libj
3. vm.so
4. #10x00007f3ae64e83eb in MarkSweep::follow_stack() () from /usr/java/jdk1.6.0_31/jre/lib/amd64/server/libjvm.so
5. #20x00007f3ae65a1f14 in PSMarkSweep::mark_sweep_phase1(bool) () from /usr/java/jdk1.6.0_31/jre/lib/amd64/server/libjvm.so
6. #30x00007f3ae65a0dc1 in PSMarkSweep::invoke_no_policy(bool) () from /usr/java/jdk1.6.0_31/jre/lib/amd64/server/libjvm.so
7. #40x00007f3ae65ad927 in PSScavenge::invoke() () from /usr/java/jdk1.6.0_31/jre/lib/amd64/server/libjvm.so
8. #50x00007f3ae656f90e in ParallelScavengeHeap::failed_mem_allocate(unsigned long, bool) () from /usr/java/jdk1.6.0_31/jre/lib
9. /amd64/server/libjvm.so
10. #60x00007f3ae66ac3d8 in VM_ParallelGCFailedAllocation::doit() () from /usr/java/jdk1.6.0_31/jre/lib/amd64/server/libjvm.so
11. #70x00007f3ae66b97ea in VM_Operation::evaluate() () from /usr/java/jdk1.6.0_31/jre/lib/amd64/server/libjvm.so
12. #80x00007f3ae66b8db2 in VMThread::evaluate_operation(VM_Operation*) () from /usr/java/jdk1.6.0_31/jre/lib/amd64/server/libjv
13. m.so
14. #90x00007f3ae66b9028 in VMThread::loop() () from /usr/java/jdk1.6.0_31/jre/lib/amd64/server/libjvm.so
15. #10 0x00007f3ae66b8b2e in VMThread::run() () from /usr/java/jdk1.6.0_31/jre/lib/amd64/server/libjvm.so
16. #11 0x00007f3ae655cbdf in java_start(Thread*) () from /usr/java/jdk1.6.0_31/jre/lib/amd64/server/libjvm.so
17. #12 0x0000003a61c077f1 in start_thread () from /lib64/libpthread.so.0
18. #13 0x0000003a618e570d in clone () from /lib64/libc.so.6

可看到该线程一直在忙着VM_ParallelGCFailedAllocation::doit()，和GC的内存分配和回收有关，往下看，就更清楚了，

C代码
文章图片

1. ParallelScavengeHeap::failed_mem_allocate(unsigned long, bool)

是在分配heap空间，说明java应用的heap空间可能不足，导致GC线程一直在忙活分配新的空间。 继续看

MarkSweep::follow_stack()在干吗，查下源代码，如下：

Cpp代码
文章图片

1. // Flush marking stack.
2. follow_stack();
4. // Process reference objects found during marking
5. {
6. ref_processor()->setup_policy(clear_all_softrefs);
7. ref_processor()->process_discovered_references(
8. is_alive_closure(), mark_and_push_closure(), follow_stack_closure(), NULL);
9. }

该方法在清除已经标记的java对象，说明对象太多，才会导致GC一直在想办法清理heap，同时也说明java heap空间不足。联想到该服务对对象的创建和服务，初步分析可能是服务队列里对象太多导致出现该问题。


4.查看jvm参数配置。
jinfo -flag Xmx 21382


Xml代码
文章图片

1. Heap
2. PSYoungGentotal 984448K, used 546524K [0x00000007c2200000, 0x00000007ffe30000, 0x0000000800000000)
3. eden space 957760K, 57% used [0x00000007c2200000,0x00000007e37b7088,0x00000007fc950000)
4. from space 26688K, 0% used [0x00000007fe420000,0x00000007fe420000,0x00000007ffe30000)
5. tospace 27072K, 0% used [0x00000007fc950000,0x00000007fc950000,0x00000007fe3c0000)
6. PSOldGentotal 204224K, used 112010K [0x0000000746600000, 0x0000000752d70000, 0x00000007c2200000)
7. object space 204224K, 54% used [0x0000000746600000,0x000000074d362800,0x0000000752d70000)
8. PSPermGentotal 44928K, used 22198K [0x0000000741400000, 0x0000000743fe0000, 0x0000000746600000)
9. object space 44928K, 49% used [0x0000000741400000,0x00000007429adbc0,0x0000000743fe0000)

Java代码
文章图片

1. Heap
2. PSYoungGentotal 881024K, used 451396K [0x00000007c2200000, 0x0000000800000000, 0x0000000800000000)
3. eden space 788480K, 45% used [0x00000007c2200000,0x00000007d8079b80,0x00000007f2400000)
4. from space 92544K, 99% used [0x00000007f2400000,0x00000007f7e57580,0x00000007f7e60000)
5. tospace 119488K, 0% used [0x00000007f8b50000,0x00000007f8b50000,0x0000000800000000)
6. PSOldGentotal 1561792K, used 1226956K [0x0000000746600000, 0x00000007a5b30000, 0x00000007c2200000)
7. object space 1561792K, 78% used [0x0000000746600000,0x00000007914330e0,0x00000007a5b30000)
8. PSPermGentotal 37888K, used 22595K [0x0000000741400000, 0x0000000743900000, 0x0000000746600000)
9. object space 37888K, 59% used [0x0000000741400000,0x0000000742a10cb8,0x0000000743900000)

以上两条输出是应用刚启动和启动20分钟后的heap使用对比， PSOldGen从 204224K(204M)增大到了
1561792K(1.5G左右)，说明当前java应用对老生代的需求较大，才导致老生代的空间暴涨；另外，
PSYoungGen的from也从26688K(26M)增大到了92544K(95M)，说明有很多对象等待被清理。继续看输出：



Java代码
文章图片

1. "Thread-23" prio=10 tid=0x00007f19f022e000 nid=0x19ac waiting for monitor entry [0x00007f19a0958000]
2. java.lang.Thread.State: BLOCKED (on object monitor)
3. at org.apache.log4j.Category.callAppenders(Category.java:204)
4. - waiting to lock <0x0000000749823ca8> (a org.apache.log4j.spi.RootLogger)
5. at org.apache.log4j.Category.forcedLog(Category.java:391)
6. at org.apache.log4j.Category.log(Category.java:856)
7. at org.slf4j.impl.Log4jLoggerAdapter.error(Log4jLoggerAdapter.java:498)
8. at com.chinahh.app.user.common.UserInfoData_Sync.setUserInfo(UserInfoData_Sync.java:508)
9. at com.chinahh.app.user.common.UserInfoData_Sync.writeAsync(UserInfoData_Sync.java:681)
10. at com.chinahh.app.user.common.UserInfoData_Sync.access$000(UserInfoData_Sync.java:45)
11. at com.chinahh.app.user.common.UserInfoData_Sync$5.run(UserInfoData_Sync.java:140)
12. at com.chinahh.app.user.common.UserInfoData_Sync$5.run(UserInfoData_Sync.java:136)
13. at com.chinahh.util.ThreadProc.dequeueAction(LazyQueue.java:234)
14. at com.chinahh.util.ThreadProc.run(LazyQueue.java:190)

通过该输出和代码的跟踪，定位到java应用的队列的代码是队列中的对象在等待出列，通过java应用逻辑来反推，对象出列时进行数据库操作，由于 数据库数据量较大，在访问量较大的情况下可能会导致响应变慢。该队列是一个ConcurrentLinkedQueue非阻塞队列，初始容量是6W多，同 时运行5个队列就是30多W个对象在队列中，并且单个对象也比较大，可以想象对内存的占用会相当大。到这里，问题就可以定位了。接下来就是问题的解决，具 体步骤如下：

1.增大heap空间。
减轻GC线程的压力，看看是否有效。配置参数如下：
su - java -c "java -Xmx2g -Xms2g -verbose:gc -Xloggc:/var/log/java/test/gc/test_gc.log -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -jar /www/run/test-0.0.1-SNAPSHOT.jar nolocalcache & "

修改参数后，观察了一段时间发现，内存的使用基本控制住了，稳定在不到12G*20%，大概减少用了600M多的内存，对于我们那苦逼的服务器：12G内存，跑着10个java服务来说，应该说是不小的资源了。CPU的占用也有缩减，但不如内存那么明显，下周再继续跟踪。

2.减小队列的长度。
下周尝试将队列长度从6W缩小到3W，先看看效果。

对于telnet 不响应的分析，通过tcpdump查看该端口的请求，发现tcp的请求还一直在过来，但为什么本机telnet 测试报错呢：
telnet: connect to address : Connection timed out

是否由于GC太多频繁导致请求不响应，还是由于访问量较大(该服务日访问量峰值是4000多W)，导致端口被使用殆尽呢，下周继续跟踪，期待能再有进展。

推荐阅读

• 

  社保卡发放城乡居民基本养老保险待遇 肇庆2月份起全面使用
• 

  山东麦收是几月份，麦收后种植什么经济作物
• 

  建筑工程技术主要考哪些证好考吗
• 

  海尔洗衣机不能洗涤是什么原因,主要差别在这里
• 

  手机|华为手机越做越大，越来越重；苹果则越来越小，越来越轻薄
• 

  PS制作另类高光黑白照片
• 

  掩于岁月敬而远之是什么意思
• 

  陈皮加枸杞泡水喝有什么作用
• 

  丝绸之路的意义是什么 关于丝绸之路的意义介绍
• 

  教师招聘体检哪些不合格不能通过
• 

  医生|又有患者不讲武德！医生“飞刀”手术后被举报：退还手术费还得道歉
• 

  如何把视频的声音提取成文字？视频转文字方法分享
• 

  做肝血管瘤介入有啥副作用,肝血管瘤介入手术有何并发症
• 

  如何刷机安卓手机,如何进行强制刷机?
• 

  Win10电脑的微软商店不见了怎么办？教你重新安装Microsoft Store详细方法
• 

  范忆琳个人资料 运动员范忆琳个人简介
• 

  爱玩mc官网 爱玩mc如何直播，爱玩mc联机装mod
• 

  Win7旗舰版打开文件提示安全警告怎么取消？
• 

  mongodb文件格式 mongodb写入文件
• 

  银耳泡后软粘是怎么回事

• 并发|11.防刷限流
• 面试真题（多线程交替打印ABC，中间变化打印顺序）
• 面试|【面试】--三个线程轮流打印ABC
• 并发|基于rxjava的生产消费模型
• LINUX|Linux网路编程基础及并发服务器
• 并发执行（串行）