[[435677]]

背景

前段時間我們的服務遇到了性能瓶頸，由于前期需求太急沒有注意這方面的優化，到了要還技術債的時候就非常痛苦了。

在很低的 QPS 壓力下服務器 load 就能達到 10-20，CPU 使用率 60% 以上，而且在每次流量峰值時接口都會大量報錯，雖然使用了服務熔斷框架 Hystrix，但熔斷后服務卻遲遲不能恢復。每次變更上線更是提心吊膽，擔心會成為壓死駱駝的最后一根稻草，導致服務雪崩。

在需求終于緩下來后，leader 給我們定下目標，限我們在兩周內把服務性能問題徹底解決。近兩周的排查和梳理中，發現并解決了多個性能瓶頸，修改了系統熔斷方案，最終實現了服務能處理的 QPS 翻倍，能實現在極高 QPS（3-4倍）壓力下服務正常熔斷，且能在壓力降低后迅速恢復正常，以下是部分問題的排查和解決過程。

服務器高CPU、高負載

首先要解決的問題就是服務導致服務器整體負載高、CPU 高的問題。

我們的服務整體可以歸納為從某個存儲或遠程調用獲取到一批數據，然后就對這批數據進行各種花式變換，最后返回。由于數據變換的流程長、操作多，系統 CPU 高一些會正常，但平常情況下就 CPU us 50% 以上，還是有些夸張了。

我們都知道，可以使用 top 命令在服務器上查詢系統內各個進程的 CPU 和內存占用情況。可是 JVM 是 Java 應用的領地，想查看 JVM 里各個線程的資源占用情況該用什么工具呢？

jmc 是可以的，但使用它比較麻煩，要進行一系列設置。我們還有另一種選擇，就是使用 jtop，jtop 只是一個 jar 包，它的項目地址在 yujikiriki/jtop， 我們可以很方便地把它復制到服務器上，獲取到 java 應用的 pid 后，使用 java -jar jtop.jar [options] 即可輸出 JVM 內部統計信息。

jtop 會使用默認參數 -stack n打印出最耗 CPU 的 5 種線程棧。

形如： 

Heap Memory: INIT=134217728  USED=230791968  COMMITED=450363392  MAX=1908932608  
NonHeap Memory: INIT=2555904  USED=24834632  COMMITED=26411008  MAX=-1  
GC PS Scavenge  VALID  [PS Eden Space, PS Survivor Space]  GC=161  GCT=440  
GC PS MarkSweep  VALID  [PS Eden Space, PS Survivor Space, PS Old Gen]  GC=2  GCT=532  
ClassLoading LOADED=3118  TOTAL_LOADED=3118  UNLOADED=0  
Total threads: 608  CPU=2454 (106.88%)  USER=2142 (93.30%)  
NEW=0  RUNNABLE=6  BLOCKED=0  WAITING=2  TIMED_WAITING=600  TERMINATED=0  
main  TID=1  STATE=RUNNABLE  CPU_TIME=2039 (88.79%)  USER_TIME=1970 (85.79%) Allocted: 640318696  
    com.google.common.util.concurrent.RateLimiter.tryAcquire(RateLimiter.java:337)  
    io.zhenbianshu.TestFuturePool.main(TestFuturePool.java:23)  
RMI TCP Connection(2)-127.0.0.1  TID=2555  STATE=RUNNABLE  CPU_TIME=89 (3.89%)  USER_TIME=85 (3.70%) Allocted: 7943616  
    sun.management.ThreadImpl.dumpThreads0(Native Method)  
    sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:454)  
    me.hatter.tools.jtop.rmi.RmiServer.listThreadInfos(RmiServer.java:59)  
    me.hatter.tools.jtop.management.JTopImpl.listThreadInfos(JTopImpl.java:48)  
    sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)  
    ... ... 

通過觀察線程棧，我們可以找到要優化的代碼點。

在我們的代碼里，發現了很多 json 序列化和反序列化和 Bean 復制耗 CPU 的點，之后通過代碼優化，通過提升 Bean 的復用率，使用 PB 替代 json 等方式，大大降低了 CPU 壓力。

熔斷框架優化

服務熔斷框架上，我們選用了 Hystrix，雖然它已經宣布不再維護，更推薦使用 resilience4j 和阿里開源的 sentinel，但由于部門內技術棧是 Hystrix，而且它也沒有明顯的短板，就接著用下去了。

先介紹一下基本情況，我們在控制器接口最外層和內層 RPC 調用處添加了 Hystrix 注解，隔離方式都是線程池模式，接口處超時時間設置為 1000ms，最大線程數是 2000，內部 RPC 調用的超時時間設置為 200ms，最大線程數是 500。

響應時間不正常

