碼上快樂

相關內容    簡體    繁體

jvm-jvm問題排查記錄案例

本文轉載自   查看原文   2020-10-12 22:42   1246    java(基礎知識、並發、jvm等)

參考：

https://blog.csdn.net/nielinqi520/article/details/78455614

https://www.cnblogs.com/Dhouse/p/7839810.html

https://blog.csdn.net/aasgis6u/article/details/54928744

https://www.iteye.com/blog/iamzhongyong-1830265

https://www.iteye.com/blog/caogen81-1513345

https://blog.csdn.net/wilsonpeng3/article/details/70064336/

https://blog.csdn.net/jacin1/article/details/44837595

 

 

 

 

 

 

JVM內存溢出導致的CPU過高問題排查案例

 

問題背景：

近期針對某接口做壓力測試的過程中發現，某接口在用戶量3千左右，並且業務沒有對外開放，CPU一直居高不下。

分析：初步懷疑開發人員邏輯控制不嚴謹， 導致死循環，因為業務量不大，用戶量不大，不可能出現高並發。

 1.通過jstack查找出對應執行線程是Vm Thread 線程,初步懷疑是頻繁的GC導致cpu過高。

 2.查看堆棧信息 jmap -heap 16190，如下圖：

看到年老區已使用86%

3.查看垃圾回收頻率,再次確認：jstat -gcutil 16190 1000

FGC頻率非常高，基本確定就是GC回收頻繁，導致CPU過高。

4.確認問題代碼，執行jmap -dump:format=b,file=heap.bin 16190，生成堆棧文件，通過MAT進行分析，如下圖：

通過層層定位和分析，得出JceSecurity這個類就占用大部分內存，點擊Dominator Tree進行分析，如下圖：

 

由於IdentityHashMap存放過多BouncyCastleProvider這個類，占用了大部分內存，查看JceSecurity中的IdentityHashMap，如下圖:

現在已經確定是由於map是static修飾導致，導致存放的類不能被jvm回收導致

5、查找程序中使用BouncyCastleProvider的代碼，跟開發人員確認是解密類，如下圖：

6、修改RSAUtil類中BouncyCastleProvider為單例，在此進行壓測觀察，如下圖：

壓測進行2小時，GC回收頻率如下圖：

內存使用情況：

 

 

 

 至此，問題已經解決

 

 

 

 

 

 

線上應用故障排查

高CPU占用

一個應用占用CPU很高，除了確實是計算密集型應用之外，通常原因都是出現了死循環。

 

根據top命令，發現PID為28555的Java進程占用CPU高達200%，出現故障。

通過ps aux | grep PID命令，可以進一步確定是tomcat進程出現了問題。但是，怎么定位到具體線程或者代碼呢？

首先顯示線程列表:

ps -mp pid -o THREAD,tid,time

找到了耗時最高的線程28802，占用CPU時間快兩個小時了！

 

其次將需要的線程ID轉換為16進制格式：

printf "%x\n" tid

 

 

最后打印線程的堆棧信息：

jstack pid |grep tid -A 30

 

 找到出現問題的代碼了！

 

最后，總結下排查CPU故障的方法和技巧有哪些：

1、top命令：Linux命令。可以查看實時的CPU使用情況。也可以查看最近一段時間的CPU使用情況。

2、PS命令：Linux命令。強大的進程狀態監控命令。可以查看進程以及進程中線程的當前CPU使用情況。屬於當前狀態的采樣數據。

3、jstack：Java提供的命令。可以查看某個進程的當前線程棧運行情況。根據這個命令的輸出可以定位某個進程的所有線程的當前運行狀態、運行代碼，以及是否死鎖等等。

4、pstack：Linux命令。可以查看某個進程的當前線程棧運行情況。

 

 

高內存占用

搞Java開發的，經常會碰到下面兩種異常：

1、java.lang.OutOfMemoryError: PermGen space

2、java.lang.OutOfMemoryError: Java heap space

要詳細解釋這兩種異常，需要簡單重提下Java內存模型。

 

