Remember the performance tuning of a Web service

Preface

A project in the development, testing, on-line, then the size of the user is still relatively small, so just on-line projects are generally stable performance. However, with the passage of time, the increase in the number of users, the increase in QPS and other factors will cause the project slowly show a half-day unresponsive situation. In the previous work also happened to encounter this process, at that time, the project carried out a lot of performance testing and tuning, today, with the help of Blog Park, the performance tuning process to write essays, hope to the vast number of Java back-end development engineers to provide help, but also take this opportunity to perform some summary of performance tuning work, To achieve the purpose of the memo.

testing tools and environmentsPerformance Testing Tools

• LoadRunner: A load testing tool that predicts system behavior and performance. LoadRunner is able to test the entire enterprise architecture by identifying and locating problems in a way that simulates the concurrent load and real-time performance monitoring of tens of thousands of users. Enterprises use LoadRunner to minimize test time, optimize performance, and accelerate the release cycle of application systems. The LoadRunner can be used for automated load testing of various architectures to predict system behavior and evaluate system performance.
• An integrated analysis tool for VISUALVM:JDK. Monitor application performance and memory usage, monitor application threads, thread dumps (thread dump) or heap dumps (heap dump), track memory leaks, monitor the garbage collector, perform memory and CPU analysis, save snapshots for offline analysis of applications At the same time, it also supports browsing and operation on Mbeans. Although the VISUALVM itself is running above JDK6, it can be monitored by the JDK1.4 version or later.
• Jstack: A thread snapshot used to generate the current moment of the Java virtual machine. A thread snapshot is a collection of method stacks that each thread in the current Java Virtual machine is executing, and the primary purpose of generating a thread snapshot is to locate the cause of a thread's long pauses, such as inter-thread deadlocks, dead loops, long waits to request external resources, and so on.
• JPS: JDK 1.5 provides a command to display all current Java process PID, simple and practical, it is very suitable for simple view of the current Java process on the Linux/unix platform.
• Performance reports for Awr:oracle.

Hardware Environment

192.168.19.28 deploys Tomcat Web services, writes data to the two different Oracle DB instances in 192.168.19.34 and 192.168.19.35 through a sub-library.

Register Interface TuningTest Scenario

Use LoadRunner to simulate 1000 concurrent users, incrementing by 5 users every 10 seconds.

Testing ProcessTest Phenomenon One

1. At the beginning of TPs there were about 800, 192.168.19.28 CPU utilization reached 10%,192.168.19.34 CPU utilization reached 3%,192.168.19.35 CPU utilization reached 3%.
2. When the number of concurrent users reached 80, the TPS reduced to 500,192.168.19.28 CPU utilization of about 20%, 192.168.19.34 CPU utilization reached 80%,192.168.19.35 CPU utilization reached 3%.
3. When the number of concurrent users reached 100, TPS reduced to 300,192.168.19.28 CPU utilization of about 30%, 192.168.19.34 CPU utilization more than 90%, 192.168.19.35 CPU utilization 3%.
4. When the number of concurrent users exceeds 200, the 192.168.19.28 CPU utilization is around 45% and the TPS is stable between 150--200.

Based on the above observation data, it is found that the database instance used for registration is only on 192.168.19.34 (due to the reason of the library), so there is no CPU change in 192.168.19.35. However, the CPU utilization of 192.168.19.34 is more than 90% when concurrent user 100, which is obviously unacceptable. All the database operations in the registration service are then dropped, leaving only the business logic to be tested.Test Phenomenon TwoRegardless of the number of concurrent users, until the largest 1000,tps is always stable at around 1400, the 192.168.19.28 CPU utilization is up to 50%,192.168.19.34 CPU utilization 6%,192.168.19.35 CPU utilization of 3%. This time the business logic in the registration service is dropped, leaving only one insert operation on the table T_user_info to continue the test.Test Phenomenon Three

