一次 Java 服務(wù)性能優(yōu)化實(shí)例詳解

背景

前段時(shí)間我們的服務(wù)遇到了性能瓶頸，由于前期需求太急沒(méi)有注意這方面的優(yōu)化，到了要還技術(shù)債的時(shí)候就非常痛苦了。

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

在需求終于緩下來(lái)后，leader 給我們定下目標(biāo)，限我們?cè)趦芍軆?nèi)把服務(wù)性能問(wèn)題徹底解決。近兩周的排查和梳理中，發(fā)現(xiàn)并解決了多個(gè)性能瓶頸，修改了系統(tǒng)熔斷方案，最終實(shí)現(xiàn)了服務(wù)能處理的 QPS 翻倍，能實(shí)現(xiàn)在極高 QPS（3-4倍）壓力下服務(wù)正常熔斷，且能在壓力降低后迅速恢復(fù)正常，以下是部分問(wèn)題的排查和解決過(guò)程。

服務(wù)器高CPU、高負(fù)載

首先要解決的問(wèn)題就是服務(wù)導(dǎo)致服務(wù)器整體負(fù)載高、CPU 高的問(wèn)題。

我們的服務(wù)整體可以歸納為從某個(gè)存儲(chǔ)或遠(yuǎn)程調(diào)用獲取到一批數(shù)據(jù)，然后就對(duì)這批數(shù)據(jù)進(jìn)行各種花式變換，最后返回。由于數(shù)據(jù)變換的流程長(zhǎng)、操作多，系統(tǒng) CPU 高一些會(huì)正常，但平常情況下就 CPU us 50% 以上，還是有些夸張了。

我們都知道，可以使用 top 命令在服務(wù)器上查詢系統(tǒng)內(nèi)各個(gè)進(jìn)程的 CPU 和內(nèi)存占用情況?？墒?JVM 是 Java 應(yīng)用的領(lǐng)地，想查看 JVM 里各個(gè)線程的資源占用情況該用什么工具呢？

jmc 是可以的，但使用它比較麻煩，要進(jìn)行一系列設(shè)置。我們還有另一種選擇，就是使用 jtop，jtop 只是一個(gè) jar 包，它的項(xiàng)目地址， 我們可以很方便地把它復(fù)制到服務(wù)器上，獲取到 java 應(yīng)用的 pid 后，使用 java -jar jtop.jar [options] <pid> 即可輸出 JVM 內(nèi)部統(tǒng)計(jì)信息。

jtop 會(huì)使用默認(rèn)參數(shù) -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)

  ... ...

通過(guò)觀察線程棧，我們可以找到要優(yōu)化的代碼點(diǎn)。

在我們的代碼里，發(fā)現(xiàn)了很多 json 序列化和反序列化和 Bean 復(fù)制耗 CPU 的點(diǎn)，之后通過(guò)代碼優(yōu)化，通過(guò)提升 Bean 的復(fù)用率，使用 PB 替代 json 等方式，大大降低了 CPU 壓力。

熔斷框架優(yōu)化

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

先介紹一下基本情況，我們?cè)诳刂破鹘涌谧钔鈱雍蛢?nèi)層 RPC 調(diào)用處添加了 Hystrix 注解，隔離方式都是線程池模式，接口處超時(shí)時(shí)間設(shè)置為 1000ms，最大線程數(shù)是 2000，內(nèi)部 RPC 調(diào)用的超時(shí)時(shí)間設(shè)置為 200ms，最大線程數(shù)是 500。

響應(yīng)時(shí)間不正常

要解決的第一個(gè)問(wèn)題是接口的響應(yīng)時(shí)間不正常。在觀察接口的 access 日志時(shí)，可以發(fā)現(xiàn)接口有耗時(shí)為 1200ms 的請(qǐng)求，有些甚至達(dá)到了 2000ms 以上。由于線程池模式下，Hystrix 會(huì)使用一個(gè)異步線程去執(zhí)行真正的業(yè)務(wù)邏輯，而主線程則一直在等待，一旦等待超時(shí)，主線程是可以立刻返回的。所以接口耗時(shí)超過(guò)超時(shí)時(shí)間，問(wèn)題很可能發(fā)生在 Hystrix 框架層、Spring 框架層或系統(tǒng)層。

這時(shí)候可以對(duì)運(yùn)行時(shí)線程棧來(lái)分析，我使用 jstack 打印出線程棧，并將多次打印的結(jié)果制作成火焰圖

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

Hystrix 注釋里解釋這些 TimerListener 是 HystrixCommand 用來(lái)處理異步線程超時(shí)的，它們會(huì)在調(diào)用超時(shí)時(shí)執(zhí)行，將超時(shí)結(jié)果返回。而在調(diào)用量大時(shí)，設(shè)置這些 TimerListener 就會(huì)因?yàn)殒i而阻塞，進(jìn)而導(dǎo)致接口設(shè)置的超時(shí)時(shí)間不生效。

接著排查調(diào)用量為什么 TimerListener 特別多。

由于服務(wù)在多個(gè)地方依賴同一個(gè) RPC 返回值，平均一次接口響應(yīng)會(huì)獲取同樣的值 3-5 次，所以接口內(nèi)對(duì)這個(gè) RPC 的返回值添加了 LocalCache。排查代碼發(fā)現(xiàn) HystrixCommand 被添加在了 LocalCache 的 get 方法上，所以單機(jī) QPS 1000 時(shí)，會(huì)通過(guò) Hystrix 調(diào)用方法 3000-5000 次，進(jìn)而產(chǎn)生大量的 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 方法上來(lái)解決這個(gè)問(wèn)題。此外為了進(jìn)一步降低 Hystrix 框架對(duì)性能的影響，將 Hystrix 的隔離策略改為了信號(hào)量模式，之后接口的最大耗時(shí)就穩(wěn)定了。而且由于方法都在主線程執(zhí)行，少了 Hystrix 線程池維護(hù)和主線程與 Hystrix 線程的上下文切換，系統(tǒng) CPU 使用率又有進(jìn)一步下降。

但使用信號(hào)量隔離模式也要注意一個(gè)問(wèn)題：信號(hào)量只能限制方法是否能夠進(jìn)入執(zhí)行，在方法返回后再判斷接口是否超時(shí)并對(duì)超時(shí)進(jìn)行處理，而無(wú)法干預(yù)已經(jīng)在執(zhí)行的方法，這可能會(huì)導(dǎo)致有請(qǐng)求超時(shí)時(shí)，一直占用一個(gè)信號(hào)量，但框架卻無(wú)法處理。

服務(wù)隔離和降級(jí)

另一個(gè)問(wèn)題是服務(wù)不能按照預(yù)期的方式進(jìn)行服務(wù)降級(jí)和熔斷，我們認(rèn)為流量在非常大的情況下應(yīng)該會(huì)持續(xù)熔斷時(shí)，而 Hystrix 卻表現(xiàn)為偶爾熔斷。

最開始調(diào)試 Hystrix 熔斷參數(shù)時(shí)，我們采用日志觀察法，由于日志被設(shè)置成異步，看不到實(shí)時(shí)日志，而且有大量的報(bào)錯(cuò)信息干擾，過(guò)程低效而不準(zhǔn)確。后來(lái)引入 Hystrix 的可視化界面后，才提升了調(diào)試效率。

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

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

由于上文中的優(yōu)化，接口的最大響應(yīng)時(shí)間已經(jīng)完全可控，可以通過(guò)嚴(yán)格限制接口方法的并發(fā)量來(lái)修改接口的熔斷策略了。 假設(shè)我們能容忍的最大接口平均響應(yīng)時(shí)間為 50ms，而服務(wù)能接受的最大 QPS 為 2000，那么可以通過(guò) 2000*50/1000=100 得到適合的信號(hào)量限制，如果被拒絕的錯(cuò)誤數(shù)過(guò)多，可以再添加一些冗余。

這樣，在流量突變時(shí)，就可以通過(guò)拒絕一部分請(qǐng)求來(lái)控制接口接受的總請(qǐng)求數(shù)，而在這些總請(qǐng)求里，又嚴(yán)格限制了最大耗時(shí)，如果錯(cuò)誤數(shù)過(guò)多，還可以通過(guò)熔斷來(lái)進(jìn)行降級(jí)，多種策略同時(shí)進(jìn)行，就能保證接口的平均響應(yīng)時(shí)長(zhǎng)了。

熔斷時(shí)高負(fù)載導(dǎo)致無(wú)法恢復(fù)

接下來(lái)就要解決接口熔斷時(shí)，服務(wù)負(fù)載持續(xù)升高，但在 QPS 壓力降低后服務(wù)遲遲無(wú)法恢復(fù)的問(wèn)題。

在服務(wù)器負(fù)載特別高時(shí)，使用各種工具來(lái)觀測(cè)服務(wù)內(nèi)部狀態(tài)，結(jié)果都是不靠譜的，因?yàn)橛^測(cè)一般都采用打點(diǎn)收集的方式，在觀察服務(wù)的同時(shí)已經(jīng)改變了服務(wù)。例如使用 jtop 在高負(fù)載時(shí)查看占用 CPU 最高的線程時(shí)，獲取到的結(jié)果總是 JVM TI 相關(guān)的棧。

不過(guò)，觀察服務(wù)外部可以發(fā)現(xiàn)，這個(gè)時(shí)候會(huì)有大量的錯(cuò)誤日志輸出，往往在服務(wù)已經(jīng)穩(wěn)定好久了，還有之前的錯(cuò)誤日志在打印，延時(shí)的單位甚至以分鐘計(jì)。大量的錯(cuò)誤日志不僅造成 I/O 壓力，而且線程棧的獲取、日志內(nèi)存的分配都會(huì)增加服務(wù)器壓力。而且服務(wù)早因?yàn)槿罩玖看蟾臑榱水惒饺罩?，這使得通過(guò) I/O 阻塞線程的屏障也消失了。

之后修改服務(wù)內(nèi)的日志記錄點(diǎn)，在打印日志時(shí)不再打印異常棧，再重寫 Spring 框架的 ExceptionHandler，徹底減少日志量的輸出。 結(jié)果符合預(yù)期，在錯(cuò)誤量極大時(shí)，日志輸出也被控制在正常范圍，這樣熔斷后，就不會(huì)再因?yàn)槿罩窘o服務(wù)增加壓力，一旦 QPS 壓力下降，熔斷開關(guān)被關(guān)閉，服務(wù)很快就能恢復(fù)正常狀態(tài)。

Spring 數(shù)據(jù)綁定異常

另外，在查看 jstack 輸出的線程棧時(shí)，還偶然發(fā)現(xiàn)了一種奇怪的棧。

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 的一次輸出中，可以看到多個(gè)線程的棧頂都停留在 Spring 的異常處理，但這時(shí)候也沒(méi)有日志輸出，業(yè)務(wù)也沒(méi)有異常，跟進(jìn)代碼看了一下，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...
  }
  ... ...
 }

結(jié)合代碼上下文再看，原來(lái) Spring 在處理我們的控制器數(shù)據(jù)綁定，要處理的數(shù)據(jù)是我們的一個(gè)參數(shù)類 ApiContext。

控制器代碼類似于：

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

按照正常的套路，我們應(yīng)該為這個(gè) ApiContext 類添加一個(gè)參數(shù)解析器(HandlerMethodArgumentResolver)，這樣 Spring 會(huì)在解析這個(gè)參數(shù)時(shí)會(huì)調(diào)用這個(gè)參數(shù)解析器為方法生成一個(gè)對(duì)應(yīng)類型的參數(shù)?？墒侨绻麤](méi)有這么一個(gè)參數(shù)解析器，Spring 會(huì)怎么處理呢？

答案就是會(huì)使用上面的那段”奇怪”代碼，先創(chuàng)建一個(gè)空的 ApiContext 類，并將所有的傳入?yún)?shù)依次嘗試 set 進(jìn)這個(gè)類，如果 set 失敗了，就 catch 住異常繼續(xù)執(zhí)行，而 set 成功后，就完成了 ApiContext 類內(nèi)一個(gè)屬性的參數(shù)綁定。

而不幸的是，我們的接口上層會(huì)為我們統(tǒng)一傳過(guò)來(lái)三四十個(gè)參數(shù)，所以每次都會(huì)進(jìn)行大量的”嘗試綁定”，造成的異常和異常處理就會(huì)導(dǎo)致大量的性能損失，在使用參數(shù)解析器解決這個(gè)問(wèn)題后，接口性能竟然有近十分之一的提升。

小結(jié)

性能優(yōu)化不是一朝一夕的事，把技術(shù)債都堆到最后一塊解決絕不是什么好的選擇。平時(shí)多注意一些代碼寫法，在使用黑科技時(shí)注意一下其實(shí)現(xiàn)有沒(méi)有什么隱藏的坑才是正解，還可以進(jìn)行定期的性能測(cè)試，及時(shí)發(fā)現(xiàn)并解決代碼里近期引入的不安定因素。

以上就是本文的全部?jī)?nèi)容，希望對(duì)大家的學(xué)習(xí)有所幫助，也希望大家多多支持億速云。