這次性能優(yōu)化， QPS 翻倍了

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

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

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

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

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

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

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

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

jtop 會使用默認參數(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)

????...?...

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

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

熔斷框架優(yōu)化

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

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

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

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

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

[

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

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

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

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

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

服務(wù)隔離和降級

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

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

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

[

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

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

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

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

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

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

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

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

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

另外，在查看 jstack 輸出的線程棧時，還偶然發(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 的一次輸出中，可以看到多個線程的棧頂都停留在 Spring 的異常處理，但這時候也沒有日志輸出，業(yè)務(wù)也沒有異常，跟進代碼看了一下，Spring 竟然偷偷捕獲了異常且不做任何處理。

List?propertyAccessExceptions?=?null;
??List?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é)合代碼上下文再看，原來 Spring 在處理我們的控制器數(shù)據(jù)綁定，要處理的數(shù)據(jù)是我們的一個參數(shù)類 ApiContext。

控制器代碼類似于：

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

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

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

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

小結(jié)

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