背景

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

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

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

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

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

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

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

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

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

形如：

Heap Memory: INIT=134217728 USED=230791968 COMMITED=450363392 MAX=1908932608NonHeap Memory: INIT=2555904 USED=24834632 COMMITED=26411008 MAX=-1GC PS Scavenge VALID [PS Eden Space, PS Survivor Space] GC=161 GCT=440GC PS MarkSweep VALID [PS Eden Space, PS Survivor Space, PS Old Gen] GC=2 GCT=532ClassLoading LOADED=3118 TOTAL_LOADED=3118 UNLOADED=0Total threads:608 CPU=2454 (106.88%) USER=2142 (93.30%)

NEW=0 RUNNABLE=6 BLOCKED=0 WAITING=2 TIMED_WAITING=600 TERMINATED=0main TID=1 STATE=RUNNABLE CPU_TIME=2039 (88.79%) USER_TIME=1970 (85.79%) Allocted: 640318696com.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: 7943616sun.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)化的代碼點(diǎn)。

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

熔斷框架優(yōu)化

服務(wù)熔斷框架上，我們選用了 Hystrix，雖然它已經(jīng)宣布不再維護(hù)，更推薦使用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 的請求，有些甚至達(dá)到了 2000ms 以上。服務(wù)正常時，這種情況對于線程池隔離方式是不可能發(fā)生的，因?yàn)榫€程池模式下，Hystrix 會創(chuàng)建一個新的線程去執(zhí)行真正的業(yè)務(wù)邏輯，而主線程則一直在等待，一旦等待超時，主線程是可以立刻返回的。所以接口耗時超過超時時間，問題很可能發(fā)生在 Hystrix 框架層、Spring 框架層或系統(tǒng)層。

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

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

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

要解決這個問題，只能修改服務(wù)的隔離策略了，將 Hystrix 的隔離策略改為信號量模式。信號量模式下，Hystrix 會在每次執(zhí)行 HystrixCommand 時獲取一次信號量，在執(zhí)行結(jié)束后還回。由于信號量的操作效率非常高，而且沒有其他附加操作，所以在使用信號量隔離模式時不會有其他性能損耗。

但使用信號量隔離模式也要注意一個問題：信號量只能限制方法是否能夠進(jìn)入，如果可以進(jìn)入執(zhí)行，則在原來的主線程內(nèi)執(zhí)行，執(zhí)行的過程中 Hystrix 是無法干預(yù)的，只能在方法返回后再判斷接口是否超時并對超時進(jìn)行處理，這可能會導(dǎo)致有部分請求耗時超長時，一直占用一個信號量，但框架卻無法處理。

在修改了 Hystrix 的隔離模式后，接口的最大耗時就穩(wěn)定了，而且由于方法都在主線程執(zhí)行，少了 Hystrix 線程池維護(hù)和主線程與 Hystrix 線程的上下文切換，系統(tǒng) CPU 使用率又有進(jìn)一步下降。

服務(wù)隔離和降級

另一個問題是服務(wù)不能按照預(yù)期的方式進(jìn)行服務(wù)隔離和降級，我們認(rèn)為流量在非常大的情況下應(yīng)該會持續(xù)熔斷時，而 Hystrix 總表現(xiàn)為半熔斷半執(zhí)行，我們認(rèn)為多余的請求不會進(jìn)入方法內(nèi)部時，它們偏偏還能被執(zhí)行。

開始時，我們對日志進(jìn)行觀察，由于日志被設(shè)置成異步，看不到實(shí)時日志，而且有大量的報錯信息干擾，過程痛苦而低效。后來得知 Hystrix 還有可視化界面后，才算找到正確的調(diào)優(yōu)方式。

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

通過可視化界面，Hystrix 的整體狀態(tài)就展示得非常清楚了，我們就可以根據(jù)這些狀態(tài)信息對它的熔斷配置進(jìn)行調(diào)整了。由于上文的優(yōu)化，接口的最大響應(yīng)時間完全可控，可以通過嚴(yán)格限制接口方法的并發(fā)量來修改服務(wù)的拒絕策略了。

