偵探劇場：堆記憶體神秘上限溢位事件

（點選上方公眾號，可快速關註）

來源：光閃，

my.oschina.net/u/2368090/blog/1628720

摘要: 小光是一名私家偵探，是小光偵探事務所的負責人。這天，他正在事務所中喝茶，突然接到警官M的電話，說接到線上總共三臺機器，有一臺機器報警，Java堆記憶體佔用超過95%，無法正常得到伺服器的響應。小光安排警官M保留好現場，急匆匆的趕往了現場…

案發

小光是一名私家偵探，是小光偵探事務所的負責人。這天，他正在事務所中喝茶，突然接到警官M的電話，說接到線上總共三臺機器，有一臺機器報警，Java堆記憶體佔用超過95%，無法正常得到伺服器的響應。小光安排警官M保留好現場，急匆匆的趕往了現場…

路上

在前往現場的路上，小光思考了以下幾個問題：

什麼情況下會出現堆記憶體

猜測可能是：

1. 瞬時併發數增大，且不能快速傳回。這種情況需要一些執行緒的呼叫棧中，取用了大量的實體才可以佔滿堆記憶體。

2. 程式中有bug，導致死迴圈，在迴圈體中一直有分配記憶體的操作，且不是臨時變數。

3. 關鍵是分配大量記憶體，且無法被有效GC。

如何去定位問題

• 最直接的方式，堆dump，使用MAT或者JVisualVm來分析dump檔案，找出是哪裡佔用了大量的堆記憶體。

• 當1無法執行時，可以使用jdk自帶的一些工具，如jmap來分析記憶體。堆有可能是dump不出來的，因為線上堆大小是8G，且同一臺物理機有多個服務在執行，可能會影響其他服務。

• 記憶體作為主要分析物件，基於上述猜測1，還需要使用jstack匯出執行緒棧資訊。

現場

到達現場後，小光立即著手從現場找到有用的線索，分別在案發現場(問題JVM)做了以下幾件事

1. 嘗試進行整個案發現場的備份，即堆dump，但被告知堆記憶體太大，無法進行dump

2. 嘗試使用JMX連線標的JVM

   以失敗告終，JVisualVM長時間無法連線。(為什麼無法連線成功，參考思考1)

3. SSH連線線上伺服器，使用JDK自帶工具嘗試獲取線索

• ps -ef | grep java：找到標的jvm的pid

• jmap -histo 標的jvm的pid | head -20：檢視Class與對應實體佔用情況。但是以失敗告終，提示： Attaching to process ID 3991, please wait…

• Error attaching to process: sun.jvm.hotspot.debugger.DebuggerException: Can’t attach to the process

• 嘗試jmap無果，接著嘗試jstack：jstack 標的jvm的pid：一樣以失敗告終，提示基本同上

可能是當前使用者無許可權導致的。但是jmx應該不是，思考失敗原因，參考歸檔1

好在警官M在之前已經jmap出來一部分有效資訊了，參考如下圖：

但是，根據這個線索，只能定位到是String導致堆記憶體佔滿的，並沒有其他有效的資訊，而String物件是整個程式執行期間處處都有使用的，很難去直接定位到問題所在…

至此，現場勘查基本完成，但是並沒有什麼收穫有效的可一次定位問題的資訊。只能清理現場、重啟服務，以防止影響後續服務。

現場監控資訊

現場已經被清理了，但是現場還有一些監控資訊。同時詢問大致案發時間，是八點三十分左右，對部分內容取8-9點之間的資訊，包括有以下內容：

應用日誌

請求M警官協助，拉取了問題機當天的所有日誌，一起另外一臺沒有問題的機器的所有日誌，方便做差異分析。

GC日誌

在堆記憶體幾乎佔滿時，GC時間也變的很長，GC日誌有一定的參考價值。

監控日誌

檢視應用日誌目錄，發現有dkimi目錄，看了下裡面大致內容，發現是dkimi這個agent層的一些日誌，也包括了一些有用資訊，但是檔案較大沒有拉出來，有需要的時候自己去伺服器上檢視。

監控平臺matrix

monitor-matrix.zeus 

線索分析

