當前位置:
首頁 > 知識 > 偵探劇場:堆內存神秘溢出事件

偵探劇場:堆內存神秘溢出事件

(點擊

上方公眾號

,可快速關注)




來源:光閃,


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.alib[email protected]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.alib[email protected]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.alib[email protected]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.alib[email protected]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.alib[email protected]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.alib[email protected]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.alib[email protected]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<Long> 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<String> noworkDays = new ArrayList<>();


    try {


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


    } catch (SourceVerifyException e) {


        logger.warn("警告信息,userCode:{}, applyType:{}", context.getUserVo(), context.getDoc().getDocType());


    }


    List<UserDetail> 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<UserDetail> partDocToDetails(ApplyCommonContext context, List<String> excludeDays, boolean deepExclude) {


    Doc doc = context.getDoc();


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


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


}




查看transferDayAttenceDoc方法,其中隱去簡單調用方法:





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


    List<TimeVo> timeVoList = Lists.newArrayList();


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


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


    // 處理中間天


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


    ...


    return timeVoList;


}




繼續往下一層進,查看ServiceDateUtil.getBetweenDates(startTime, endTime)





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


    SimpleDateFormat format = new SimpleDateFormat("yyyy-MM-dd");


    List<String> betweenList = new ArrayList<String>();


    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) + "
")




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技能


喜歡這篇文章嗎?立刻分享出去讓更多人知道吧!

本站內容充實豐富,博大精深,小編精選每日熱門資訊,隨時更新,點擊「搶先收到最新資訊」瀏覽吧!


請您繼續閱讀更多來自 ImportNew 的精彩文章:

通向架構師的道路 ( 第十七天 ) IBM Websphere 集群探秘 – WASND
不同的垃圾回收器的比較

TAG:ImportNew |