【JVM】記錄一次線上SWAP偏高告警的故障分析過程

近期遇到一個堆外內存致使swap飆高的問題，這類問題比較罕見，所以將整個排查過程記錄下來了

現象描述

最近1周線上服務器時不時出現swap報警（swap超過內存10%時觸發報警，內存是4G，所以swap超過400M會觸發報警），每次都是童鞋們經過重啓tomcat解決的；
但致使的根本緣由是什麼呢？必須找到根本緣由才行，老是這麼重啓就有點low了

問題排查

因而找了1臺佔用了swap但還未觸發報警的服務器進行了排查
如下是當時經過top命令觀察到的結果

23:03:22 swap佔用了354M的內存

23:55:42 swap佔用了398M的內存

緣由分析

究竟是什麼緣由致使swap飆高呢？確定是tomcat，由於每次重啓tomcat就解決了;但根本緣由是？

誰佔用了swap

經過如下腳本 swap.sh

#!/bin/bash
# Get current swap usage for all running processes
# Erik Ljungstrom 27/05/2011
do_swap () {
SUM=0
OVERALL=0
for DIR in `find /proc/ -maxdepth 1 -type d | egrep "^/proc/[0-9]"` ; do
PID=`echo $DIR | cut -d / -f 3`
PROGNAME=`ps -p $PID -o comm --no-headers`
for SWAP in `grep Swap $DIR/smaps 2>/dev/null| awk '{ print $2 }'`
do
let SUM=$SUM+$SWAP
done
echo "PID=$PID - Swap used: $SUM - ($PROGNAME )"
let OVERALL=$OVERALL+$SUM
SUM=0
 
done
echo "Overall swap used: $OVERALL"
}
do_swap  |awk -F[\ \(] '{print $5,$1,$8}' | sort -n | tail -3

 

能夠看出PID=19911這個進程使用了324M的swap

經過grep進程號19911能夠看出確實是tomcat佔用swap最多

進程19911佔用總的物理內存是3.1G，java佔用的堆內內存大小爲2.78G，剩下的320M是堆外內存佔用的

Max memory = [-Xmx] + [-XX:MaxPermSize] + number_of_threads * [-Xss]

2779M=2048M+268M+463*1M

sudo -u tomcat ./jinfo -flag MaxPermSize 19911
-XX:MaxPermSize=268435456

java -XX:+PrintFlagsFinal -version | grep ThreadStackSize
     intx CompilerThreadStackSize                   = 0               {pd product}
     intx ThreadStackSize                           = 1024            {pd product}
     intx VMThreadStackSize                         = 1024            {pd product}
java version "1.7.0_45"
Java(TM) SE Runtime Environment (build 1.7.0_45-b18)
Java HotSpot(TM) 64-Bit Server VM (build 24.45-b08, mixed mode)

java -XX:+PrintFlagsFinal -version | grep -i permsize
    uintx AdaptivePermSizeWeight                    = 20              {product}
    uintx MaxPermSize                               = 85983232        {pd product}
    uintx PermSize                                  = 21757952        {pd product}
java version "1.7.0_45"
Java(TM) SE Runtime Environment (build 1.7.0_45-b18)
Java HotSpot(TM) 64-Bit Server VM (build 24.45-b08, mixed mode)

哪行代碼佔用了堆外內存

堆內內存溢出能夠直接經過MAT分析堆信息就能夠定位到具體的代碼，可是對於堆外內存就必須經過BTrace來解決

google-perftools 定位類名和方法名

如何安裝和使用google-perftools見這裏
因爲要啓動google-perftools須要重啓tomcat，因此重啓tomcat後，PID從19911變成了9176

重啓tomcat後，會自動生成heap文件，文件名的命名規範是gperf_pid.xxx.heap，因此咱們只須要關注gperf_9176.*便可

[xxxx@xxxx   /home/xxx/logs]$ ll *.heap
…...
-rw-r--r-- 1 tomcat tomcat    5048 May  6 10:46 gperf_9171.0001.heap
-rw-r--r-- 1 tomcat tomcat    5036 May  6 10:46 gperf_9173.0001.heap
-rw-r--r-- 1 tomcat tomcat    5055 May  6 10:46 gperf_9174.0001.heap
-rw-r--r-- 1 tomcat tomcat    5352 May  6 10:46 gperf_9175.0001.heap
-rw-r--r-- 1 tomcat tomcat 1048563 May  6 10:46 gperf_9176.0001.heap
-rw-r--r-- 1 tomcat tomcat 1048564 May  6 10:46 gperf_9176.0002.heap
-rw-r--r-- 1 tomcat tomcat 1048563 May  6 10:47 gperf_9176.0003.heap
-rw-r--r-- 1 tomcat tomcat 1048565 May  6 10:47 gperf_9176.0004.heap
-rw-r--r-- 1 tomcat tomcat 1048574 May  6 10:49 gperf_9176.0005.heap
-rw-r--r-- 1 tomcat tomcat 1048574 May  6 10:50 gperf_9176.0006.heap
-rw-r--r-- 1 tomcat tomcat 1048568 May  6 10:51 gperf_9176.0007.heap
-rw-r--r-- 1 tomcat tomcat 1048572 May  6 10:53 gperf_9176.0008.heap
-rw-r--r-- 1 tomcat tomcat 1048564 May  6 10:55 gperf_9176.0009.heap
-rw-r--r-- 1 tomcat tomcat 1048560 May  6 10:58 gperf_9176.0010.heap
-rw-r--r-- 1 tomcat tomcat 1048563 May  6 11:00 gperf_9176.0011.heap
-rw-r--r-- 1 tomcat tomcat 1048564 May  6 11:03 gperf_9176.0012.heap
…...

分析heap文件

/home/google-perftools/bin/pprof  --text  /home/java  /home/logs/gperf_9176.0010.heap
Using local file /home/java.
Using local file /home/logs/gperf_9176.0010.heap.
Total: 186.4 MB
91.2 48.9% 48.9% 91.2 48.9% updatewindow
52.5 28.2% 77.1% 52.5 28.2% os::malloc
38.0 20.4% 97.4% 38.0 20.4% inflateInit2_
3.0 1.6% 99.0% 3.0 1.6% init
0.8 0.4% 99.5% 0.8 0.4% ObjectSynchronizer::omAlloc
0.4 0.2% 99.7% 0.4 0.2% readCEN
0.3 0.2% 99.9% 38.3 20.5% Java_java_util_zip_Inflater_init
0.1 0.1% 100.0% 0.1 0.1% _dl_allocate_tls
0.0 0.0% 100.0% 0.0 0.0% _dl_new_object
0.0 0.0% 100.0% 1.1 0.6% Thread::Thread
0.0 0.0% 100.0% 0.0 0.0% CollectedHeap::CollectedHeap
0.0 0.0% 100.0% 0.0 0.0% Events::init
0.0 0.0% 100.0% 0.4 0.2% ZIP_Put_In_Cache0
0.0 0.0% 100.0% 0.0 0.0% read_alias_file
0.0 0.0% 100.0% 0.0 0.0% _nl_intern_locale_data

能夠看出是java.util.zip.Inflater的init()佔用了比較多的內存

經過BTrace定位代碼調用方

編寫代碼BtracerInflater.java對init方法進行攔截

import static com.sun.btrace.BTraceUtils.*;
import com.sun.btrace.annotations.*;
 
import java.nio.ByteBuffer;
import java.lang.Thread;
 
@BTrace public class BtracerInflater{
   @OnMethod(
      clazz="java.util.zip.Inflater",
      method="/.*/"
   )
   public static void traceCacheBlock(){
      println("Who call java.util.zip.Inflater's methods :");
     jstack();
   }
}

運行BTrace

[xxxx@l-xxx.xx.xx /home/xxx/btrace-bin/bin]$ sudo -u tomcat ./btrace -cp ../build 9176 BtracerInflater.java|more
Who call java.util.zip.Inflater's methods :
java.util.zip.Inflater.<init>(Inflater.java:102)
java.util.zip.GZIPInputStream.<init>(GZIPInputStream.java:76)
java.util.zip.GZIPInputStream.<init>(GZIPInputStream.java:90)
com.xxx.OrderDiffUtil.ungzip(OrderDiffUtil.java:54)
com.xxx.OrderDiffUtil.parse(OrderDiffUtil.java:32)
com.xxx.FaxOrderEventListener.takeSectionChangedInfo(FaxOrderEventListener.java:87)
com.xxx.FaxOrderEventListener.onMessage(FaxOrderEventListener.java:46)
.......

能夠看出是OrderDiffUtil的ungzip()調用了java.util.zip.Inflater的init()

看看OrderDiffUtil.ungzip()

private static String ungzip(String encodeJson) {
        ByteArrayOutputStream out = new ByteArrayOutputStream(encodeJson.length() * 5);
        ByteArrayInputStream in = null;
        try {
            in = new ByteArrayInputStream(Base64.decode(encodeJson));
        } catch (UnsupportedEncodingException e) {
            return "{}";
        }
        try {
            GZIPInputStream gunzip = new GZIPInputStream(in);
            byte buffer[] = new byte[1024];
            int len = 0;
            while ((len = gunzip.read(buffer)) != -1) {
                out.write(buffer, 0, len);
            }
        } catch (IOException e) {
            return "{}";
        }
        try {
            return out.toString("ISO-8859-1");
        } catch (UnsupportedEncodingException e) {
        }
        return "{}";
    }

可見gunzip未被close

因此根本緣由是未調用GZIPInputStream的close()關閉流致使堆外內存佔用