線索有以下內容：

一張jmap圖

應用所有日誌

GC日誌

dkimi日誌

監控平臺圖表

專案原始碼

直接從1、3、4、5中並不能直接分析出問題所在，但是可以根據這些資訊得出一個非常有價值的線索：案發時間

1. 確定案發時間

由圖4可知，案發時間在8:24分左右，但不確定該監控平臺的監控間隔，以及時間的準確性。透過檢查dkimi日誌，發現每隔30s會自動上報當前jvm狀態json資料，狀態中包括了jvm:gc:ParNew:time，即gc時間。

cat dkimi-agent.2018-01-10.log | grep ‘2018-01-10 08:2[2-5]:.*HeartB.*jvm:gc:ParNew:time’

 

2018-01-10 08:22:26 – jvm:gc:ParNew:time:2107

2018-01-10 08:22:56 – jvm:gc:ParNew:time:2107

2018-01-10 08:23:26 – jvm:gc:ParNew:time:2128

2018-01-10 08:23:56 – jvm:gc:ParNew:time:9462

2018-01-10 08:24:28 – jvm:gc:ParNew:time:19735

2018-01-10 08:24:59 – jvm:gc:ParNew:time:21332

2018-01-10 08:25:44 – jvm:gc:ParNew:time:22556

取22分到25分的資料，大致定位了時間為23-24分鐘之間。

2. 取案發時間區間監控日誌

cat all_is_well.log | grep ‘20180110-08:2[3-4]’

在拉取日誌後，小光的智商突然下線…透過通讀兩臺機器這一分鐘的所有日誌後，沒有發現任何異常，所以也就沒有得到任何結論…

在漫無目的的檢視日誌沒有結果之後，開始懷疑起了日誌區間，從此開始進入了誤區…

3. 進入誤區

先從日誌中報error的地方入手，雖然error不會導致堆記憶體上限溢位，但是或許會有一些有用的資訊。

cat all_is_well.log | grep ‘20180110-08:2.*ERROR’

20180110-08:25:44.743 [ZkClient-EventThread-40] ERROR org.I0Itec.zkclient.ZkEventThread [44263889_40_754] [] – Error handling event ZkEvent[Children of /fake changed sent to com.alibaba.dubbo.remoting.zookeeper.zkclient.ZkclientZookeeperClient$2@68c3c43c]

20180110-08:25:44.745 [ZkClient-EventThread-40] ERROR org.I0Itec.zkclient.ZkEventThread [44263889_40_754] [] – Error handling event ZkEvent[Children of /fake changed sent to com.alibaba.dubbo.remoting.zookeeper.zkclient.ZkclientZookeeperClient$2@6cfc4dfc]

20180110-08:25:44.746 [ZkClient-EventThread-40] ERROR org.I0Itec.zkclient.ZkEventThread [44263889_40_754] [] – Error handling event ZkEvent[Children of /fake changed sent to com.alibaba.dubbo.remoting.zookeeper.zkclient.ZkclientZookeeperClient$2@29fece07]

20180110-08:25:44.747 [ZkClient-EventThread-40] ERROR org.I0Itec.zkclient.ZkEventThread [44263889_40_754] [] – Error handling event ZkEvent[Children of /fake changed sent to com.alibaba.dubbo.remoting.zookeeper.zkclient.ZkclientZookeeperClient$2@6e09bdf2]

20180110-08:25:44.748 [ZkClient-EventThread-40] ERROR org.I0Itec.zkclient.ZkEventThread [44263889_40_754] [] – Error handling event ZkEvent[Children of /fake changed sent to com.alibaba.dubbo.remoting.zookeeper.zkclient.ZkclientZookeeperClient$2@189d662b]

20180110-08:25:44.749 [ZkClient-EventThread-40] ERROR org.I0Itec.zkclient.ZkEventThread [44263889_40_754] [] – Error handling event ZkEvent[Children of /fake changed sent to com.alibaba.dubbo.remoting.zookeeper.zkclient.ZkclientZookeeperClient$2@16804b69]

