微電平台
微電平台是集電銷、企業微信等于一體的綜合智能SCRM SAAS化系統，涵蓋多管道管理、全客戶生命周期管理、私域營銷營運等主要功能，承接了京東各業務線服務，專注于為業務提供職場外包式的一站式客戶管理及一體化私域營運服務。
導讀
本文介紹電銷系統【客戶名單離線打标流程】遇到jmq消費端吞吐下降40%、jsf接口服務機器假死問題時，從排查、反複驗證到最終解決問題并額外提升50%吞吐的過程，适合服務端研發同學，提供生産環遇到一些複雜問題時排查思路及解決方案，正确使用京東内部例如sgm、jmq、jsf等工具抓到問題根因并徹底解決，用技術為業務發展保駕護航~
下面開始介紹電銷系統實際生産環境遇到的離線黑名單打标流程吞吐問題。
事件背景
1、概述
每日淩晨夜間會為電銷系統億級客戶名單進行黑名單打标，平均速度為95萬名單/分鐘，黑名單jsf服務總tps約2萬，tp99在100~110ms，若夜間沒有完成标記加工操作，會導緻白天職場無法正常作業，并且存在客戶騷擾隐患、降低職場營運效率的問題，因外部接口依賴數量較多打标程式隻能淩晨啟動和結束。
2、複雜度
面向業務提供千人千面的配置功能，底層基于規則引擎設計實作，調用鍊路中包含衆多外部接口，例如金融刷單标記、風控标記、人群畫像标記、商城風控标記、商城實名标記等，包含的次元多、複雜度較高。
3、問題
早上通過監控發現黑名單打标沒有執行完成，表現為jmq消費端tp99過高、進而降低了打标程式吞吐，通過臨時擴容、下掉4台“問題機器” （上帝視角：其實是程式導緻的問題機器）提高吞吐，加速完成黑名單打标。
但，為什麼會頻繁有機器問題？為什麼少量機器有問題會降低40%吞吐？後續如何避免此類情況？
帶着上述問題，下面開啟問題根因定位及解決之旅~
抓出幕後黑手
1、為什麼幾台機器出問題就會導緻吞吐急劇下降？
如上圖所示，每有一條消息消費報錯（在本案例中是打到“問題機器”上），jmq會本地嘗試sleep後重新消費拉下來的所有消息（本案例中jmq的batchSize=10），即每次報錯産生的總耗時至少會增加一千毫秒，一共80台機器，jsf使用預設負載均衡算法，服務請求打到4台問題機器的機率是5%，jmq一次拉下來10條消息，隻要有一條消息命中“問題機器”就會極大降低吞吐。
綜上所述，少量機器有問題吞吐就會急劇降低的原因是jsf随機負載均衡算法下每個執行個體的命中率相同以及報錯後jmq consumer重試時預設休眠1秒的機制導緻。
解決：當然consumer不報錯是完全可以規避問題，那如果保證不了不報錯，可以通過：
1）修改jmq的重試次數、重試延遲時間來盡可能的減少影響
<jmq:consumer id="cusAttributionMarkConsumer" transport="jmqTransport">
<jmq:listener topic="${jmq.topic}" listener="jmqListener" retryDelay="10" maxRetryDelay="20" maxRetrys="1"/>
</jmq:consumer>
2）修改jsf負載均衡算法
配置樣例：
<jsf:consumer loadbalance="shortestresponse"/>
原理圖：
上圖中的consumer圖是從jsf wiki裡摘取，上面的紅字是看jsf代碼提取的關鍵資訊，總而言之就是：預設的random是完全随機算法，shortestresponse是基于響應時間、請求數權重進行負載均衡，是以使用shortestresponse算法可以很大程度上規避此類問題，類似于熔斷的作用（本次解決過程中也使用了jsf的執行個體熔斷、預熱能力，具體看jsf wiki，在此不過多介紹）。
2、如何判定是執行個體問題、找出有問題的執行個體ip？
通過監控觀察，耗時高的現象隻存在于4台機器上，第一反應确實是以為機器問題，但結合之前（1月份有過類似現象）的情況，覺得此事必有蹊跷。
下圖是第一反應認為是機器問題的日志（對應sgm監控這台機器耗時也是連續高），下掉此類機器确實可以臨時解決問題：
綜上所述，當時間段内耗時高或失敗的都是某個ip，此時可以判定該ip對應的執行個體有問題（例如網絡、硬體等），如果是大量ip存在類似現象，判定不是機器本身的問題，本案例涉及到的問題不是機器本身問題而是程式導緻的現象，繼續往下看揭曉答案。
3、是什麼導緻機器頻繁假死、成為故障機器？
通過上述分析可以得知，問題機器報錯為jsf線程池打滿，機器出問題期間tps幾乎為0，期間有請求過來就會報jsf線程池（非業務線程池）打滿，此時有兩種可能，一是jsf線程池有問題，二是jsf線程池的線程一直被占用着，抱着信任中間件的思路，選擇可能性二繼續排查。
通過行雲進行如下操作：
1）dump記憶體對象
無明顯問題，記憶體占用也不大，符合監控上的少量gc現象，繼續排查堆棧
2）jstack堆棧
從此來看與問題機器表象一緻了，基本得出結論：所有jsf線程都在waiting，是以有流量進來就會報jsf線程池滿錯誤，并且與機器cpu、記憶體都很低現象相符，繼續看詳細棧資訊，抽取兩個比較有代表的jsf線程。
線程編号JSF-BZ-22000-92-T-200：
stackTrace:
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000007280021f8> (a java.util.concurrent.FutureTask)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
at java.util.concurrent.FutureTask.get(FutureTask.java:191)
at com.jd.jr.scg.service.common.crowd.UserCrowdHitResult.isHit(UserCrowdHitResult.java:36)
at com.jd.jr.scg.service.impl.BlacklistTempNewServiceImpl.callTimes(BlacklistTempNewServiceImpl.java:409)
at com.jd.jr.scg.service.impl.BlacklistTempNewServiceImpl.hit(BlacklistTempNewServiceImpl.java:168)
線程編号JSF-BZ-22000-92-T-199：
stackTrace:
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000007286c9a68> (a java.util.concurrent.FutureTask)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
at java.util.concurrent.FutureTask.get(FutureTask.java:191)
at com.jd.jr.scg.service.biz.BlacklistBiz.isBlacklist(BlacklistBiz.java:337)
推斷：線程編号JSF-BZ-22000-92-T-200在UserCrowdHitResult的36行等待，線程編号JSF-BZ-22000-92-T-199在BlacklistBiz的337行等待，查到這，基本能推斷出問題原因是線程等待，造成問題的類似代碼場景是1）main線程讓線程池A去執行一個任務X；2）任務X中又讓同一個線程池去執行另一個任務，當第二步擷取不到線程時就會一直等，然後第一步又會一直等第二步執行完成，就是造成線程互相等待的假死現象。
小結：查到這基本可以确認問題，但因代碼維護人離職以及程式錯綜複雜，此時為驗證結論先修改業務線程池A線程數：50->200（此處是為了驗證沒有線程等待現象時的吞吐表現），再進行驗證，結論是tps會有小範圍抖動，但不會出現tps到0或是大幅降低的現象。
單機tps300~500，流量正常了，即未産生線程等待問題時可以正常提供服務，如圖：
印證推斷：通過堆棧定位到具體代碼，代碼邏輯如下：
BlacklistBiz->【線程池A】blacklistTempNewService.hit
blacklistTempNewService.hit->callTimes
callTimes->userCrowdServiceClient.isHit->【線程池A】crowdIdServiceRpc.groupFacadeHit
小結：BlacklistBiz作為主線程通過線程池A執行了blacklistTempNewService.hit任務，然後blacklistTempNewService.hit中又使用線程池A執行了crowdIdServiceRpc.groupFacadeHit造成了線程等待、假死現象，與上述推斷一緻，至此，問題已完成定位。
解決：辦法很簡單，額外新增一個線程池避免線程池嵌套使用。
4、意外收獲，發現一個影響黑名單服務性能的問題點
檢視堆棧資訊時發現存在大量waiting to lock的資訊：
問題：通過上述堆棧進而排查代碼發現一個服務鍊路中的3個方法使用了同一把鎖，性能不降低都怪了
解決：通過引入caffeine本地緩存替換掉原來使用同步鎖維護的手寫本地緩存。
5、額外收獲，你知道jsf線程池滿的時候報RpcException用戶端不會進行重試嗎？
這個讓我挺意外的，之前看jsf代碼以及和jsf架構師交流得到的資訊是：所有RpcException都會進行重試，重試的時候通過負載均衡算法重新找provider進行調用，但在實際驗證過程中發現若服務端報：handlerRequest error msg:[JSF-23003]Biz thread pool of provider has bean exhausted, the server port is 22001，用戶端不會發起重試，此結論最終與jsf架構師達成一緻，是以此類場景想要重試，需要在用戶端程式中想辦法，實作比較簡單，這裡不貼樣例了。
追加一些細節，感謝京東物流大佬@史建剛 進行了詳細論證：目前的jsf隻有在consumer抛出的RpcException才會進行重試，其他都不會重試（如上述provider抛出的異常會被當做正常傳回封包處理、consumer不會重試）。
總結
問題是打标流程沒有執行完，表象是jmqtp99升高、吞吐降低，這個時候如果打标jsf服務tp99飙高就能說明是服務問題，但恰恰相反（看着像請求量小而不是打标jsf服務本身問題），此時打标jsf服務tps低且tp99正常、記憶體及cpu等名額也都處于空閑狀态，但頻繁有jsf線程池耗盡的錯誤，是以進一步排查了堆棧、記憶體快照等資訊，最終定位到是業務線程等待導緻服務響應時長高、進而導緻打标服務jsf線程池耗盡報錯，也就是說jmq的tp99高實際不是打标jsf服務耗時高導緻、而是打标jsf服務報錯觸發了jmq重試機制（延遲及休眠）導緻了jmq吞吐降低的表象，最終定位及解決了線程等待問題，額外解決了一個影響打标jsf服務性能的鎖，并通過了解jmq、jsf一些配置原理及調優，達到了即使服務報錯也不至于大幅度影響mq吞吐的效果。
事件回顧
通過本次的問題解決，不但徹底解決了問題，還對影響性能的因素做了優化，最終效果有：
1、解決黑名單jsf服務線程等待安全隐患、去掉同步鎖提升吞吐，tps從2萬提升至3萬的情況下，tp99從100ms降低至65ms；
2、jmq重試等待及延遲時間調優，規避重試時吞吐大幅降低：tp99從1100ms降低至300ms；
3、jsf負載均衡算法調優，規避機器故障時仍然大量請求打到機器上，效果是服務相對穩定；
最終從8點多執行完提前至5點前完成，整體時間縮減了57%，并且即使機器出現“問題”也不會大幅降低整體吞吐，收益比較明顯。
優化後的運作圖如下：
寫在最後
微電平台雖說不在黃金鍊路，但場景複雜度（業務複雜度、rpa等機器人使用者複雜度）以及流量量級使我們經常面臨各種挑戰，好在我們都解決了，這裡共勉一句話：“在前進的路上總會有各種意想不到的情況，但是，都會撥雲見日”。