偵探劇場：堆內存神秘溢出事件
（點擊
上方公眾號
，可快速關注）
來源：光閃，
my.oschina.net/u/2368090/blog/1628720
摘要: 小光是一名私家偵探，是小光偵探事務所的負責人。這天，他正在事務所中喝茶，突然接到警官M的電話，說接到線上總共三台機器，有一台機器報警，Java堆內存佔用超過95%，無法正常得到伺服器的響應。小光安排警官M保留好現場，急匆匆的趕往了現場…
案發
小光是一名私家偵探，是小光偵探事務所的負責人。這天，他正在事務所中喝茶，突然接到警官M的電話，說接到線上總共三台機器，有一台機器報警，Java堆內存佔用超過95%，無法正常得到伺服器的響應。小光安排警官M保留好現場，急匆匆的趕往了現場…
路上
在前往現場的路上，小光思考了以下幾個問題：
什麼情況下會出現堆內存
猜測可能是：
瞬時並發數增大，且不能快速返回。這種情況需要一些線程的調用棧中，引用了大量的實例才可以佔滿堆內存。
程序中有bug，導致死循環，在循環體中一直有分配內存的操作，且不是臨時變數。
關鍵是分配大量內存，且無法被有效GC。
如何去定位問題
最直接的方式，堆dump，使用MAT或者JVisualVm來分析dump文件，找出是哪裡佔用了大量的堆內存。
當1無法執行時，可以使用jdk自帶的一些工具，如jmap來分析內存。堆有可能是dump不出來的，因為線上堆大小是8G，且同一台物理機有多個服務在運行，可能會影響其他服務。
內存作為主要分析對象，基於上述猜測1，還需要使用jstack導出線程棧信息。
現場
到達現場後，小光立即著手從現場找到有用的線索，分別在案發現場(問題JVM)做了以下幾件事
嘗試進行整個案發現場的備份，即堆dump，但被告知堆內存太大，無法進行dump
嘗試使用JMX連接目標JVM
以失敗告終，JVisualVM長時間無法連接。(為什麼無法連接成功，參考思考1)
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<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技能
※通向架構師的道路 ( 第十七天 ) IBM Websphere 集群探秘 – WASND
※不同的垃圾回收器的比較
TAG:ImportNew |