1. 首页
  2. 问答
  3. Hung JVM消耗100％CPU

Hung JVM消耗100％CPU

2011-02-03 90 views
10

我们在Linux 32位（CentOS）上的Sun JRE 6u20上运行JAVA服务器。我们利用CMS收集与下列选项服务器热点（我只提供相关的）：Hung JVM消耗100％CPU

-Xmx896m -Xss128k -XX:NewSize=384M -XX:MaxPermSize=96m -XX:+UseParNewGC -XX:+UseConcMarkSweepGC

有时，运行一段时间后，在JVM似乎陷入挂起状态，因此即使尽管我们没有向应用程序发出任何请求，但CPU仍以100％旋转（我们有8个逻辑CPU，因此看起来只有一个CPU在旋转）。 在这种状态下，JVM不响应SIGHUP信号（kill -3），我们无法通过jstack正常连接它。我们可以使用“jstack -F”连接，但输出是狡猾的（我们可以看到很多来自JStack的NullPointerExceptions，显然是因为它无法'走'某些堆栈）。所以“jstack -F”输出似乎没用。我们已经从“gdb”运行了一个堆栈转储，并且我们能够匹配使CPU旋转的线程ID（我们发现使用“顶部”和每个线程视图 - “H”选项）与出现在gdb的结果，这是怎么看起来像一个线程堆栈：

Thread 443 (Thread 0x7e5b90 (LWP 26310)): 
#0 0x0115ebd3 in CompactibleFreeListSpace::block_size(HeapWord const*) const() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#1 0x01160ff9 in CompactibleFreeListSpace::prepare_for_compaction(CompactPoint*)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#2 0xc in Generation::prepare_for_compaction(CompactPoint*)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#3 0x01229b2c in GenCollectedHeap::prepare_for_compaction()() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#4 0x0122a7fc in GenMarkSweep::invoke_at_safepoint(int, ReferenceProcessor*, bool)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#5 0x01186024 in CMSCollector::do_compaction_work(bool)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#6 0x011859ee in CMSCollector::acquire_control_and_collect(bool, bool)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#7 0x01185705 in ConcurrentMarkSweepGeneration::collect(bool, bool, unsigned int, bool)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#8 0x01227f53 in GenCollectedHeap::do_collection(bool, bool, unsigned int, bool, int)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#9 0x0115c7b5 in GenCollectorPolicy::satisfy_failed_allocation(unsigned int, bool)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#10 0x0122859c in GenCollectedHeap::satisfy_failed_allocation(unsigned int, bool)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#11 0x0158a8ce in VM_GenCollectForAllocation::doit()() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#12 0x015987e6 in VM_Operation::evaluate()() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#13 0x01597c93 in VMThread::evaluate_operation(VM_Operation*)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#14 0x01597f0f in VMThread::loop()() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#15 0x015979f0 in VMThread::run()() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#16 0x0145c24e in java_start(Thread*)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#17 0x00ccd46b in start_thread() from /lib/libpthread.so.0 
#18 0x00bc2dbe in clone() from /lib/libc.so.6

看来，虽然做了一些CMS相关工作一个JVM线程在打转。 我们检查了盒子上的内存使用情况，似乎有足够的内存可用，并且系统没有交换。 有没有人遇到过这种情况？它看起来像是一个JVM错误吗？

UPDATE

我获得有关这个问题（它已经运行了超过7天的服务器上再次发生）的更多信息。 当JVM进入“挂起”状态时，它会一直保持2小时，直到手动重新启动服务器。我们已经获得了该进程和gc日志的核心转储。我们也试图获得堆转储，但“jmap”失败。我们试图使用jmap -F，但是在程序中止之前只有一个4Mb文件被写入异常（有关内存位置不可访问的内容）。 到目前为止，我认为最有趣的信息来自gc日志。看来，GC日志记录停止时（可能在当VM线程走进长循环的时间）：

657501.199: [Full GC (System) 657501.199: [CMS: 400352K->313412K(524288K), 2.4024120 secs] 660634K->313412K(878208K), [CMS Perm : 29455K->29320K(68568K)], 2.4026470 secs] [Times: user=2.39 sys=0.01, real=2.40 secs] 
657513.941: [GC 657513.941: [ParNew: 314624K->13999K(353920K), 0.0228180 secs] 628036K->327412K(878208K), 0.0230510 secs] [Times: user=0.08 sys=0.00, real=0.02 secs] 
657523.772: [GC 657523.772: [ParNew: 328623K->17110K(353920K), 0.0244910 secs] 642036K->330523K(878208K), 0.0247140 secs] [Times: user=0.08 sys=0.00, real=0.02 secs] 
657535.473: [GC 657535.473: [ParNew: 331734K->20282K(353920K), 0.0259480 secs] 645147K->333695K(878208K), 0.0261670 secs] [Times: user=0.11 sys=0.00, real=0.02 secs] 
.... 
.... 
688346.765: [GC [1 CMS-initial-mark: 485248K(524288K)] 515694K(878208K), 0.0343730 secs] [Times: user=0.03 sys=0.00, real=0.04 secs] 
688346.800: [CMS-concurrent-mark-start] 
688347.964: [CMS-concurrent-mark: 1.083/1.164 secs] [Times: user=2.52 sys=0.09, real=1.16 secs] 
688347.964: [CMS-concurrent-preclean-start] 
688347.969: [CMS-concurrent-preclean: 0.004/0.005 secs] [Times: user=0.00 sys=0.01, real=0.01 secs] 
688347.969: [CMS-concurrent-abortable-preclean-start] 
CMS: abort preclean due to time 688352.986: [CMS-concurrent-abortable-preclean: 2.351/5.017 secs] [Times: user=3.83 sys=0.38, real=5.01 secs] 
688352.987: [GC[YG occupancy: 297806 K (353920 K)]688352.987: [Rescan (parallel) , 0.1815250 secs]688353.169: [weak refs processing, 0.0312660 secs] [1 CMS-remark: 485248K(524288K)] 783055K(878208K), 0.2131580 secs] [Times: user=1.13 sys 
=0.00, real=0.22 secs] 
688353.201: [CMS-concurrent-sweep-start] 
688353.903: [CMS-concurrent-sweep: 0.660/0.702 secs] [Times: user=0.91 sys=0.07, real=0.70 secs] 
688353.903: [CMS-concurrent-reset-start] 
688353.912: [CMS-concurrent-reset: 0.008/0.008 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
688354.243: [GC 688354.243: [ParNew: 344928K->30151K(353920K), 0.0305020 secs] 681955K->368044K(878208K), 0.0308880 secs] [Times: user=0.15 sys=0.00, real=0.03 secs] 
.... 
.... 
688943.029: [GC 688943.029: [ParNew: 336531K->17143K(353920K), 0.0237360 secs] 813250K->494327K(878208K), 0.0241260 secs] [Times: user=0.10 sys=0.00, real=0.03 secs] 
688950.620: [GC 688950.620: [ParNew: 331767K->22442K(353920K), 0.0344110 secs] 808951K->499996K(878208K), 0.0347690 secs] [Times: user=0.11 sys=0.00, real=0.04 secs] 
688956.596: [GC 688956.596: [ParNew: 337064K->37809K(353920K), 0.0488170 secs] 814618K->515896K(878208K), 0.0491550 secs] [Times: user=0.18 sys=0.04, real=0.05 secs] 
688961.470: [GC 688961.471: [ParNew (promotion failed): 352433K->332183K(353920K), 0.1862520 secs]688961.657: [CMS

我怀疑这个问题有什么做的日志中的最后一行（I”我添加了一些“....”以跳过一些不感兴趣的行）。 服务器处于挂起状态2小时（可能尝试GC并压缩老一代）的事实对我来说似乎很奇怪。此外，gc日志会突然停止，并且没有其他内容会被打印，可能是因为虚拟机线程进入了某种无限循环（或者需要2个小时以上）。

来源

2011-02-03 Bogdan

+1

如果您正在低内存条件下运行，这是不可能观察到的。但是更新虚拟机，在u21/22，iirc中有一些GC大的修复。另外MaxPermSize = 96m非常低，但我不知道你跑的是什么。 – bestsss 2011-02-04 18:25:33

+0

我很确定虚拟机没有在内存不足的情况下运行。从GC日志中可以看出，每次有完整的GC时，OldGen的平均回收率为370Mb，这意味着其中大约有27％的可用空间。年轻一代（384Mb）在每次清理时几乎都清空了。所以我觉得有很多记忆。这个问题似乎发生在Full GC运行之前（正如您从日志中看到的那样），当OldGen几乎已满并且YoungGen收集器无法宣传某些对象时。虚拟机可能意识到OldGen太分散了，所以它触发了一个压缩（持续2个小时）。 – Bogdan 2011-02-07 09:30:18

回答

2

它看起来像一个GC调优问题，可能由内存泄漏引发。我建议您添加启用GC日志记录的JVM参数，并查看它是否给您提供任何见解。

它看起来像是一个JVM错误吗？

不对我。

当您用完堆空间（例如，由于存储泄漏）时，通常会看到GC越来越频繁地运行，并且使用的CPU占用越来越大。您可以设置一些JVM参数来避免这种情况，但它们会导致您的JVM早日通过OOME进行安装。 （这听起来很奇怪，但在很多情况下，这是件好事，因为它减少了系统重新启动并能够正常运行的时间）。

来源

2011-02-03 10:15:15

相关问题

 相关问题