記一次Web服務的性能調優

前言

　　一個項目在經歷開發、測試、上線後，當時的用戶規模還比較小，因此剛剛上線的項目通常會表現穩定。可是隨着時間的推移，用戶數量的增長，qps的增長等因素會形成項目慢慢表現出網頁半天無響應的情況。在以前的工做中也恰巧遇到這個過程，當時對項目進行了不少性能測試和調優，今天藉助博客園，將此次性能調優的過程進行整理後寫成隨筆，但願給廣大Java後端開發的工程師提供幫助，也藉此機會，對性能調優進行一些總結工做，達到備忘的目的。

測試工具與環境

性能測試工具

• Loadrunner：一種預測系統行爲和性能的負載測試工具。經過以模擬上千萬用戶實施併發負載及實時性能監測的方式來確認和查找問題，LoadRunner可以對整個企業架構進行測試。企業使用LoadRunner能最大限度地縮短測試時間，優化性能和加速應用系統的發佈週期。 LoadRunner可適用於各類體系架構的自動負載測試，能預測系統行爲並評估系統性能。
• VisualVM：JDK的一個集成的分析工具。監控應用程序的性能和內存佔用狀況、監控應用程序的線程、進行線程轉儲(Thread Dump)或堆轉儲(Heap Dump)、跟蹤內存泄漏、監控垃圾回收器、執行內存和CPU分析，保存快照以便脫機分析應用程序；同時它還支持在MBeans上進行瀏覽和操做。儘管 VisualVM自身要在JDK6以上的運行，可是JDK1.4以上版本的程序它都能被它監控。
• Jstack：用於生成java虛擬機當前時刻的線程快照。線程快照是當前java虛擬機內每一條線程正在執行的方法堆棧的集合，生成線程快照的主要目的是定位線程出現長時間停頓的緣由，如線程間死鎖、死循環、請求外部資源致使的長時間等待等。
• Jps：是JDK 1.5提供的一個顯示當前全部java進程pid的命令，簡單實用，很是適合在linux/unix平臺上簡單察看當前java進程的一些簡單狀況。
• Awr：Oracle的性能報告。

硬件環境

　　192.168.19.28部署了Tomcat的web服務、經過分庫將數據寫入到192.168.19.34和192.168.19.35這兩個不一樣的Oracle數據庫實例中。

註冊接口調優

測試場景

　　使用Loadrunner模擬1000併發用戶，以每10秒鐘遞增5個用戶。

測試過程

測試現象一

1. 剛開始tps有800左右，192.168.19.28的cpu利用率達到10%，192.168.19.34的cpu利用率達到3%，192.168.19.35的cpu利用率達到3%。
2. 併發用戶數達到80時，tps降到500，192.168.19.28的cpu利用率達到20%左右，192.168.19.34的cpu利用率達到80%，192.168.19.35的cpu利用率達到3%。
3. 併發用戶數達到100時，tps降到300，192.168.19.28的cpu利用率30%左右，192.168.19.34的cpu利用率90%以上，192.168.19.35的cpu利用率3%。
4. 併發用戶數超過200時，192.168.19.28的cpu利用率45%左右，tps穩定在150——200之間。

　　根據以上觀測數據，發現註冊用到的數據庫實例只在192.168.19.34上（因爲分庫的緣由），因此192.168.19.35沒有什麼cpu的變化。可是192.168.19.34的的cpu利用率在併發用戶100時，就達到90%以上，這明顯是不能接受的。因而將註冊服務中的數據庫操做所有注掉，只保留業務邏輯，進行測試。

測試現象二

　　不管併發用戶是多少，直到最大的1000，tps始終穩定在1400左右，192.168.19.28的cpu利用率最大到50%，192.168.19.34的cpu利用率6%，192.168.19.35的cpu利用率3%。

　　此次將註冊服務中的業務邏輯注掉，只保留一條關於表t_user_info的插入操做，繼續測試。

測試現象三

1. 剛開始tps有800左右，192.168.19.28的cpu利用率10%，192.168.19.34的cpu利用率3%，192.168.19.35的cpu利用率3%。
2. 併發用戶數達到80時，tps降到600，192.168.19.28的cpu利用率20%左右，192.168.19.34的cpu利用率80%，192.168.19.35的cpu利用率3%。
3. 併發用戶數達到100時，tps降到500，192.168.19.28的cpu利用率30%左右，192.168.19.34的cpu利用率90%以上，192.168.19.35的cpu利用率3%。
4. 併發用戶數超過200時，192.168.19.28的cpu利用率45%左右，最後tps穩定在300——350。

使用VisualVM

根據以上測試數據，發現當註冊接口只存在業務邏輯，不進行數據庫操做時的tps正常，當操做數據庫甚至只是對錶t_user_info進行插入時，tps降低明顯，尤爲是192.168.19.34的cpu利用率達到90%以上，因此我懷疑是數據庫方面的緣由。爲了進一步排查緣由，給Tomcat增長如下Jmx配置：

JAVA_OPTS="$JAVA_OPTS -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=10207 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false"

啓動VisualVM遠程鏈接， 經過監控Tomcat內存（如圖1所示），發現以前已經配置好的minor GC垃圾回收狀態平穩，full GC只是在Tomcat啓動時出現一次，以後再也沒有出現。（能夠啓動jpstat服務，安裝visual GC更加直觀）

圖1 VisualVM遠程監控Tomcat

　　經過轉儲Tomcat線程（使用Jps和Jstack，VisualVM轉儲Tomcat線程沒有反應），發現有大量的有關logback線程的阻塞。內容以下：

"http-8080-1000" daemon prio=10 tid=0x00007fdbe48c4000 nid=0x7217 waiting for monitor entry [0x00007fdb743d5000]
   java.lang.Thread.State: BLOCKED (on object monitor)