Java內存模型是描述Java程序中各變量（實例域、靜態域和數組元素）之間的關系，以及在實際計算機系統中將變量存儲到內存和從內存取出變量這樣的低層細節。

在Java虛擬機中，內存分為三個代：新生代（New）、老生代（Old）、永久代（Perm）。

（1）新生代New：新建的對象都存放這里

（2）老生代Old：存放從新生代New中遷移過來的生命周期較久的對象。新生代New和老生代Old共同組成了堆內存。

（3）永久代Perm：是非堆內存的組成部分。主要存放加載的Class類級對象如class本身，method，field等等。

如果出現java.lang.OutOfMemoryError: Java heap space異常，說明Java虛擬機的堆內存不夠。原因有二：

（1）Java虛擬機的堆內存設置不夠，可以通過參數-Xms、-Xmx來調整。

（2）代碼中創建了大量大對象，並且長時間不能被垃圾收集器收集（存在被引用）。

如果出現java.lang.OutOfMemoryError: PermGen space，說明是Java虛擬機對永久代Perm內存設置不夠。

一般出現這種情況，都是程序啟動需要加載大量的第三方jar包。例如：在一個Tomcat下部署了太多的應用。

 

從代碼的角度，軟件開發人員主要關注java.lang.OutOfMemoryError: Java heap space異常，減少不必要的對象創建，同時避免內存泄漏。

現在以一個實際的例子分析內存占用的故障排查。