20180110-08:25:44.750 [ZkClient-EventThread-40] ERROR org.I0Itec.zkclient.ZkEventThread [44263889_40_754] [] – Error handling event ZkEvent[Children of /fake changed sent to com.alibaba.dubbo.remoting.zookeeper.zkclient.ZkclientZookeeperClient$2@49d13148]

發現大量的Zookeeper異常，正常機器上的日誌上並沒有這個異常。莫非是這裡的問題？開始看這裡的原始碼…結果並沒有什麼收穫(這就是所謂的病急亂投醫吧)。

在仔細思考後，小光覺得這個異常一定與堆記憶體洩漏相關，莫非是這個報錯之前有其他操作導致了這個問題？

在檢視該時間點附近相關日誌後，發現了

20180110-08:25:44.727 [localhost-startStop-1-EventThread] INFO  org.apache.zookeeper.ZooKeeper [44263935_42_78] [] – Initiating client connection, connectString=xxx sessionTimeout=30000

 

20180110-08:24:59.034 [localhost-startStop-1-SendThread(111.222.111.222)] WARN  org.apache.zookeeper.ClientCnxn [44263926_41_516] [] – Client session timed out, have not heard from server in 30475ms for sessionid 0x25f06ee8bd75078

莫非是這個sessionTimeout導致了上面的error， 超時時間30s，那麼是否有什麼操作導致整個zookeeper連線阻塞了將近30s，無法有效與zookeeper進行互動導致的？上面發現session timed out個WARN從24:59開始就有了，檢視這段日誌相關的原始碼。沒有發現任何異常……那麼從這個前面開始找…

突然小光註意到了日誌的事件，在8:24:59之前，最近一條日誌竟然是8:24:37，中間二十多秒的日誌去哪兒了？

20180110-08:24:37.821 [catalina-exec-60] INFO  com.web.filter.WebFilter [1477821_495_995] [25216534600963] – time http://xxx.com/,7

20180110-08:24:59.034 [localhost-startStop-1-SendThread(11.11.111.11:2181)] WARN  org.apache.zookeeper.ClientCnxn [44263926_41_516] [] – Client session timed out, have not heard from server in 30475ms for sessionid 0x25f06ee8bd75078

缺少的二十多秒的日誌，不可能是應用二十多秒沒有日誌輸出，那麼可以做到這種事情的，只有JVM的Stop The World!檢視GC日誌，發現GC時間確實有二十多秒。

由此判斷ERROR日誌基本上可以確定為GC暫定導致的，又回歸了線索的原點。。

4. 結合監控嘗試找出嫌疑人

既然無法從ERROR中得到嫌疑人的有效資訊，那就回歸最開始的猜想：不能快速傳回的請求。

可以看到上面日誌中，有個WebFilter日誌，最後有耗費的時長，拉取這段時間所有WebFilter日誌

cat all_is_well.log | grep ‘20180110-08:2[3-5].*WebFilter’

看了下時間，並沒有發現較長的響應時間。莫非是非Web請求導致的問題？

透過結構化日誌到資料庫，分析是否有非web執行緒的日誌，並與正常機器的日誌執行緒做對比，觀察執行緒不一致的日誌。如何結構化請看歸檔2

其中n1是log4j的一個token，n2是一次web請求的生命週期中唯一的id，使用ThreadLocal實現的。

SELECT * FROM log150 where thread not like ‘%catalina-exec%’;

查詢非web執行緒，除了workflowMessageListenerContainer沒有其他的

SELECT * FROM log151 where thread not like ‘%catalina-exec%’;

查詢非web執行緒，除了workflowMessageListenerContainer沒有其他的

SELECT * FROM log151 where thread not in (select thread from log150)

查詢log151中沒有150的執行緒，並沒有..

SELECT * FROM log150 where thread not in (select thread from log151)

查詢log150中沒有151的執行緒，有一堆workflowMessageListenerContainer

查了下151的workflowMessageListenerContainer日誌，並沒有什麼異常…

至此，透過檢視web相關請求的響應時間，排除了web相關請求，透過兩臺機器對比執行緒，排除了非web相關請求。這樣問題就死在這裡了…

小光抬眼看了下時間，已經到了晚上，思路也漸漸的不清晰了，暫時休息，明天繼續。