at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:211)
- waiting to lock <0x00000007c01ed840> (a ch.qos.logback.core.spi.LogbackLock)
at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:148)
at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103)
at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:280)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:267)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:449)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:403)
at ch.qos.logback.classic.Logger.info(Logger.java:607)
at com.uuzz.los.gateway.web.controller.RequestProcessorSupport.readHead(RequestProcessorSupport.java:130)
at com.uuzz.los.gateway.web.controller.RequestProcessorSupport.process(RequestProcessorSupport.java:74)
at sun.reflect.GeneratedMethodAccessor71.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at org.springframework.web.bind.annotation.support.HandlerMethodInvoker.doInvokeMethod(HandlerMethodInvoker.java:421)
at org.springframework.web.bind.annotation.support.HandlerMethodInvoker.invokeHandlerMethod(HandlerMethodInvoker.java:136)
at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.invokeHandlerMethod(AnnotationMethodHandlerAdapter.java:326)
at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.handle(AnnotationMethodHandlerAdapter.java:313)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:875)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:807)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:571)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:511)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:859)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:602)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
at java.lang.Thread.run(Thread.java:722)

因而可知是logback的日誌輸出對文件寫鎖致使。最後將logback改成異步方式，此阻塞再沒有出現。

可是依然有大量的CobarSqlMapClientTemplate執行的線程等待，具體以下：

"http-8080-995" daemon prio=10 tid=0x00007f2580897000 nid=0x7e1b waiting on condition [0x00007f24e3933000]
   java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for  <0x0000000788b82410> (a java.util.concurrent.CountDownLatch$Sync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:994)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1303)
at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:236)
at com.alibaba.cobar.client.support.execution.DefaultConcurrentRequestProcessor.process(DefaultConcurrentRequestProcessor.java:85)
at com.alibaba.cobar.client.CobarSqlMapClientTemplate.executeInConcurrency(CobarSqlMapClientTemplate.java:911)
at com.alibaba.cobar.client.CobarSqlMapClientTemplate.queryForObject(CobarSqlMapClientTemplate.java:666)
at com.alibaba.cobar.client.CobarSqlMapClientTemplate.queryForObject(CobarSqlMapClientTemplate.java:704)
at com.alibaba.cobar.client.CobarSqlMapClientTemplate.queryForObject(CobarSqlMapClientTemplate.java:709)
at com.uuzz.los.account.dao.impl.UserInfoDaoImpl.getSequence(UserInfoDaoImpl.java:114)
at com.uuzz.los.account.service.impl.AbstractUserInfoService.insertUserInfoAndUserDetail(AbstractUserInfoService.java:212)
at com.uuzz.los.account.service.impl.AbstractUserInfoService$1.doInTransaction(AbstractUserInfoService.java:166)
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:128)
at com.uuzz.los.account.service.impl.AbstractUserInfoService.register(AbstractUserInfoService.java:160)
at com.uuzz.los.gwservice.service.standard.impl.UserServiceClientImpl.register(UserServiceClientImpl.java:99)
at com.uuzz.los.gateway.facade.impl.standard.UserRegisterFacadeImpl.perform(UserRegisterFacadeImpl.java:69)
at com.uuzz.los.gateway.facade.impl.standard.UserRegisterFacadeImpl.perform(UserRegisterFacadeImpl.java:1)
at com.uuzz.los.gateway.facade.impl.BusinessFacadeSupport.handleResponse(BusinessFacadeSupport.java:224)
at com.uuzz.los.gateway.facade.impl.BusinessFacadeSupport.doBusiness(BusinessFacadeSupport.java:141)
at com.uuzz.los.gateway.facade.impl.BusinessFacadeSupport.doBusiness(BusinessFacadeSupport.java:1)
at com.uuzz.los.gateway.web.controller.RequestProcessorSupport.process(RequestProcessorSupport.java:89)
at sun.reflect.GeneratedMethodAccessor47.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at org.springframework.web.bind.annotation.support.HandlerMethodInvoker.doInvokeMethod(HandlerMethodInvoker.java:421)
at org.springframework.web.bind.annotation.support.HandlerMethodInvoker.invokeHandlerMethod(HandlerMethodInvoker.java:136)
at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.invokeHandlerMethod(AnnotationMethodHandlerAdapter.java:326)
at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.handle(AnnotationMethodHandlerAdapter.java:313)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:875)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:807)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:571)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:511)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:859)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:602)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
at java.lang.Thread.run(Thread.java:722)

可見是數據庫資源阻塞引發。

使用AWR

　　最後結合Oracle導出的AWR執行報告，發現SQL軟解析爲0.43，SQL硬解析爲0.01，邏輯讀85020.13，物理讀0.01，物理寫6.83，事務回滾率0.00%，緩存命中率100%，執行計劃的Library命中率99.99%，內存排序100.00%，軟解析99.18%。說明程序中的SQL沒有硬編碼，緩存利用率高，如圖2所示。

 

圖2　　AWR執行報告部份內容一

最後查看Top 5 Timed Events，如圖3所示。

圖3　　AWR執行報告中佔用時間最長的事件

發現等待耗時排在第一的是log file sync ，正常狀況下，應當是CPU time排第一。結合以前登錄接口中的insert語句，能夠知道產生大量的commit的事務，產生大量的日誌寫。日誌寫因爲系統緣由，併發操做緩慢，最終致使插入緩慢。由運維DBA解決日誌寫的慢等待問題後，性能大幅提高。

 

如需轉載，請標明本文做者及出處——做者：jiaan.gja，本文原創首發：博客園，原文連接：http://www.cnblogs.com/jiaan-geng/p/5093133.html