1. The TPS has just started at about 800, 192.168.19.28 CPU Utilization 10%,192.168.19.34 CPU Utilization 3%,192.168.19.35 CPU utilization of 3%.
2. When the number of concurrent users reaches 80, the TPS drops to 600,192.168.19.28 CPU utilization of about 20%, 192.168.19.34 CPU Utilization 80%,192.168.19.35 CPU utilization 3%.
3. When the number of concurrent users reached 100, TPS reduced to 500,192.168.19.28 CPU utilization of about 30%, 192.168.19.34 CPU utilization more than 90%, 192.168.19.35 CPU utilization 3%.
4. When the number of concurrent users exceeds 200, the 192.168.19.28 CPU utilization is about 45% and the TPS is stable at 300--350.

using VISUALVM

According to the above test data, it is found that when the registered interface only has the business logic, the TPS is normal when the database operation is not performed, and when the operation database is even inserted into the table T_user_info, the TPS drops obviously, especially the 192.168.19.34 CPU utilization reaches above 90%. So I suspect the database is the reason. To further troubleshoot the cause, add the following JMX configuration to Tomcat:

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"

Start the VISUALVM remote connection by monitoring the Tomcat memory (shown in 1) and discovering that the minor GC garbage collection status was previously configured smoothly, and that the full GC only appears once at Tomcat startup, and no longer appears. (can start Jpstat service, install visual GC more intuitive)

Figure 1 VISUALVM remote monitoring tomcat

By dumping the Tomcat thread (using JPS and JSTACK,VISUALVM to dump the tomcat thread without reacting), there is a significant amount of blocking on the logback thread. The contents are as follows:

"http-8080-1000"Daemon prio=TenTid=0x00007fdbe48c4000Nid=0x7217Waiting forMonitor entry [0x00007fdb743d5000] Java.lang.Thread.State:BLOCKED ( onObjectmonitor) 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: the) at Ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders (Appenderattachableimpl.java: -) 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: the) at Com.uuzz.los.gateway.web.controller.RequestProcessorSupport.process (Requestprocessorsupport.java: About) at Sun.reflect.GeneratedMethodAccessor71.invoke (Unknown Source) at Sun.reflect.DelegatingMethodAccessorImpl.invoke (Delegatingmethodaccessorimpl.java: +) 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)

This shows that the Logback log output is caused by a file write lock. Finally, the logback is changed to asynchronous mode, and this blocking no longer appears. But there are still a lot of cobarsqlmapclienttemplate executing threads waiting, specifically as follows:

"http-8080-995"Daemon prio=TenTid=0x00007f2580897000Nid=0x7e1bWaiting on condition [0x00007f24e3933000] Java.lang.Thread.State:WAITING (parking) at Sun.misc.Unsafe.park (Native Method)-Parking towait  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: -) 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: the) 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: -) at Com.uuzz.los.account.service.impl.AbstractUserInfoService.register (Abstractuserinfoservice.java: the) at Com.uuzz.los.gwservice.service.standard.impl.UserServiceClientImpl.register (Userserviceclientimpl.java:  About) at Com.uuzz.los.gateway.facade.impl.standard.UserRegisterFacadeImpl.perform (Userregisterfacadeimpl.java:  the) 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: the) at Sun.reflect.GeneratedMethodAccessor47.invoke (Unknown Source) at Sun.reflect.DelegatingMethodAccessorImpl.invoke (Delegatingmethodaccessorimpl.java: +) 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)

Visible is caused by database resource blocking.

using AWR

Finally, combined with the Oracle-exported AWR execution report, it is found that SQL Soft parse is 0.43,sql hard parse to 0.01, logical read 85020.13, physical read 0.01, physical write 6.83, transaction rollback rate 0%, Cache hit ratio 100%, Execution plan of the library hit rate 99.99%, memory sequencing 100%, soft parsing 99.18%. The SQL in the description program is not hard-coded, and the cache utilization is high, as shown in 2.

Figure 2 AWR implementation report Part One

Finally see top 5 Timed events,3 shown.

Figure 3 The longest-taking event in the AWR execution report

Notice that waiting time is the first log file sync, which normally should be the first in the CPU. By combining the INSERT statements from the previous login interface, you can know that a large number of commit transactions are generated, resulting in a large number of log writes. Log write because of system reasons, concurrency is slow, resulting in slow insertion. Performance is greatly improved after the slow-wait issue that is written by the operations DBA to resolve the log.

Remember the performance tuning of a Web service