2G19({7(0}N(FIL09LH175N

通過top命令，發現PID為9004的Java進程一直占用比較高的內存不釋放（24.7%），出現高內存占用的故障。

想起上一篇線上應用故障排查之一：高CPU占用介紹的PS命令，能否找到具體是哪個的線程呢？

ps -mp 9004 -o THREAD,tid,time,rss,size,%mem

1

遺憾的是，發現PS命令可以查到具體進程的CPU占用情況，但是不能查到一個進程下具體線程的內存占用情況。

 

只好尋求其他方法了，幸好Java提供了一個很好的內存監控工具：jmap命令

jmap命令有下面幾種常用的用法：

•jmap [pid]

•jmap -histo:live [pid] >a.log

•jmap -dump:live,format=b,file=xxx.xxx [pid]

用得最多是后面兩個。其中，jmap -histo:live [pid] 可以查看當前Java進程創建的活躍對象數目和占用內存大小。

jmap -dump:live,format=b,file=xxx.xxx [pid] 則可以將當前Java進程的內存占用情況導出來，方便用專門的內存分析工具（例如：MAT）來分析。

這個命令對於分析是否有內存泄漏很有幫助。具體怎么使用可以查看本博的另一篇文章：利用Eclipse Memory Analyzer Tool（MAT）分析內存泄漏

 

這里詳細介紹下jmap -histo:live [pid] 命令：

1

從上圖可以看出，int數組、constMethodKlass、methodKlass、constantPoolKlass都占用了大量的內存。

特別是占用了大量內存的int數組，需要仔細檢查相關代碼。

 

最后，總結下排查內存故障的方法和技巧有哪些：

1、top命令：Linux命令。可以查看實時的內存使用情況。  

2、jmap -histo:live [pid]，然后分析具體的對象數目和占用內存大小，從而定位代碼。

3、jmap -dump:live,format=b,file=xxx.xxx [pid]，然后利用MAT工具分析是否存在內存泄漏等等。

 

 

 

 

 

 

 

 

 

一個java內存泄漏的排查案例

 

這是個比較典型的java內存使用問題，定位過程也比較直接，但對新人還是有點參考價值的，所以就紀錄了一下。

下面介紹一下在不了解系統代碼的情況下，如何一步步分析和定位到具體代碼的排查過程
（以便新人參考和自己回顧）

 

初步的現象

業務系統消費MQ中消息速度變慢，積壓了200多萬條消息，通過jstat觀察到業務系統fullgc比較頻繁,到最后干脆OOM了：



進一步分析

既然知道了內存使用存在問題，那么就要知道是哪些對象占用了大量內存.

很多人都會想到把堆dump下來再用MAT等工具進行分析，但dump堆要花較長的時間，並且文件巨大，再從服務器上拖回本地導入工具，這個過程太折騰不到萬不得已最好別這么干。

可以用更輕量級的在線分析，用jmap查看存活的對象情況（jmap -histo:live [pid]），可以看出HashTable中的元素有5000多萬，占用內存大約1.5G的樣子：



定位到代碼

現在已經知道了是HashTable的問題，那么就要定位出什么代碼引起的

接下來自然要看看是什么代碼往HashTable里瘋狂的put數據，於是用神器btrace跟蹤Hashtable.put調用的堆棧。

首先寫btrace腳本TracingHashTable.java：

  1.  
    import com.sun.btrace.annotations.*;
  2.  
    import static com.sun.btrace.BTraceUtils.*;
  3.  
     
  4.  
    @ BTrace
  5.  
    public class TracingHashTable {
  6.  
    /*指明要查看的方法，類*/
  7.  
    @OnMethod(
  8.  
    clazz= "java.util.Hashtable",
  9.  
    method= "put",
  10.  
    location= @Location(Kind.RETURN))
  11.  
    public static void traceExecute( @Self java.util.Hashtable object){
  12.  
    println("調用堆棧！！");
  13.  
    jstack();
  14.  
    }
  15.  
    }

然后運行：
bin/btrace -cp build 4947 TracingHashTable.java

看到有大量類似下圖的調用堆棧



可以看出是在接收到消息后查詢入庫的代碼造成的，業務方法調用ibatis再到mysql jdbc驅動執行statement時put了大量的屬性到HashTable中。

通過以上排查已基本定位了由那塊代碼引起的，接下來就是打開代碼工程進行白盒化改造了，對相應代碼進行優化（不在本文范圍內了。幾個圖中的pid不一致就別糾結了，有些是系統重啟過再截圖的）.

 

 

 

 

 

一次JVM中FullGC問題排查過程

這個問題比較常見，我把過程中的日志記錄下來了，希望后續大家遇到類似的能快速定位。

1、平均三秒一次FullFC

 sudo -u admin java/bin/jstat -gcutil `pgrep java -u admin` 1000 2000

  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT  

  0.00   0.53  71.69   9.19  92.42   6183  901.265 54986 48865.327 49766.592

  0.00   0.53  72.34   9.19  92.42   6183  901.265 54986 48866.617 49767.881

  0.00   0.53  72.68   9.19  92.42   6183  901.265 54986 48866.617 49767.881

  0.00   0.53  73.08   9.19  92.42   6183  901.265 54987 48866.617 49767.881

  0.00   0.53  73.08   9.19  92.42   6183  901.265 54987 48866.617 49767.881

  0.00   0.53  73.68   9.19  92.42   6183  901.265 54987 48867.875 49769.140

  0.00   0.53  73.87   9.19  92.42   6183  901.265 54988 48867.875 49769.140

  0.00   0.53  73.87   9.19  92.42   6183  901.265 54988 48869.260 49770.525

  0.00   0.53  74.90   9.19  92.42   6183  901.265 54988 48869.260 49770.525

  0.00   0.53  75.32   9.19  92.42   6183  901.265 54988 48869.260 49770.525

  0.00   0.53  75.39   9.19  92.42   6183  901.265 54989 48869.260 49770.525

  0.00   0.53  76.07   9.19  92.42   6183  901.265 54989 48870.539 49771.804

  0.00   0.53  76.34   9.19  92.42   6183  901.265 54990 48870.539 49771.804

  0.00   0.53  76.34   9.19  92.42   6183  901.265 54990 48870.539 49771.804

  0.00   0.53  77.36   9.19  92.42   6183  901.265 54990 48871.973 49773.238

  0.00   0.53  77.65   9.19  92.42   6183  901.265 54990 48871.973 49773.238

  0.00   0.53  77.76   9.19  92.42   6183  901.265 54991 48871.973 49773.238

 

2、重啟應用之后發現Perm區一直在上漲

 sudo -u admin /java/bin/jstat -gcutil `pgrep java -u admin` 5000 200

  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT  

  0.00  71.04  14.28   0.00  71.46      5    0.467     0    0.000    0.467

  0.00  71.04  16.19   0.00  71.47      5    0.467     0    0.000    0.467

  0.00  71.04  18.30   0.00  71.54      5    0.467     0    0.000    0.467

  0.00  71.04  20.82   0.00  71.54      5    0.467     0    0.000    0.467

  0.00  71.04  22.77   0.00  71.54      5    0.467     0    0.000    0.467

  0.00  71.04  24.46   0.00  71.54      5    0.467     0    0.000    0.467

  0.00  71.04  26.24   0.00  71.54      5    0.467     0    0.000    0.467

  0.00  71.04  29.01   0.00  72.66      5    0.467     0    0.000    0.467

  0.00  71.04  30.84   0.00  72.66      5    0.467     0    0.000    0.467

  0.00  71.04  32.65   0.00  72.68      5    0.467     0    0.000    0.467

  0.00  71.04  34.48   0.00  72.68      5    0.467     0    0.000    0.467

  0.00  71.04  36.40   0.00  72.69      5    0.467     0    0.000    0.467

  0.00  71.04  38.10   0.00  72.69      5    0.467     0    0.000    0.467

  0.00  71.04  39.76   0.00  72.70      5    0.467     0    0.000    0.467

 

3、Btrace查看后發現HSF的一個類在調用ClassLoader的defineClass方法來創建類：

sudo -u admin sh  btrace -cp /home/admin/btrace/build 4955  /home/admin/btrace/BtraceAll.java

===========================================================================

java.lang.ClassLoader.defineClass

Time taken : 2

java thread method trace:---------------------------------------------------

java.lang.ClassLoader.defineClass(ClassLoader.java:615)

org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.defineClass(DefaultClassLoader.java:165)

org.eclipse.osgi.baseadaptor.loader.ClasspathManager.defineClass(ClasspathManager.java:554)

org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findClassImpl(ClasspathManager.java:524)

org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClassImpl(ClasspathManager.java:455)

org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass_LockClassLoader(ClasspathManager.java:443)

org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass(ClasspathManager.java:423)

org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.findLocalClass(DefaultClassLoader.java:193)

org.eclipse.osgi.framework.internal.core.BundleLoader.findLocalClass(BundleLoader.java:368)

org.eclipse.osgi.framework.internal.core.SingleSourcePackage.loadClass(SingleSourcePackage.java:33)

org.eclipse.osgi.framework.internal.core.BundleLoader.findClassInternal(BundleLoader.java:432)

org.eclipse.osgi.framework.internal.core.BundleLoader.findClass(BundleLoader.java:397)

org.eclipse.osgi.framework.internal.core.BundleLoader.findClass(BundleLoader.java:385)

org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.loadClass(DefaultClassLoader.java:87)

java.lang.ClassLoader.loadClass(ClassLoader.java:247)

com.taobao.hsf.rpc.tbremoting.provider.ProviderProcessor.handleRequest(ProviderProcessor.java:117)

com.taobao.hsf.rpc.tbremoting.provider.ProviderProcessor.handleRequest(ProviderProcessor.java:55)

com.taobao.remoting.impl.DefaultMsgListener$1.run(DefaultMsgListener.java:98)

java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

java.lang.Thread.run(Thread.java:662)

 

4、Perm區配置都是128M，有點小，之前占比90%的時候開始FullGC

VM Flags:

-Dprogram.name=run.sh -Xms4g -Xmx4g -XX:PermSize=128m -XX:MaxPermSize=128m -Xmn2500m -XX:SurvivorRatio=7 -XX:+UseConcMarkSweepGC -XX:+UseCMSCompactAtFullCollection

 

5、應用中war包的lib目錄就有177M

在應用剛開始啟動的時候，占比70% 左右，也就是90M左右的樣子，之后有些類動態加載進來了，到90% 后就回收不了了。

 

臨時解決辦法：調大Perm區，增大至256m

后續考慮：優化jar包依賴，目前太多沒用的被依賴進來，導致包很大。

 

 

 

 

 

 

 

一次讓人難以忘懷的排查頻繁Full GC過程

我們的Java應用因頻繁FULL GC導致性能降低很多，經過多人的定位也沒有結論，於是我自主請命，經過一天的研究終於搞定了，現把經驗與大家共享，相關的gc日志如下：

4.758: [Full GC [PSYoungGen: 464K->0K(71936K)] [PSOldGen: 37949K->33994K(68672K)] 38413K->33994K(140608K) [PSPermGen: 33221K->33221K(66560K)], 0.1887540 secs] [Times: user=0.20 sys=0.00, real=0.19 secs]

32.324: [Full GC [PSYoungGen: 12025K->0K(176320K)] [PSOldGen: 57570K->65642K(128256K)] 69595K->65642K(304576K) [PSPermGen: 35548K->35548K(76544K)], 0.2467320 secs] [Times: user=0.22 sys=0.02, real=0.25 secs]

50.133: [Full GC [PSYoungGen: 20999K->0K(437248K)] [PSOldGen: 118647K->114524K(198528K)] 139647K->114524K(635776K) [PSPermGen: 49637K->49637K(84224K)], 0.3302180 secs] [Times: user=0.32 sys=0.00, real=0.33 secs]

149.586: [Full GC [PSYoungGen: 44223K->0K(411712K)] [PSOldGen: 190278K->185382K(296064K)] 234501K->185382K(707776K) [PSPermGen: 50674K->50208K(85248K)], 0.6151800 secs] [Times: user=0.62 sys=0.00, real=0.61 secs]

260446.223: [Full GC [PSYoungGen: 31393K->0K(436032K)] [PSOldGen: 1006486K->396428K(1021312K)] 1037880K->396428K(1457344K) [PSPermGen: 61093K->61093K(61440K)], 1.3636610 secs] [Times: user=1.36 sys=0.00, real=1.52 secs]

260630.161: [Full GC (System) [PSYoungGen: 40410K->0K(424768K)] [PSOldGen: 991397K->721859K(1021312K)] 1031808K->721859K(1446080K) [PSPermGen: 61100K->61100K(61440K)], 2.1272130 secs] [Times: user=2.14 sys=0.00, real=2.13 secs]

260720.146: [Full GC (System) [PSYoungGen: 4949K->0K(439360K)] [PSOldGen: 1004066K->833610K(1021312K)] 1009015K->833610K(1460672K) [PSPermGen: 61108K->61108K(61440K)], 2.8408660 secs] [Times: user=2.72 sys=0.10, real=2.84 secs]

260810.150: [Full GC (System) [PSYoungGen: 33459K->0K(463552K)] [PSOldGen: 949989K->245655K(1021312K)] 983448K->245655K(1484864K) [PSPermGen: 61117K->61088K(61184K)], 1.1344010 secs] [Times: user=1.12 sys=0.02, real=1.14 secs]

03430.144: [Full GC (System) [PSYoungGen: 7390K->0K(489024K)] [PSOldGen: 871871K->393481K(976704K)] 879262K->393481K(1465728K) [PSPermGen: 64306K->64295K(64640K)], 1.3848850 secs] [Times: user=1.34 sys=0.06, real=1.38 secs]

403794.982: [Full GC [PSYoungGen: 9352K->0K(454144K)] [PSOldGen: 963758K->426051K(991744K)] 973110K->426051K(1445888K) [PSPermGen: 64298K->64298K(64640K)], 1.3783510 secs] [Times: user=1.32 sys=0.06, real=1.38 secs]

404120.149: [Full GC (System) [PSYoungGen: 6846K->0K(467648K)] [PSOldGen: 943642K->440168K(991744K)] 950489K->440168K(1459392K) [PSPermGen: 64300K->64300K(64640K)], 1.1605070 secs] [Times: user=1.12 sys=0.04, real=1.16 secs]

404466.698: [Full GC [PSYoungGen: 9719K->0K(472768K)] [PSOldGen: 980355K->442899K(1021312K)] 990074K->442899K(1494080K) [PSPermGen: 64303K->64303K(64640K)], 1.1729280 secs] [Times: user=1.14 sys=0.04, real=1.18 secs]

 

經過日志分析，我找到兩個突破點，重點關注紅色字體部分的日志，分析過程如下：

1）FULL GC前后Java堆大小有變化；經研究發現是由於Java應用JVM參數XMS設置為默認值，在我們的系統環境下，Hotspot的Xms默認值為50M（-Xms默認是物理內存的1/64）；每次GC時，JVM會根據各種條件調節Java堆的大小，Java堆的取值范圍為[Xms, Xmx]。根據以上分析，修改Xms值與Xmx相等，這樣就不會因為所使用的Java堆不夠用而進行調節，經過測試后發現FULL GC次數從四位數減少至個位數。


2）關鍵詞“System”讓我想到了System.gc調用，System.gc調用只是建議JVM執行年老代GC，而年老代GC觸發FULL GC，JVM會根據系統條件決定是否執行FULL GC，正因為系統條件不好判斷，所以很難構造System.gc調用觸發FULL GC，幾經周折終於成功，當System.gc觸發FULL  GC時都會有關鍵詞“（System）”，而　JVM自動觸發的FULL GC卻不帶關鍵詞“（System）”，可以斷定是Java應用存在“System.gc”代碼。經過本次測試我也發現System.gc的真正含義，通俗言之，“System.gc” 就是FULL GC觸發的最后一根稻草。

從本次分析中，我們可以得出如下的經驗：
1）Java應用的jvm參數Xms與Xmx保持一致，避免因所使用的Java堆內存不夠導致頻繁full gc以及full gc中因動態調節Java堆大小而耗費延長其周期。

2）建議不要調用System.gc或者Runtime.getRuntime().gc，否則本次調用可能會成為“壓死駱駝的最后一根稻草”。當然我們可以通過設置jvm參數禁止這種調用生效，但是除非特別有把握該參數有必要添加，否則不推薦這么設置。

 

 

 

 

 

 

線上FullGC頻繁排查-druid

 

線上FullGC頻繁的排查

本應該寫在文末的

這個問題我再github上提交了一個issue，具體issue的討論見這里

問題

前段時間發現線上的一個dubbo服務Full GC比較頻繁，大約每兩天就會執行一次Full GC。

Full GC的原因

我們知道Full GC的觸發條件大致情況有以下幾種情況：

  1. 程序執行了System.gc() //建議jvm執行fullgc，並不一定會執行
  2. 執行了jmap -histo:live pid命令 //這個會立即觸發fullgc
  3. 在執行minor gc的時候進行的一系列檢查
執行Minor GC的時候，JVM會檢查老年代中最大連續可用空間是否大於了當前新生代所有對象的總大小。
如果大於，則直接執行Minor GC（這個時候執行是沒有風險的）。
如果小於了，JVM會檢查是否開啟了空間分配擔保機制，如果沒有開啟則直接改為執行Full GC。
如果開啟了，則JVM會檢查老年代中最大連續可用空間是否大於了歷次晉升到老年代中的平均大小，如果小於則執行改為執行Full GC。
如果大於則會執行Minor GC，如果Minor GC執行失敗則會執行Full GC

 

  1. 使用了大對象 //大對象會直接進入老年代
  2. 在程序中長期持有了對象的引用 //對象年齡達到指定閾值也會進入老年代

對於我們的情況，可以初步排除1，2兩種情況，最有可能是4和5這兩種情況。為了進一步排查原因，我們在線上開啟了 -XX:+HeapDumpBeforeFullGC。

注意：
    JVM在執行dump操作的時候是會發生stop the word事件的，也就是說此時所有的用戶線程都會暫停運行。
    為了在此期間也能對外正常提供服務，建議采用分布式部署，並采用合適的負載均衡算法

 

JVM參數的設置：

線上這個dubbo服務是分布式部署，在其中一台機子上開啟了 -XX:HeapDumpBeforeFullGC，總體JVM參數如下：

-Xmx2g 
-XX:+HeapDumpBeforeFullGC 
-XX:HeapDumpPath=. 
-Xloggc:gc.log 
-XX:+PrintGC 
-XX:+PrintGCDetails 
-XX:+PrintGCDateStamps 
-XX:+UseGCLogFileRotation 
-XX:NumberOfGCLogFiles=10 
-XX:GCLogFileSize=100m 
-XX:HeapDumpOnOutOfMemoryError

 

Dump文件分析

dump下來的文件大約1.8g，用jvisualvm查看，發現用char[]類型的數據占用了41%內存，同時另外一個com.alibaba.druid.stat.JdbcSqlStat類型的數據占用了35%的內存，也就是說整個堆中幾乎全是這兩類數據。如下圖：

這里寫圖片描述

查看char[]類型數據，發現幾乎全是sql語句。

這里寫圖片描述

接下來查看char[]的引用情況：

這里寫圖片描述

找到了JdbcSqlStat類，在代碼中查看這個類的代碼，關鍵代碼如下：

//構造函數只有這一個
public JdbcSqlStat(String sql){
    this.sql = sql;
    this.id = DruidDriver.createSqlStatId();
}

//查看這個函數的調用情況，找到com.alibaba.druid.stat.JdbcDataSourceStat#createSqlStat方法：

public JdbcSqlStat createSqlStat(String sql) {
    lock.writeLock().lock();
    try {
        JdbcSqlStat sqlStat = sqlStatMap.get(sql);
        if (sqlStat == null) {
            sqlStat = new JdbcSqlStat(sql);
            sqlStat.setDbType(this.dbType);
            sqlStat.setName(this.name);
            sqlStatMap.put(sql, sqlStat);
        }

        return sqlStat;
    } finally {
        lock.writeLock().unlock();
    }
}

//這里用了一個map來存放所有的sql語句。

 

 

其實到這里也就知道什么原因造成了這個問題，因為我們使用的數據源是阿里巴巴的druid，這個druid提供了一個sql語句監控功能，同時我們也開啟了這個功能。只需要在配置文件中把這個功能關掉應該就能消除這個問題，事實也的確如此，關掉這個功能后到目前為止線上沒再觸發FullGC

這里寫圖片描述

其他

如果用mat工具查看，建議把 “Keep unreachable objects” 勾上，否則mat會把堆中不可達的對象去除掉，這樣我們的分析也許會變得沒有意義。如下圖：Window–>References 。另外jvisualvm對ool的支持不是很好，如果需要oql建議使用mat。

這里寫圖片描述

擴展

本人自己建了一個jdk8和jdk7的源碼閱讀倉庫，會在閱讀源碼的過程中添加一些注釋。
感興趣的朋友可以一起來添加對代碼的理解。倉庫地址：
jdk8:
	github: https://github.com/rocky-peng/jdk8-sourcecode-read
	gitlab: https://gitlab.com/rocky_peng/jdk8
jdk7:
	github: https://github.com/rocky-peng/jdk7-sourcecode-read
	gitlab: https://gitlab.com/rocky_peng/jdk7
github和gitlab是完全自動同步的。   
jdk8和jdk7的源碼來源於jdk8和jdk7的src.zip文件。

 

 

 

 

 

 

JVM服務問題排查

 線上的服務就像一個黑匣子，具體什么情況，這個就是體現監控運維的價值，監控報警運維解決了的軟件服務最后一公里的問題。大公司一般都有很成熟的監控服務系統，可視化服務狀態，自動化運維操作，這些自動化的工具對開發人員來說都是如沐春風，但是一般中小企業這些基礎建設就沒有那么優秀了，很多問題都需要開發人員自行定位解決。
    線上的JVM服務運行久了或者出現訪問壓力時，服務往往會暴露一些問題，這個時候就需要開發人員自行定位具體問題，OpenJDK也提供了一些基本工具，比如 jstat jstack jmap jps jinfo。
    對於JVM服務可能出現的問題，我們一般依次排查內容為：
    （1）. 宿主機器問題
    （2）. JVM內存，是否頻繁GC
    （3）. 線程棧，是否線程暴漲，線程死鎖
    （4）. 排查日志，檢查程序代碼
 

1. 宿主機器問題：

    軟件是運行在機器上，如果宿主機器有問題，軟件肯定是不可用的。一般排查機器問題，我們主要考慮幾方面問題：內存，CPU，磁盤。
    內存和CPU問題，通過簡單的top命令，可以看到具體的情況
    
top -p ${pid}
#查看該進程關聯線程情況 top -H -p ${pid}

2. JVM堆使用情況和GC問題：

    這里需要使用到JDK自帶的工具，jps jmap jstat，具體的用法，這里就不詳述（網上或者直接help可以查詢），jps是查看機器的JVM進程，原理是通過讀取JVM啟動時寫入本地tmp的文件pid，一般很少使用，我們都是習慣通過ps的方式過去具體進程ID，jmap是與堆有關的工具，建議在JVM啟動時開啟 -XX:+HeapDumpOnOutOfMemoryError，該命令可以讓應用在發生OOM時，自動生成HeapDump的轉儲文件，方便問題排查。
    回到jmap使用問題，以下命令可以方便查看系統的堆情況 
 jmap -heap ${pid}
 
    上圖可以看到目前系統占用的年輕代、年老代、永久代的占用比率，還有具體的年輕代子分區的占用情況，Eden Space、From Space和To Space，系統的內存占用比率可以一目了解（以上討論在JDK7環境下，不同JDK，JVM堆分區設計難免有所差異）
    如果我們想查詢那些實例占用內存情況呢？jmap -histo可以幫助到你 
jmap -histo ${pid}

    
    一般需要具體到包名，比如 
 jmap -histo ${pid} | grep ${package}
 
    
    查詢GC情況，我們可以通過jstat命令，可以查詢到每個堆分代的內存占用情況和Young GC和Full GC次數和時間等。如下 
  jstat -gcutil ${pid} 1000 10
 
 

3. 線程棧，定位線程問題

    jstack 工具可以獲取當前線程運行情況，目前為止筆者沒有發現一個簡單有效的命令方式去判斷系統有沒有死鎖，一般都是使用jconsole連接后使用其檢測死鎖的工具和jstack dump出具體線程棧信息后，然后人為分析，這兩次方式都不是很便捷。
    如果時間和環境允許，最好是使用dump出來的文件的，然后使用MAT（Memory Analyse Tools）分析，MAT強大的分析功能和可視化界面是個不錯的選擇。
    Thread dump文件和MAT的使用都是一個很大的命題，一時半會筆者也說不清，目前也不太深入，這里就不展開描述了。
 

4. 排查日志，檢查程序代碼

    最后一步是通過以上步驟定位到問題所在后，具體修改代碼，重新上線，呵呵。

 

 

 

 

 


免責聲明！

本站轉載的文章為個人學習借鑒使用，本站對版權不負任何法律責任。如果侵犯了您的隱私權益，請聯系本站郵箱yoyou2525@163.com刪除。



猜您在找 JVM線上問題排查 我不是bug神（JVM問題排查） jvm問題排查工具、命令 JVM進程占用CPU過高問題排查 Java程序宕機問題-jvm層面排查 Jvm故障問題排查以及Jvm調優總結 jvm內存增長問題排查簡例 三步排查JVM cpu 100%問題 jvm 內存溢出問題排查方法 java問題之2：JVM堆外內存問題排查--刪除
 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM