记一次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