假設(shè)接口平均響應(yīng)時間為 50ms，而服務(wù)能容納的最大 QPS 為 2000，那么可以通過2000*50/1000=100得到適合的信號量限制，如果被拒絕的錯誤數(shù)過多，可以再添加一些冗余。

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

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

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

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

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

要驗(yàn)證這項猜測也很簡單，修改服務(wù)內(nèi)的日志記錄點(diǎn)，在打印日志時不再打印異常棧，再重寫 Spring 框架的 ExceptionHandler，徹底減少日志量的輸出。

結(jié)果非常符合預(yù)期，在錯誤量極大時，日志輸出也被控制在正常范圍，這樣熔斷后，就不會再因?yàn)槿罩窘o服務(wù)增加壓力，一旦 QPS 壓力下降，熔斷開關(guān)被關(guān)閉，服務(wù)很快就能恢復(fù)正常狀態(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)

at java.lang.Throwable.(Throwable.java:287)

at java.lang.Exception.(Exception.java:84)

at java.lang.RuntimeException.(RuntimeException.java:80)

at org.springframework.core.NestedRuntimeException.(NestedRuntimeException.java:66)

at org.springframework.beans.BeansException.(BeansException.java:50)

at org.springframework.beans.FatalBeanException.(FatalBeanException.java:45)

at org.springframework.beans.InvalidPropertyException.(InvalidPropertyException.java:54)

at org.springframework.beans.InvalidPropertyException.(InvalidPropertyException.java:43)

at org.springframework.beans.NotWritablePropertyException.(NotWritablePropertyException.java:77)

at org.springframework.beans.BeanWrapperImpl.createNotWritablePropertyException(BeanWrapperImpl.java:243)

at org.springframework.beans.AbstractNestablePropertyAccessor.processLocalProperty(AbstractNestablePropertyAccessor.java:426)

at org.springframework.beans.AbstractNestablePropertyAccessor.setPropertyValue(AbstractNestablePropertyAccessor.java:278)

at org.springframework.beans.AbstractNestablePropertyAccessor.setPropertyValue(AbstractNestablePropertyAccessor.java:266)

at org.springframework.beans.AbstractPropertyAccessor.setPropertyValues(AbstractPropertyAccessor.java:97)

at org.springframework.validation.DataBinder.applyPropertyValues(DataBinder.java:839)

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.servlet.mvc.method.annotation.ServletModelAttributeMethodProcessor.bindRequestParameters(ServletModelAttributeMethodProcessor.java:157)

at org.springframework.web.method.annotation.ModelAttributeMethodProcessor.resolveArgument(ModelAttributeMethodProcessor.java:153)

at org.springframework.web.method.support.HandlerMethodArgumentResolverComposite.resolveArgument(HandlerMethodArgumentResolverComposite.java:124)

at org.springframework.web.method.support.InvocableHandlerMethod.getMethodArgumentValues(InvocableHandlerMethod.java:161)

at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:131)

at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:102)

at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:877)

at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:783)

at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)

at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:991)

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

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) {throwex;

}//Otherwise, just ignore it and continue...

}

... ...

}

結(jié)合代碼上下文再看，原來 Spring 在處理我們的控制器數(shù)據(jù)綁定，要處理的數(shù)據(jù)是我們的一個上下文類 ApiContext，它是由多個字段組成的參數(shù)傳輸 Bean。

控制器代碼類似于：

@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 進(jìn)這個類，如果 set 失敗了，就 catch 住異常繼續(xù)執(zhí)行，而 set 成功后，就完成了 ApiContext 類內(nèi)一個屬性的參數(shù)綁定。

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

小結(jié)

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

關(guān)于本文有什么疑問可以在下面留言交流，如果您覺得本文對您有幫助，歡迎關(guān)注我的公眾號【Java技術(shù)zhai】，有新文章發(fā)布會第一時間通知您。

總結(jié)

以上是生活随笔為你收集整理的java服务端性能优化_记我的一次 Java 服务性能优化的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯，歡迎將生活随笔推薦給好友。