前言

  一个项目在经历开发、测试、上线后,当时的用户规模还比较小,所以刚刚上线的项目一般会表现稳定。但是随着时间的推移,用户数量的增加,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线程的阻塞。内容如下:

 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:)
- waiting to lock <0x00000007c01ed840> (a ch.qos.logback.core.spi.LogbackLock)
at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:)
at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:)
at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:)
at ch.qos.logback.classic.Logger.)
at com.uuzz.los.gateway.web.controller.RequestProcessorSupport.readHead(RequestProcessorSupport.java:)
at com.uuzz.los.gateway.web.controller.RequestProcessorSupport.process(RequestProcessorSupport.java:)
at sun.reflect.GeneratedMethodAccessor71.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:)
at java.lang.reflect.Method.invoke(Method.java:)
at org.springframework.web.bind.annotation.support.HandlerMethodInvoker.doInvokeMethod(HandlerMethodInvoker.java:)
at org.springframework.web.bind.annotation.support.HandlerMethodInvoker.invokeHandlerMethod(HandlerMethodInvoker.java:)
at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.invokeHandlerMethod(AnnotationMethodHandlerAdapter.java:)
at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.handle(AnnotationMethodHandlerAdapter.java:)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:)
at java.lang.Thread.run(Thread.java:)
由此可见是logback的日志输出对文件写锁导致。最后将logback改为异步方式,此阻塞再没有出现。
但是依然有大量的CobarSqlMapClientTemplate执行的线程等待,具体如下:
 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:)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:)
at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:)
at com.alibaba.cobar.client.support.execution.DefaultConcurrentRequestProcessor.process(DefaultConcurrentRequestProcessor.java:)
at com.alibaba.cobar.client.CobarSqlMapClientTemplate.executeInConcurrency(CobarSqlMapClientTemplate.java:)
at com.alibaba.cobar.client.CobarSqlMapClientTemplate.queryForObject(CobarSqlMapClientTemplate.java:)
at com.alibaba.cobar.client.CobarSqlMapClientTemplate.queryForObject(CobarSqlMapClientTemplate.java:)
at com.alibaba.cobar.client.CobarSqlMapClientTemplate.queryForObject(CobarSqlMapClientTemplate.java:)
at com.uuzz.los.account.dao.impl.UserInfoDaoImpl.getSequence(UserInfoDaoImpl.java:)
at com.uuzz.los.account.service.impl.AbstractUserInfoService.insertUserInfoAndUserDetail(AbstractUserInfoService.java:)
at com.uuzz.los.account.service.impl.AbstractUserInfoService$.doInTransaction(AbstractUserInfoService.java:)
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:)
at com.uuzz.los.account.service.impl.AbstractUserInfoService.register(AbstractUserInfoService.java:)
at com.uuzz.los.gwservice.service.standard.impl.UserServiceClientImpl.register(UserServiceClientImpl.java:)
at com.uuzz.los.gateway.facade.impl.standard.UserRegisterFacadeImpl.perform(UserRegisterFacadeImpl.java:)
at com.uuzz.los.gateway.facade.impl.standard.UserRegisterFacadeImpl.perform(UserRegisterFacadeImpl.java:)
at com.uuzz.los.gateway.facade.impl.BusinessFacadeSupport.handleResponse(BusinessFacadeSupport.java:)
at com.uuzz.los.gateway.facade.impl.BusinessFacadeSupport.doBusiness(BusinessFacadeSupport.java:)
at com.uuzz.los.gateway.facade.impl.BusinessFacadeSupport.doBusiness(BusinessFacadeSupport.java:)
at com.uuzz.los.gateway.web.controller.RequestProcessorSupport.process(RequestProcessorSupport.java:)
at sun.reflect.GeneratedMethodAccessor47.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:)
at java.lang.reflect.Method.invoke(Method.java:)
at org.springframework.web.bind.annotation.support.HandlerMethodInvoker.doInvokeMethod(HandlerMethodInvoker.java:)
at org.springframework.web.bind.annotation.support.HandlerMethodInvoker.invokeHandlerMethod(HandlerMethodInvoker.java:)
at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.invokeHandlerMethod(AnnotationMethodHandlerAdapter.java:)
at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.handle(AnnotationMethodHandlerAdapter.java:)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:)
at java.lang.Thread.run(Thread.java:)

可见是数据库资源阻塞引起。

使用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

记一次Web服务的性能调优的更多相关文章

  1. web移动端性能调优及16ms优化

    本文只是一个索引,收集了网络上大部分关于调试及优化方面的文章,从中挑选了一些比较好的文章分享给大家. 移动端性能不及桌面浏览器性能的10分之1,特别是在android设备良莠不齐的情况下,性能显得尤为 ...

  2. web前端性能调优(二)

    项目经过第一波优化之后APP端已基本已经符合我们的要求了,但是TV端还是反应比较慢,页面加载和渲染都比较慢了一点,我觉的还是有必要在进行一些优化,经过前面的优化,我们的优化空间已经小了一部分,不过还是 ...

  3. 性能调优之提高 ASP.NET Web 应用性能的 24 种方法和技巧

    性能调优之提高 ASP.NET Web 应用性能的 24 种方法和技巧   poptest是国内唯一一家培养测试开发工程师的培训机构,以学员能胜任自动化测试,性能测试,测试工具开发等工作为目标.如果对 ...

  4. 提高 web 应用性能之 CSS 性能调优

    简介 Web 开发中经常会遇到性能的问题,尤其是 Web 2.0 的应用.CSS 代码是控制页面显示样式与效果的最直接“工具”,但是在性能调优时他们通常被 Web 开发工程师所忽略,而事实上不规范的 ...

  5. Web服务端性能提升实践

    随着互联网的不断发展,日常生活中越来越多的需求通过网络来实现,从衣食住行到金融教育,从口袋到身份,人们无时无刻不依赖着网络,而且越来越多的人通过网络来完成自己的需求. 作为直接面对来自客户请求的Web ...

  6. web前端性能调优

    最近2个月一直在做手机端和电视端开发,开发的过程遇到过各种坑.弄到快元旦了,终于把上线了.2个月干下来满满的的辛苦,没有那么忙了自己准备把前端的性能调优总结以下,以方便以后自己再次使用到的时候得于得心 ...

  7. 记一次sql server 性能调优,查询从20秒至2秒

    一.需求 需求很简单,就是需要查询一个报表,只有1个表,数据量大约60万左右,但是中间有些逻辑. 先说明一下服务器配置情况:1核CPU.2GB内存.机械硬盘.Sqlserver 2008 R2.Win ...

  8. sql server 性能调优之 CPU消耗最大资源分析1 (自sqlserver服务启动以后)

    一. 概述 上次在介绍性能调优中讲到了I/O的开销查看及维护,这次介绍CPU的开销及维护, 在调优方面是可以从多个维度去发现问题如I/O,CPU,  内存,锁等,不管从哪个维度去解决,都能达到调优的效 ...

  9. web前端性能调优(一)

    最近2个月一直在做手机端和电视端开发,开发的过程遇到过各种坑.弄到快元旦了,终于把上线了.2个月干下来满满的的辛苦,没有那么忙了自己准备把前端的性能调优总结以下,以方便以后自己再次使用到的时候得于得心 ...

随机推荐

  1. sqlyog导出json数据格式支持mysql数据转存mongodb

    <!-------------知识的力量是无限的(当然肯定还有更简单的方法)-----------!> 当我考虑将省市区三级联动数据从mysql转入mongodb时遇到了网上无直接插入mo ...

  2. 谁动了我的特征?——sklearn特征转换行为全记录

    目录 1 为什么要记录特征转换行为?2 有哪些特征转换的方式?3 特征转换的组合4 sklearn源码分析 4.1 一对一映射 4.2 一对多映射 4.3 多对多映射5 实践6 总结7 参考资料 1 ...

  3. Objective-c 代理模式(delegate)

    Objective-c 代理模式(delegate) (2012-07-31 22:04:39) 转载▼ 标签: 杂谈 分类: iOS Objective-c 代理模式(delegate)     一 ...

  4. Nginx日志切割,以及脚本上传nginx的切割日志

    一:日志切割步骤 命令都在root下进行 1.创建目录 mkdir -p /etc/opt/modules/bin ## 创建文件夹 2.上传cut 3.观察目录 4.修改的cut文件 5.检测 需要 ...

  5. 装饰模式(Decorate Pattern)

    在不必改变原类文件和使用继承的情况下,动态地扩展一个对象的功能.它是通过创建一个包装对象,也就是装饰来包裹真实的对象. (1) 装饰对象和真实对象有相同的接口.这样客户端对象就能以和真实对象相同的方式 ...

  6. fill_parent和wrap_content的区别

    在Android布局文件中定义视图垂直或水平大小: android:layout_width和android_layout_height的属性有fill_parent.wrap_content和mat ...

  7. gradle使用eclipse debug 代码

    设置环境变量 unix,linux      export GRADLE_OPTS="-Xdebug -Xrunjdwp:transport=dt_socket,address=9999,s ...

  8. 查找DOM

    <!doctype html> <html lang="en"> <head> <meta charset="UTF-8&quo ...

  9. bzoj 1419 Red is good(期望DP)

    [题意] R红B蓝,选红得1选蓝失1,问最优状态下的期望得分. [思路] 设f[i][j]为i个Rj个B时的最优期望得分,则有转移式为: f[i][j]=max{ 0,(f[i-1][j]+1)*(i ...

  10. What is the innovator&rsquo;s solution&mdash;&mdash;什么才是创新的解决方案1

    最近学习MOT(management of Technology),研读了Christensen的<创新者的窘境>和<创新者的解答>,以下简称创新者系列.总觉得需要写点儿什么. ...