5. 第二天，根據不在場證明確定嫌疑人

第二天，小光早早的起了床，並立了一個Flag，今天肯定能查到原因。因為昨晚他突然想到，當一個請求很耗時，甚至都不傳回成為死迴圈時，可能連日誌都沒有。

同時，WebFilter的日誌列印，是在finally中，當請求無法傳回時，當然不會列印日誌，昨天確實是忽略了這個問題，走了個大的彎路。

public void doFilter(ServletRequest request, ServletResponse response,

                     FilterChain arg2) throws IOException, ServletException {

    long startTime = System.currentTimeMillis();

    StringBuffer url = new StringBuffer();

    try {

        url = url.append(((HttpServletRequest)request).getRequestURL().toString());

        arg2.doFilter(request, response);

    } catch (Throwable e){

        request.setAttribute(“errmsg”, e.getClass()+”-“+e.getMessage());

        RequestDispatcher rd = request.getRequestDispatcher(“/resources/error.jsp”);

        try {  

            rd.forward(request, response);  

            return;  

        }catch(Exception ex){}  

    } finally{

        if (!url.toString().contains(“resources”)) {

            logger.info(String.format(“time %s,%s”, url, System.currentTimeMillis() – startTime));

        }

    }

}

可以看到，只有finally中列印了日誌，請求之前並沒有列印日誌。

那麼是否有before和after都列印了日誌，只要分析一下有before但是沒有after的請求，那麼就可以定位到問題點了！

想到這裡，小光立馬興奮了一起，開啟程式碼，找尋其他切入點，果然找到了一個WebInterceptor：

public class RequestLoggerHandler extends HandlerInterceptorAdapter {

    private static Logger logger = LogManager.getLogger(RequestLoggerHandler.class);

    private ThreadLocal startTime = new ThreadLocal();

 

    public RequestLoggerHandler() {

    }

 

    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {

        this.startTime.set(System.currentTimeMillis());

        User user = SessionUserUtil.getCurrentSessionUser();

        logger.info(“[http]preHandle url: {}, user:{}, inParams: {}”, new Object[]{request.getRequestURL(), user, this.toJSONString(request.getParameterMap())});

        return true;

    }

 

    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {

        logger.info(“[http]postHandle url: {}, cause [{}] ms”, new Object[]{request.getRequestURL(), System.currentTimeMillis() – ((Long)this.startTime.get()).longValue()});

        ThreadTokenHelper.clear();

    }

 

    private String toJSONString(Object object) {

        try {

            return JSON.toJSONString(object);

        } catch (Exception var3) {

            logger.warn(“request請求引數序列化{}異常……”);

            var3.printStackTrace();

            return null;

        }

    }

}

這裡的before和after都列印了日誌，且日誌可以透過上面的n2即日誌id來關聯，沒有日誌id的時候可以使用請求地址來做對比。

結構化該請求相關的日誌

cat all_is_well.log | grep ‘20180110-08:2[2-4].*com.xxx.commons.log.RequestLoggerHandler.*’

匯出日誌。

 

SELECT count(1),n2 FROM requestlog GROUP BY n2

查詢資料，找出其中為奇數的請求。

最終竟然真的找到了一個，而且有且只有一個

檢視時間點，也確實與案發時間對的上。為增加確定性，搜尋該時間點之後執行緒catalina-exec-19的相關日誌，發現在該時間點之後，就沒有與此執行緒相關的日誌了。由此，根據各執行緒的不在場證明可以基本確定嫌疑人為執行緒catalina-exec-19。

檢視該條日誌，得到請求資訊，內容為：

20180110-08:23:26.449 [catalina-exec-19] INFO  com.commons.log.RequestLoggerHandler [1406449_454_770] [25216485580601] – [http]preHandle url: http://xxx.com/apply, user:{“userId”:100000001111111, “userCode”:”1111111″,”userName”:”光閃”}, inParams: {“103009”:[“”],”docContent”:[“大區 年會”],”submitterId”:[“22222222″],”showHalfDay”:[“1″],”docDuration”:[“1.5″],”dateValid”:[“true”],”docDurationApplied”:[“0″],”docType”:[“103014″],”isBeijing”:[“false”],”remaining”:[“0″],”maxDayCount”:[“”],”days”:[“2.5″],”docStartTime”:[“2018-01-08 08:22:50″],”docEndTime”:[“2018-01-10 08:22:56″],”docStartTimeInterval”:[“2″],”docEndTimeInterval”:[“2”]}

