1. 首頁
  2. 問答
  3. Hung JVM消耗100％CPU

Hung JVM消耗100％CPU

2011-02-03 82 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

相關問題

 相關問題