前言
一個項目在經歷開發、測試、上線后，當時的用戶規模還比較小，所以剛剛上線的項目一般會表現穩定。但是隨着時間的推移，用戶數量的增加，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個用戶。
測試過程
測試現象一
- 剛開始tps有800左右，192.168.19.28的cpu利用率達到10%，192.168.19.34的cpu利用率達到3%，192.168.19.35的cpu利用率達到3%。
- 並發用戶數達到80時，tps降到500，192.168.19.28的cpu利用率達到20%左右，192.168.19.34的cpu利用率達到80%，192.168.19.35的cpu利用率達到3%。
- 並發用戶數達到100時，tps降到300，192.168.19.28的cpu利用率30%左右，192.168.19.34的cpu利用率90%以上，192.168.19.35的cpu利用率3%。
- 並發用戶數超過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的插入操作，繼續測試。
測試現象三
- 剛開始tps有800左右，192.168.19.28的cpu利用率10%，192.168.19.34的cpu利用率3%，192.168.19.35的cpu利用率3%。
- 並發用戶數達到80時，tps降到600，192.168.19.28的cpu利用率20%左右，192.168.19.34的cpu利用率80%，192.168.19.35的cpu利用率3%。
- 並發用戶數達到100時，tps降到500，192.168.19.28的cpu利用率30%左右，192.168.19.34的cpu利用率90%以上，192.168.19.35的cpu利用率3%。
- 並發用戶數超過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