推理破案

上次講到最終定位到了犯罪嫌疑人，但是犯罪嫌疑人也不是吃素的，證據又不足以定罪，小光繼續進行分析推理：

1. 嫌疑人拒不認罪

嫌疑人catalina-exec-19表示，沒有兇器與行兇方式，證據是不充足的，不能進行逮捕。小光說，既然已知嫌疑人，以及兇器的一點線索，找到兇器只是時間問題，接著便埋頭開始推理。

兇器的線索在日誌中已經提供：請求地址是http://xxx.com/apply。同時該執行緒日誌id為25216485580601。透過請求處理邏輯，以及呼叫過程中整個的日誌資訊，要想得到確切的問題點不會太難。

查看了程式碼才發現，上面想的還是有點簡單了，這個介面的處理邏輯使用了模板樣式，在模板樣式中又嵌tao了模板樣式…與25216485580601相關的日誌有71條，多為DataPermissionInterceptor類的日誌，該類攔截所有dao層呼叫。

同時可知，在最後一條日誌打印出來之後，該執行緒就沒有再列印日誌了，既沒有報錯也沒有終止，那麼大機率是死迴圈到某處了。

2. 找出兇器

透過請求引數”docType”:[“103014”]找到對應的處理類，又透過層層模擬呼叫，結合日誌，最終確定了問題發生在這段程式碼之中

