分類  >  互聯網 >

正題:java服務,cpu高,內存高,telnet不通排查及分析

tags:    時間:2013-12-27 15:42:00
主題: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的輸出找到對應線程的信息,如下:

 

Xml代碼  
  1. Thread 150 (Thread 0x7f3aa7fff700 (LWP 21397)):  
  2. #0  0x00007f3ae62fcdc4 in instanceKlass::oop_follow_contents(oopDesc*) () from /usr/java/jdk1.6.0_31/jre/lib/amd64/server/libj  
  3. vm.so  
  4. #1  0x00007f3ae64e83eb in MarkSweep::follow_stack() () from /usr/java/jdk1.6.0_31/jre/lib/amd64/server/libjvm.so  
  5. #2  0x00007f3ae65a1f14 in PSMarkSweep::mark_sweep_phase1(bool) () from /usr/java/jdk1.6.0_31/jre/lib/amd64/server/libjvm.so  
  6. #3  0x00007f3ae65a0dc1 in PSMarkSweep::invoke_no_policy(bool) () from /usr/java/jdk1.6.0_31/jre/lib/amd64/server/libjvm.so  
  7. #4  0x00007f3ae65ad927 in PSScavenge::invoke() () from /usr/java/jdk1.6.0_31/jre/lib/amd64/server/libjvm.so  
  8. #5  0x00007f3ae656f90e in ParallelScavengeHeap::failed_mem_allocate(unsigned long, bool) () from /usr/java/jdk1.6.0_31/jre/lib  
  9. /amd64/server/libjvm.so  
  10. #6  0x00007f3ae66ac3d8 in VM_ParallelGCFailedAllocation::doit() () from /usr/java/jdk1.6.0_31/jre/lib/amd64/server/libjvm.so  
  11. #7  0x00007f3ae66b97ea in VM_Operation::evaluate() () from /usr/java/jdk1.6.0_31/jre/lib/amd64/server/libjvm.so  
  12. #8  0x00007f3ae66b8db2 in VMThread::evaluate_operation(VM_Operation*) () from /usr/java/jdk1.6.0_31/jre/lib/amd64/server/libjv  
  13. m.so  
  14. #9  0x00007f3ae66b9028 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 longbool)  

是在分配heap空間,說明java應用的heap空間可能不足,導致GC線程一直在忙活分配新的空間。 繼續看

 

MarkSweep::follow_stack()在幹嗎,查下源代碼,如下:

 

Cpp代碼  
  1. // Flush marking stack.  
  2.   follow_stack();  
  3.   
  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.  PSYoungGen      total 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.   to   space 27072K, 0% used [0x00000007fc950000,0x00000007fc950000,0x00000007fe3c0000)  
  6.  PSOldGen        total 204224K, used 112010K [0x0000000746600000, 0x0000000752d70000, 0x00000007c2200000)  
  7.   object space 204224K, 54% used [0x0000000746600000,0x000000074d362800,0x0000000752d70000)  
  8.  PSPermGen       total 44928K, used 22198K [0x0000000741400000, 0x0000000743fe0000, 0x0000000746600000)  
  9.   object space 44928K, 49% used [0x0000000741400000,0x00000007429adbc0,0x0000000743fe0000)  

 

 

 

Java代碼  
  1. Heap  
  2. PSYoungGen      total 881024K, used 451396K [0x00000007c22000000x00000008000000000x0000000800000000)  
  3.  eden space 788480K, 45% used [0x00000007c2200000,0x00000007d8079b80,0x00000007f2400000)  
  4.  from space 92544K, 99% used [0x00000007f2400000,0x00000007f7e57580,0x00000007f7e60000)  
  5.  to   space 119488K, 0% used [0x00000007f8b50000,0x00000007f8b50000,0x0000000800000000)  
  6. PSOldGen        total 1561792K, used 1226956K [0x00000007466000000x00000007a5b300000x00000007c2200000)  
  7.  object space 1561792K, 78% used [0x0000000746600000,0x00000007914330e0,0x00000007a5b30000)  
  8. PSPermGen       total 37888K, used 22595K [0x00000007414000000x00000007439000000x0000000746600000)  
  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),導致埠被使用殆盡呢,下周繼續跟蹤,期待能再有進展。

 

推薦閱讀文章

Bookmark the permalink ,來源:互聯網