要解決的第一個問題是接口的響應時間不正常。在觀察接口的 access 日志時，可以發現接口有耗時為 1200ms 的請求，有些甚至達到了 2000ms 以上。由于線程池模式下，Hystrix 會使用一個異步線程去執行真正的業務邏輯，而主線程則一直在等待，一旦等待超時，主線程是可以立刻返回的。所以接口耗時超過超時時間，問題很可能發生在 Hystrix 框架層、Spring 框架層或系統層。

這時候可以對運行時線程棧來分析，我使用 jstack 打印出線程棧，并將多次打印的結果制作成火焰圖（參見 應用調試工具-火焰圖）來觀察。

如上圖，可以看到很多線程都停在 LockSupport.park(LockSupport.java:175) 處，這些線程都被鎖住了，向下看來源發現是 HystrixTimer.addTimerListener(HystrixTimer.java:106), 再向下就是我們的業務代碼了。

Hystrix 注釋里解釋這些 TimerListener 是 HystrixCommand 用來處理異步線程超時的，它們會在調用超時時執行，將超時結果返回。而在調用量大時，設置這些 TimerListener 就會因為鎖而阻塞，進而導致接口設置的超時時間不生效。

接著排查調用量為什么 TimerListener 特別多。

由于服務在多個地方依賴同一個 RPC 返回值，平均一次接口響應會獲取同樣的值 3-5 次，所以接口內對這個 RPC 的返回值添加了 LocalCache。排查代碼發現 HystrixCommand 被添加在了 LocalCache 的 get 方法上，所以單機 QPS 1000 時，會通過 Hystrix 調用方法 3000-5000 次，進而產生大量的 Hystrix TimerListener。

代碼類似于：   

@HystrixCommand(  
           fallbackMethod = "fallBackGetXXXConfig",  
           commandProperties = {  
                   @HystrixProperty(name = "execution.isolation.thread.timeoutInMilliseconds", value = "200"),  
                   @HystrixProperty(name = "circuitBreaker.errorThresholdPercentage", value = "50")},  
           threadPoolProperties = {  
                   @HystrixProperty(name = "coreSize", value = "200"),  
                   @HystrixProperty(name = "maximumSize", value = "500"),  
                   @HystrixProperty(name = "allowMaximumSizeToDivergeFromCoreSize", value = "true")})  
   public XXXConfig getXXXConfig(Long uid) {  
       try {  
           return XXXConfigCache.get(uid);  
       } catch (Exception e) {  
           return EMPTY_XXX_CONFIG;  
       }  
   } 

修改代碼，將 HystrixCommand 修改到 localCache 的 load 方法上來解決這個問題。此外為了進一步降低 Hystrix 框架對性能的影響，將 Hystrix 的隔離策略改為了信號量模式，之后接口的最大耗時就穩定了。而且由于方法都在主線程執行，少了 Hystrix 線程池維護和主線程與 Hystrix 線程的上下文切換，系統 CPU 使用率又有進一步下降。

但使用信號量隔離模式也要注意一個問題：信號量只能限制方法是否能夠進入執行，在方法返回后再判斷接口是否超時并對超時進行處理，而無法干預已經在執行的方法，這可能會導致有請求超時時，一直占用一個信號量，但框架卻無法處理。

服務隔離和降級

另一個問題是服務不能按照預期的方式進行服務降級和熔斷，我們認為流量在非常大的情況下應該會持續熔斷時，而 Hystrix 卻表現為偶爾熔斷。

最開始調試 Hystrix 熔斷參數時，我們采用日志觀察法，由于日志被設置成異步，看不到實時日志，而且有大量的報錯信息干擾，過程低效而不準確。后來引入 Hystrix 的可視化界面后，才提升了調試效率。

Hystrix 可視化模式分為服務端和客戶端，服務端是我們要觀察的服務，需要在服務內引入 hystrix-metrics-event-stream 包并添加一個接口來輸出 Metrics 信息，再啟動 hystrix-dashboard 客戶端并填入服務端地址即可。

通過類似上圖的可視化界面，Hystrix 的整體狀態就展示得非常清楚了。

由于上文中的優化，接口的最大響應時間已經完全可控，可以通過嚴格限制接口方法的并發量來修改接口的熔斷策略了。假設我們能容忍的最大接口平均響應時間為 50ms，而服務能接受的最大 QPS 為 2000，那么可以通過 2000*50/1000=100 得到適合的信號量限制，如果被拒絕的錯誤數過多，可以再添加一些冗余。

這樣，在流量突變時，就可以通過拒絕一部分請求來控制接口接受的總請求數，而在這些總請求里，又嚴格限制了最大耗時，如果錯誤數過多，還可以通過熔斷來進行降級，多種策略同時進行，就能保證接口的平均響應時長了。

熔斷時高負載導致無法恢復

接下來就要解決接口熔斷時，服務負載持續升高，但在 QPS 壓力降低后服務遲遲無法恢復的問題。

在服務器負載特別高時，使用各種工具來觀測服務內部狀態，結果都是不靠譜的，因為觀測一般都采用打點收集的方式，在觀察服務的同時已經改變了服務。例如使用 jtop 在高負載時查看占用 CPU 最高的線程時，獲取到的結果總是 JVM TI 相關的棧。

不過，觀察服務外部可以發現，這個時候會有大量的錯誤日志輸出，往往在服務已經穩定好久了，還有之前的錯誤日志在打印，延時的單位甚至以分鐘計。大量的錯誤日志不僅造成 I/O 壓力，而且線程棧的獲取、日志內存的分配都會增加服務器壓力。而且服務早因為日志量大改為了異步日志，這使得通過 I/O 阻塞線程的屏障也消失了。

之后修改服務內的日志記錄點，在打印日志時不再打印異常棧，再重寫 Spring 框架的 ExceptionHandler，徹底減少日志量的輸出。結果符合預期，在錯誤量極大時，日志輸出也被控制在正常范圍，這樣熔斷后，就不會再因為日志給服務增加壓力，一旦 QPS 壓力下降，熔斷開關被關閉，服務很快就能恢復正常狀態。

Spring 數據綁定異常

另外，在查看 jstack 輸出的線程棧時，還偶然發現了一種奇怪的棧。 

at java.lang.Throwable.fillInStackTrace(Native Method)  
at java.lang.Throwable.fillInStackTrace(Throwable.java:783)  
  - locked <0x00000006a697a0b8> (a org.springframework.beans.NotWritablePropertyException) 
  ...  
org.springframework.beans.AbstractNestablePropertyAccessor.processLocalProperty(AbstractNestablePropertyAccessor.java:426)  
at org.springframework.beans.AbstractNestablePropertyAccessor.setPropertyValue(AbstractNestablePropertyAccessor.java:278)  
  ...  
at org.springframework.validation.DataBinder.doBind(DataBinder.java:735)  
at org.springframework.web.bind.WebDataBinder.doBind(WebDataBinder.java:197)  
at org.springframework.web.bind.ServletRequestDataBinder.bind(ServletRequestDataBinder.java:107)  
at org.springframework.web.method.support.InvocableHandlerMethod.getMethodArgumentValues(InvocableHandlerMethod.java:161)  
 ...  
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:991) 

jstack 的一次輸出中，可以看到多個線程的棧頂都停留在 Spring 的異常處理，但這時候也沒有日志輸出，業務也沒有異常，跟進代碼看了一下，Spring 竟然偷偷捕獲了異常且不做任何處理。 

List<PropertyAccessException> propertyAccessExceptions = null;  
List<PropertyValue> propertyValues = (pvs instanceof MutablePropertyValues ?  
    ((MutablePropertyValues) pvs).getPropertyValueList() : Arrays.asList(pvs.getPropertyValues()));  
for (PropertyValue pv : propertyValues) {  
  try {  
    // This method may throw any BeansException, which won't be caught  
    // here, if there is a critical failure such as no matching field.  
    // We can attempt to deal only with less serious exceptions.  
    setPropertyValue(pv);  
  }  
  catch (NotWritablePropertyException ex) {  
    if (!ignoreUnknown) {  
      throw ex;  
    }  
    // Otherwise, just ignore it and continue...  
  }  
  ... ...  
} 

結合代碼上下文再看，原來 Spring 在處理我們的控制器數據綁定，要處理的數據是我們的一個參數類 ApiContext。

控制器代碼類似于： 

@RequestMapping("test.json")  
 public Map testApi(@RequestParam(name = "id") String id, ApiContext apiContext) {} 

按照正常的套路，我們應該為這個 ApiContext 類添加一個參數解析器(HandlerMethodArgumentResolver)，這樣 Spring 會在解析這個參數時會調用這個參數解析器為方法生成一個對應類型的參數。可是如果沒有這么一個參數解析器，Spring 會怎么處理呢？

答案就是會使用上面的那段”奇怪”代碼，先創建一個空的 ApiContext 類，并將所有的傳入參數依次嘗試 set 進這個類，如果 set 失敗了，就 catch 住異常繼續執行，而 set 成功后，就完成了 ApiContext 類內一個屬性的參數綁定。

而不幸的是，我們的接口上層會為我們統一傳過來三四十個參數，所以每次都會進行大量的”嘗試綁定”，造成的異常和異常處理就會導致大量的性能損失，在使用參數解析器解決這個問題后，接口性能竟然有近十分之一的提升。

小結

性能優化不是一朝一夕的事，把技術債都堆到最后一塊解決絕不是什么好的選擇。平時多注意一些代碼寫法，在使用黑科技時注意一下其實現有沒有什么隱藏的坑才是正解，還可以進行定期的性能測試，及時發現并解決代碼里近期引入的不安定因素。