問題再現:
個人中心在上周四上線(2012.9.13)第一次上線,由于種種緣由,遺留了部分低級別的BUG,后于次日修復,下午4時再次上線。
當日晚上8點,運維發現user-web 五臺服務器中四臺jboss僵死,無法響應用戶請求。
問題分析:
問題發生當日,運維截留了當時的日志信息并dump 了JVM內存信息,關鍵信息如下:
java.lang.NullPointerException
Message 2012-09-15 02:47:56,992 - com.dianping.userweb.service.processor.MyInfoFavouriteModuleProcessor -235970 [myInfoThreadPoolTaskExecutor-1] ERROR - com.dianping.userweb.service.processor.MyInfoFavouriteModuleProcessor process module exception.
......
"http-0.0.0.0-8080-271" daemon prio=10 tid=0x00002b6ef4211000 nid=0x292a waiting on condition [0x00002b6eac592000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000007c4a3f0f0> (a java.util.concurrent.CountDownLatch$Sync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:969)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1281)
at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:207)
at com.dianping.userweb.framework.concurrent.ConcurrentSidebarManager.execute(ConcurrentSidebarManager.java:46)
at com.dianping.userweb.action.page.myinfo.MyInfoIndexAction.sideBarManagerExecute(MyInfoIndexAction.java:39)
......
從以上日志中我們可以得到兩個信息
1.一個 process報了空指針異常,
2.一個線程一直處在waiting狀態。
根據日志找到對應的代碼:
@Override
public void execute(final UCActionContext context) throws ProjectException {
final CountDownLatch countDownLatch = new CountDownLatch(getHeadSize() + getLeftSize() + getRightSize());
barHandleExecute(context, countDownLatch, sideBar);
try {
countDownLatch.await(); --- A
} catch (InterruptedException e) {
logger.error("current handle error!", e);
throw new ProjectException("current handle error!");
}
}
這段是處理并行的核心代碼,通過CountDownLatch來處理并行的執行,主線程通過 countDownLatch.await();等待子線程的完成。這個方法會拋除InterruptedException異常,這個異常包含三個含義:
1.這是一個異常,需要業務根據時間情況處理,當然有些廢話
2.這是一個等待方法,等待的時間不根據CPU或是內存的情況,而是依賴于定時器或是磁盤IO的返回,本案是根據子線程的執行情況
3.這個等待線程是可以中斷的
所以當一個請求過來時,主線程會在這個A處等待,直到所有子線程告訴我,所有子線程已經執行完成了。
再看barHandleExecute方法的處理:
protected void barHandleExecute(final UCActionContext context, final CountDownLatch countDownLatch, SideBar sideBar) {
.......
threadPoolTaskExecutor.execute(new Runnable() {
@Override
public void run() {
Transaction t = Cat.getProducer().newTransaction("Modules",
moduleProcessor.getClass().getName());// 接入cat
try {
moduleProcessor.execute(context);
countDownLatch.countDown();
t.setStatus(Transaction.SUCCESS);
} catch (Throwable e) {
Cat.getProducer().logError(e);// 用log4j記錄系統異常,以便在Logview中看到此信息
t.setStatus(e);
} finally {
t.complete();
}
}
});
.......
}
對于多個線程,通過線程池來處理,每個線程也就是moduleProcessor處理完成后, countDownLatch.countDown();告訴主線程我已經執行完成了,當主線程收到所有子線程的答復后,繼續往下執行,進行頁面的渲染。
以上都是正常流程的流轉過程,但是,若我們其中的一個moduleProcessor拋出異常后,會出現什么情況呢?這個異常會被接入CAT監控的代碼會吃掉,告訴CAT一個日志信息,然后就什么都不做了。那countDownLatch.countDown();這段代碼就永遠不會被執行,而主線程又依賴于子線程通過countDownLatch.countDown();來告知是否執行完了。這個時候就悲劇了,主線程一直在等待子線程的消息,無法渲染頁面返回結果,這個時候用戶的第一反應會是是不是網絡原因導致沒有加載數據,不停的F5,每次都會產生一個新的請求進來,若是刷新的人越多,這些進程就永遠僵死在那邊,不釋放內存,造成系統雪崩。
一個合理的介入CAT方式是:
Transaction t = Cat.getProducer().newTransaction("Modules",
moduleProcessor.getClass().getName());// 接入cat
try {
// 業務處理
t.setStatus(Transaction.SUCCESS);
} catch (Throwable e) {
Cat.getProducer().logError(e);
t.setStatus(e);
throw new ProjectException(); //這里必須拋出異常,有業務系統決定如何處理異常
} finally {
t.complete();
}
幾個疑問:
1.為什么processor會拋出異常?
當時在porcessor編寫的時候,約定各個processor需要cacth自己的異常,不能因為自己的失敗導致請求的其他模塊加載失敗。我們看看報空指針的地方:
.....
context.getParam(DefaultActionContext.Contant.MEMBER_ID.name)
.....
try
...
報錯的是從上下文獲取memberID的代碼,這個操作并沒有放在try catch塊中。由于個人中心的所有頁面都必須依賴于memberID這個字段,所以編碼時就忽略了memberId為空的這種情況,而且在我們的action層也對memberID為空的情況作了處理,具體代碼如下:
......
private void initMemberInfo(UCActionContext context) throws ProjectException {
// 驗證會員存在
if (memberId == null) {
throwException(MemberUtil.MEMBERID_INVALID_TITLE, MemberUtil.MEMBERID_INVALID_MSG);
}
......
所以理論上來說,對于memberId為空的情況不會進入后端處理的processor,所以后端也就沒有考慮到從context獲取memberID會為空,但是實際情況還是發生了,這段代碼也做了攔截,并拋出了異常,不過 在initMemberInfo這個方法的外層,又catch住了這個異常:
try
....
initMemberInfo(context);
catch(){
....
}
所以說ACTION做的處理并沒有起到攔截作用,導致這個null的memberid傳遞到了后端,后端出錯后被接入CAT的代碼抓住,導致主線程一直得不到返回。
2.為什么在壓力測試過程中沒有發生這個問題?
壓力測試過程時,當時批量處理方法barHandleExecute的源代碼如下所示,并沒有介入CAT監控代碼
protected void barHandleExecute(final UCActionContext context, final CountDownLatch countDownLatch, SideBar sideBar) {
.......
threadPoolTaskExecutor.execute(new Runnable() {
@Override
public void run() {
moduleProcessor.execute(context);
countDownLatch.countDown();
}
});
.......
}
這個地方為什么沒有做try catch,是考慮到我們一些并行的processor存在一些依賴關系,processorA出異常的話,processorB就算不出問題,也不渲染頁面。所以這里就不cacth異常,由具體的processor來決定是否cacth異常。所以在壓力測試過程,就算其中processor拋出異常,框架就認為這是某個依賴processor拋出的異常,就將這個異常拋到WEB,由最外層做控制,跳轉到統一的錯誤頁面。所以這主線程僵死的情況就不會出現。
3.周四上線的時候為什么沒有讓jboss僵死?
個人中心周四晚上9點多上線,當時訪問量也不是很大,就算碰到會導致一些無效的memberID的請求進入,也不會立刻讓JBOSS僵死。同時我們在周五下午又對個人中心做了一次上線,重啟了應用了,所以沒報出這個問題,但是在周五晚上,請求增大,各種復雜情況的請求進入后,就觸發了我們代碼中的缺陷,最終導致JBOSS僵死。
總結:
1.前段action攔截不合理,放入了memberId為NULL的請求,打開了系統出錯的門。
2.后端processor信任前段過來的數據,并沒有做防御式處理,導致空指針異常,同時又沒有將這段獲取數據的代碼納入try中,進一步將系統推向奔潰邊緣。
3.上線前接入CAT代碼,沒有考慮全面,這段代碼在自己本分(記錄系統執行開銷及異常)外干了不是它的事,cacth住了我們的系統異常,這個才是壓垮系統的最后一根稻草,導致系統雪崩。
4.框架本身考慮不夠全面,用一種靠擴展對自身的約束來處理異常情況,沒有分開的去處理:多個無關porcessor和多個存在關聯processor的兩種情況。
以上四步,只要不走錯一步,就不會出現周五晚上的JBOSS僵死問題??梢娨粋€重大錯誤大多是由一系列的錯誤連鎖導致的。