protected JsonDto analyzec(ApplyCommonContext context) {

    List noworkDays = new ArrayList<>();

    try {

        noworkDays = detailService.getNoworkDays(userCode, docStartTime, docEndTime);

    } catch (SourceVerifyException e) {

        logger.warn(“警告資訊，userCode:{}, applyType:{}”, context.getUserVo(), context.getDoc().getDocType());

    }

    List listist = UserProcessUtil.partDocToDetails(context, noworkDays, deepExclude(context.getDoc().getDocType(), context));

第71條日誌是在getNoworkDays方法中列印的，而在UserProcessUtil.partDocToDetails後面又肯定會有新的日誌產生，那麼問題就發生在getNoworkDays方法體內和UserProcessUtil.partDocToDetails方法體內。(中間還遇到了日誌與呼叫過程不一致的情況，後發現是因為dao層有@Cacheable註解，導致dao層邏輯沒有經過DataPermissionInterceptor攔截器)

大致瀏覽了一下getNoworkDays，發現其中並沒有特殊的方法呼叫和迴圈，嫌疑物件指向了UserProcessUtil.partDocToDetails方法：

public static List partDocToDetails(ApplyCommonContext context, List excludeDays, boolean deepExclude) {

    Doc doc = context.getDoc();

    List timeVoList = transferDayDoc(doc, context.getUserVo());

    return convertToDetails(doc, timeVoList, doc.getId(), excludeDays, deepExclude);

}

檢視transferDayAttenceDoc方法，其中隱去簡單呼叫方法：

private static List transferDayDoc(Doc doc, UserVo userVo) {

    List timeVoList = Lists.newArrayList();

    String startTime = DateUtil.formatDate(doc.getDocStartTime());

    String endTime = DateUtil.formatDate(doc.getDocEndTime());

    // 處理中間天

    List desList = ServiceDateUtil.getBetweenDates(startTime, endTime);

    …

    return timeVoList;

}

繼續往下一層進，檢視ServiceDateUtil.getBetweenDates(startTime, endTime)

public static List getBetweenDates(String begin, String end) {

    SimpleDateFormat format = new SimpleDateFormat(“yyyy-MM-dd”);

    List betweenList = new ArrayList();

    try {

        Calendar startDay = Calendar.getInstance();

        startDay.setTime(format.parse(begin));

        startDay.add(Calendar.DATE, -1);

 

        while (true) {

            startDay.add(Calendar.DATE, 1);

            Date newDate = startDay.getTime();

            String newend = format.format(newDate);

            betweenList.add(newend);

            if (end.equals(newend)) {

                break;

            }

        }

    } catch (Exception e) {

        e.printStackTrace();

    }

    betweenList.remove(begin);

    betweenList.remove(end);

    return betweenList;

}

看到這段程式碼時，突然一道光穿透了小光的兩耳(此處配名偵探柯南發現真相圖)。下麵那個while (true)非常可疑！

分析程式碼，迴圈終止條件是end.equals(newend)。newend則是startDay每次迴圈加一的結果，那麼就是在某種情況下無法觸發迴圈結束條件。

把請求中引數的”docStartTime”:[“2018-01-08 08:22:50”],”docEndTime”:[“2018-01-10 08:22:56”]作為引數傳入方法呼叫後，直接死迴圈了…結果是因為判斷條件是拿全部String做的equals。而newend是經過日期格式化的，只取日期那一部分的值，而end則不做任何變化，那麼一個日期與一個日期時間，做字串equals是肯定不會相等的，必然會死迴圈。

到這裡，小光以為案件已破。但是仔細一想，這樣的話豈不是所以進到這裡的邏輯，都會直接觸發死迴圈，這一點又解釋不通。

檢視呼叫該方法傳入的引數，發現start和end其實是經過格式化的日期字串

String startTime = DateUtil.formatDate(attenceDoc.getDocStartTime());

String endTime = DateUtil.formatDate(attenceDoc.getDocEndTime());

繼續分析equals條件，當傳入引數start大於傳入引數end時，就永遠不會觸髮結束條件。什麼情況下會start大於end呢。

此時，又一道光閃過小光的眼前！DateFormat是執行緒不安全的，當多個執行緒使用同一個DateFormat時，有可能導致格式化後的結果不是自己想要的！看DateUtil.formatDate的程式碼

private static final DateFormat DEFAULT_DATE_FORMAT = new SimpleDateFormat(“yyyy-MM-dd”);

public static String formatDate(Date date) {

    return DEFAULT_DATE_FORMAT.format(date);

}

果然與猜想的一樣，此處使用了一個靜態的DEFAULT_DATE_FORMAT來格式化日期，當多執行緒操作時，會導致start變為其他執行緒正在操作的時間。若此時間正好比end大，那麼就會觸發死迴圈。關於DateFormat執行緒不安全，參考歸檔3.

再看死迴圈邏輯，往一個list中丟String物件，與最開始jmap結果也一致！

3. 還原作案手法

在多執行緒併發環境下，併發越高，上面的問題越容易重現。這也解釋了之前到月底發生該問題的現象，月底考勤系統併發增加，問題出現機率增高。

透過構建多執行緒共用同一個DateFormat，開啟500個執行緒同時Format日期2018.01.12，主執行緒呼叫兩次Format，分別Format 2018.01.08和2018.01.10，之後作為引數傳入getBetweenDates，嘗試幾次後，果然重現

public static void main(String[] args) {

    Date start = DateUtil.parseDate(“2018.01.08”);

    Date end = DateUtil.parseDate(“2018.01.10”);

    final Date other = DateUtil.parseDate(“2018.01.12”);

    for (int i = 0; i < 500; i++) {

        new Thread(() -> DateUtil.formatDate(other)).start();

    }

    ServiceDateUtil.getBetweenDates(DateUtil.formatDate(start), DateUtil.formatDate(end));

}

4. 真相大白

至此，兇器已被找到，證據確鑿，嫌疑人也已無法狡辯，只得乖乖俯首認罪。而小光也說出了那就他早就想說的話：真相永遠只有一個！

後記

思考上面問題出現的原因。

Util作者寫了個方法，期望該方法的使用者，傳入引數時，一定符合他的約定。

而使用者在使用該方法時，也都嚴格按照該約定進行傳參。

但是中間殺出了個程咬金，多執行緒環境下結果的不確定性，最終導致了嚴重的堆記憶體洩漏問題。

案件已經偵破，那麼各位針對上面的問題，有什麼好的解決方法嗎？當然直接換執行緒安全的日期格式化工具是非常有必要的，方法中做引數的必要性校驗也是有必要的。

插曲

歸檔

JVisualVM長時間無法連線、工具Attach失敗的原因：

首先要瞭解一下這些工具執行的原理，為何會報出Attach失敗？

這些工具的執行原理都是基於Sun公司的Attach API。透過com.sun.tools.attach.VirtualMachine類，呼叫attach(pid)方法，attach到標的JVM上。

那麼標的JVM又是怎麼覺察到attach進來一個工具呢？透過執行緒Signal Dispatcher來實現。當attach時，會對標的執行緒發出一個訊號量，該訊號量交由該執行緒處理，訊號量處理程式發現是attach訊號，檢測Attach Listener執行緒是否啟動，如果沒有啟動則啟動一個Attach Listener執行緒，attach的具體操作交由Attach Listener執行。

attach到標的虛擬機器後，真正邏輯的執行是靠Java Platform Debugger Architecture(JPDA)來進行的。

所有真正的執行還是要依賴標的JVM的，所以當標的JVM堆記憶體不足，且長時間GC佔用CPU時間片時，Attach是很難執行的。

要想獲取更相信的資訊，請參考：

• Java除錯那點事

• JPDA 體系概覽

• JVM Attach機制實現

結構化日誌方式

• 指令碼語言：Python、Node.js

• sed命令

• awk命令

• grep命令

參考指令碼

with open(‘E:/logAnalysis/out.txt’, ‘w’, encoding=’UTF-8′) as fo:

    with open(‘E:/logAnalysis/request.log’,encoding=’UTF-8′) as f:

        for line in f:

            if line[0:8] != ‘20180110’:

                continue

            time = line[12:21]

            line = line[22:].lstrip()

            thread = line[0:line.find(” “)]

            line = line[len(thread) + 1:].lstrip()

            level = line[0:line.find(” “)]

            line = line[len(level) + 1:].lstrip()

            clazz = line[0:line.find(” “)]

            line = line[len(clazz) + 1:].lstrip()

            n1 = line[0:line.find(” “)]

            line = line[len(n1) + 1:].lstrip()

            n2 = line[0:line.find(” “)]

            line = line[len(n2) + 1:].lstrip()

            content = line[2:].strip()

            request = 0 if content.find(‘[http]preHandle’) >= 0 else 1

            fo.write(“” + time + “^” + thread + “^” + level + “^” + clazz + “^” + n1 + “^” + n2 + “^” + str(request) + “\n”)

DateFormat執行緒不安全的原因

說嚴禁點，其實是SimpleDateFormat的parse和format方法執行緒不安全。究其原因是因為其中使用了一個共享的calendar變數來進行日期與實時間的處理。在format時，先進行了一個calendar的setTime操作。這裡就導致了多執行緒環境下，結果的不一致。

// Called from Format after creating a FieldDelegate

private StringBuffer format(Date date, StringBuffer toAppendTo,

                            FieldDelegate delegate) {

    // Convert input date to time field list

    calendar.setTime(date);

上面雖然引起了堆記憶體大量佔用，但是並沒有OOM，思考原因

上面說了堆記憶體被大量佔用，且有個死迴圈一直分配記憶體。奇怪的是卻一直沒有報出OutOfMemmoryError。這裡需要去瞭解一下丟擲OutOfMemmoryError的時機，參考JVM原始碼分析之臨門一腳的OutOfMemoryError完全解讀。

個人猜測是因為，嘗試分配記憶體時，發現記憶體不足，嘗試進行GC，一次GC時間達到了半分鐘。GC後，由於有其他執行緒可以釋放一部分記憶體，又可以讓死迴圈多分配點記憶體，最終持續進行分配與GC，始終達不到觸發OOM錯誤的時機，故沒有丟擲OOM。

PS

第一次嘗試這種寫作風格，歡迎各位提出意見與建議。如果覺得文章不錯，歡迎關註和點贊哈，您的支援是我最大的動力。本地還有一些存貨，有機會的話我會繼續寫這個系列，希望大家支援~

看完本文有收穫？請轉發分享給更多人

關註「ImportNew」，提升Java技能