`

java服务,cpu高,内存高,telnet不通排查及分析

 
阅读更多

记录上周五的一个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查看进程的栈信息。

pstack 21382 > test_pstack_20131221_12.out

 

从pstack的输出找到线程21397对应的信息,如下:

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

 

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

 

ParallelScavengeHeap::failed_mem_allocate(unsigned long, bool)

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

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

 

// Flush marking stack.
  follow_stack();

  // Process reference objects found during marking
  {
    ref_processor()->setup_policy(clear_all_softrefs);
    ref_processor()->process_discovered_references(
      is_alive_closure(), mark_and_push_closure(), follow_stack_closure(), NULL);
  }

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

 

4.查看jvm参数配置。

jinfo -flag Xmx 21382

 

Heap
 PSYoungGen      total 984448K, used 546524K [0x00000007c2200000, 0x00000007ffe30000, 0x0000000800000000)
  eden space 957760K, 57% used [0x00000007c2200000,0x00000007e37b7088,0x00000007fc950000)
  from space 26688K, 0% used [0x00000007fe420000,0x00000007fe420000,0x00000007ffe30000)
  to   space 27072K, 0% used [0x00000007fc950000,0x00000007fc950000,0x00000007fe3c0000)
 PSOldGen        total 204224K, used 112010K [0x0000000746600000, 0x0000000752d70000, 0x00000007c2200000)
  object space 204224K, 54% used [0x0000000746600000,0x000000074d362800,0x0000000752d70000)
 PSPermGen       total 44928K, used 22198K [0x0000000741400000, 0x0000000743fe0000, 0x0000000746600000)
  object space 44928K, 49% used [0x0000000741400000,0x00000007429adbc0,0x0000000743fe0000)

 

 

 Heap
 PSYoungGen      total 881024K, used 451396K [0x00000007c2200000, 0x0000000800000000, 0x0000000800000000)
  eden space 788480K, 45% used [0x00000007c2200000,0x00000007d8079b80,0x00000007f2400000)
  from space 92544K, 99% used [0x00000007f2400000,0x00000007f7e57580,0x00000007f7e60000)
  to   space 119488K, 0% used [0x00000007f8b50000,0x00000007f8b50000,0x0000000800000000)
 PSOldGen        total 1561792K, used 1226956K [0x0000000746600000, 0x00000007a5b30000, 0x00000007c2200000)
  object space 1561792K, 78% used [0x0000000746600000,0x00000007914330e0,0x00000007a5b30000)
 PSPermGen       total 37888K, used 22595K [0x0000000741400000, 0x0000000743900000, 0x0000000746600000)
  object space 37888K, 59% used [0x0000000741400000,0x0000000742a10cb8,0x0000000743900000)

 

以上两条输出是应用刚启动和启动20分钟后的heap使用对比, PSOldGen从 204224K(204M)增大到了

1561792K(1.5G左右),说明当前java应用对老生代的需求较大,才导致老生代的空间暴涨;另外,

PSYoungGen的from也从26688K(26M)增大到了92544K(95M),说明有很多对象等待被清理。继续看输出:

 

"Thread-23" prio=10 tid=0x00007f19f022e000 nid=0x19ac waiting for monitor entry [0x00007f19a0958000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at org.apache.log4j.Category.callAppenders(Category.java:204)
        - waiting to lock <0x0000000749823ca8> (a org.apache.log4j.spi.RootLogger)
        at org.apache.log4j.Category.forcedLog(Category.java:391)
        at org.apache.log4j.Category.log(Category.java:856)
        at org.slf4j.impl.Log4jLoggerAdapter.error(Log4jLoggerAdapter.java:498)
        at com.chinahh.app.user.common.UserInfoData_Sync.setUserInfo(UserInfoData_Sync.java:508)
        at com.chinahh.app.user.common.UserInfoData_Sync.writeAsync(UserInfoData_Sync.java:681)
        at com.chinahh.app.user.common.UserInfoData_Sync.access$000(UserInfoData_Sync.java:45)
        at com.chinahh.app.user.common.UserInfoData_Sync$5.run(UserInfoData_Sync.java:140)
        at com.chinahh.app.user.common.UserInfoData_Sync$5.run(UserInfoData_Sync.java:136)
        at com.chinahh.util.ThreadProc.dequeueAction(LazyQueue.java:234)
        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),导致端口被使用殆尽呢,下周继续跟踪,期待能再有进展。

 

5.GC日志分析

 

7890.915: [Full GC 7890.915: [CMS7893.415: [CMS-concurrent-mark: 2.563/2.575 secs] [Times: user=9.62 sys=0.46, real=2.57 secs]
 (concurrent mode failure): 1048576K->1048575K(1048576K), 15.8792530 secs] 1520448K->1518673K(1520448K), [CMS Perm : 22435K->22431K(131072K)], 15.8794830 secs] [Times: user=22.52 sys=0.40, real=15.88 secs]
Total time for which application threads were stopped: 15.8805650 seconds

 

通过部分GC日志,系统运行到一定时间后,发现full gc越来越频繁,而且耗时很长。例如这段Full GC时会导致应用在15.88秒左右的时间里不对外响应,这还了得.......

 

同时可以看到老年代空间压力较大,里面都是什么东西呢,打个heapdump瞅瞅吧。

 

6.heapdump分析

如果线上不方便直接打heapdump,可以考虑使用:

jmap -histo `pgrep` > #your file path#

也可以拿到heap里面的对象数量概况,然后再进一步跟踪。heapdump分析截图:



 

通过mat分析,找到了heap中占用空间最大的所在:tcp事务管理器,是否由于程序中没有关闭tcp连接造成的呢,反过来去查代码,正常的处理逻辑中tcp连接都关闭了,继续查代码对异常情况的处理,突然、果然....

发现有一个地方处理的不是很完善,当在某种特殊的情况下没有关闭tcp连接,特别巧合的是,最近连接的一个系统在不断地向这个调用在报错。于是产生了一个推断:

 

    被调用方频繁返回错误,会导致大量的tcp连接没有被关闭,事务一直在打开状态,这个tcp transaction manager可能也会一直存在,老年代占满后会引起Full GC,但连接不是垃圾又不能被sweep,导致cpu一直在忙于Full GC,没有时间响应telnet 的请求。

 

    修改代码,对tcp连接做完善的关闭处理,等待线上验证。代码修改后,确保正常和异常情况下tcp请求都被及时的返回。应用放到线上运行,继续收集gc日志,同时做一些手动的测试,例如:telnet服务端口等。经过一段时间的观察发现情况依旧:应用运行20分钟以后,full GC很频繁,而且耗时较长,导致应用的吞吐量受到非常大地影响。感到很无奈,和我们的技术负责人讨论了一下,他提到了一个很重要的地方,管理tcp请求的sessionpool是全局唯一的,容量在100W个请求左右,和之前从mat中得到的结论是不一致的。

 

    回头再分析heapdump,发现netty的多个工作线程都对这个sessionpool进行引用,但地址都是相同的,说明100W个请求所占的内存在40M左右,并非之前的分析20*40 = 800M,也就是说20多个工作线程在同时处理100W个tcp的请求,这个sessionpool并非占用大内存的对象。准备下周抽个时间对heapdump进行再次分析,然后看看是否有新的发现。

 

 

  • 大小: 53.8 KB
分享到:
评论
2 楼 wensong 2013-12-27  
(concurrent mode failure),是并行收集失败,进而转向串行收集,当然时间会长。
1 楼 makemyownlife 2013-12-27  
楼主的亲身实践有参考价值 ,建议加一些JAVA代码的解释 这样整篇博客更好 :)

相关推荐

    telnet-0.17-64.el7.x86_64.rpm

    1. **telnet协议**:telnet是一种用于远程登录的协议,允许用户通过网络在远程主机上执行命令,常用于系统管理员进行远程管理或故障排查。 2. **RPM包管理**:`rpm`是Linux下的包管理器,它提供了安装、卸载、查询...

    阿里监控工具阿里监控工具

    在性能监控方面,阿里监控工具能够深入到操作系统、数据库、网络等多个层次,实时监测CPU使用率、内存占用、磁盘I/O、网络流量等关键指标。通过对这些指标的持续监控,可以及时发现并预警潜在的性能瓶颈,避免系统...

    Linux.docx

    本文将详细讲解Linux中的常见命令、命令分类以及如何利用这些命令来查看系统资源,如内存和CPU状态,同时也会涉及到Java线上问题的排查方法。 1. **Linux命令分类及用途**: - **文件和目录操作**:如`ls`用于列出...

    通过服务运行tomcat

    - 此外,还可以通过修改`JAVA_OPTS`等环境变量来调整服务的Java虚拟机参数,例如增加JVM的最大堆内存等。 4. **创建系统服务** - 使用`sc`命令创建系统服务,示例命令如下: - `sccreate App_vastelnetwg_...

    TongWeb应用系统慢是怎么个慢.doc

    总之,解决TongWeb应用的“慢”与“死”问题,需要综合运用Linux操作、Java编程、JDK命令以及TongWeb的使用知识,通过观察现象、分析日志、调整配置和代码优化,逐步排查和优化,以确保应用的稳定高效运行。

    基于TCP远程终端管理系统

    3. **资源管理**:服务器需要合理分配系统资源,如CPU、内存和磁盘空间,以防止单个用户过度消耗影响其他用户。 4. **会话管理**:包括会话的建立、维持和断开。当用户登录后,系统应创建一个会话,允许用户执行...

    linux基本培训指南

    - `Heartbeat` 和 `DRBD` 是用于高可用性和数据同步的工具。 - 安装:使用包管理器安装相应的软件包。 - 使用:根据文档进行配置和设置。 以上就是 Linux 基础培训指南中的主要内容。通过掌握这些命令,可以帮助...

    详解在Linux虚拟机下配置tomcat

    在Linux虚拟机中配置Tomcat是一项常见的任务,尤其对于那些从事Java Web开发的人员来说,了解如何在Linux环境中部署和管理Tomcat服务器至关重要。本文将详细介绍这一过程。 首先,我们需要从Apache官网...

    CRT网络交换机调试软件

    - **监控网络状态**:实时查看设备状态,如CPU利用率、内存使用情况等。 对于初学者来说,了解如何正确配置和使用CRT网络交换机调试软件是非常重要的。它不仅可以提升工作效率,还能帮助理解网络设备的工作原理和...

    GNS3的使用方法

    2. 镜像配置:为每个设备分配合适的镜像,设置内存、CPU等资源。 四、启动和配置设备 1. 启动设备:点击设备图标,选择"启动",等待设备初始化完成。 2. 进行配置:通过串口连接(如TFTP、SSH或telnet)登录到设备...

Global site tag (gtag.js) - Google Analytics