公司的項目有的頁面超級慢，20s以上，不知道用戶會不會瘋掉，于是老大說這個頁面要性能優化。于是，首先就要搞清楚究竟是哪一步耗時太多。

我采用spring aop來統計各個階段的用時，其中計時器工具為StopWatch。

文章結構：

遇到的問題

創建項目

AOP-HelloWorld

時間統計

bug

final

壓力測試

源碼

其中，遇到的問題:

1.少包aspectjweaver

添加依賴后才可以使用@Aspect

2.環繞通知加入多個point

剛開使用&&連接多個point，傻傻的看不到調用，忽然看到要用||才對

3.監聽時間工具StopWatch每次只能啟動一個，一定要關閉后才能啟動下一個。

而我想要測試controller->service->repository各個階段用時顯然很不適應。因為使用同一個stopwatch對象來保存時間，而stopwatch每次只能記錄一個時間段作為總時間的一部分，不存在時間嵌套關系（這個以后可以考慮想想別的方案）。controller開始后執行部分驗證邏輯或是其他，然后調用service，這時候service啟動定時會失敗，因為controller的計時器還沒關，因此需要先關掉controller的計時器。這樣會導致controller的計時部分僅僅是調用service之前的時間，service返回值之后，controller再進行某些處理的時間并沒有統計。顯然，我需要一個卡表的時間統計設計，即進入controller開始計時，調用service后開始service計時，以此類推，最后獲得controller總時間Tc，service總時間Ts，repository總時間Tr.所以時間統計應該如圖1：

? ? ? ? ? ? ? ??

? ? ? ? ? ? ? ?圖一 ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? 圖二

這樣的話，我應該分別獲得Tc,Ts,Tr的時間，然后計算百分比或者別的統計工作。也就是說，log僅僅是log，記錄而已，想要得到一個統計結果還需要針對數據二次開發，這就需要將時間存儲起來或者進行日志挖掘，然而這統計的工作會越來越復雜，最終我都不知會加多少任務進去。

事實上，我們這個頁面耗費時間主要是多個webservice調用產生的io耗時，也就是說其實統計一個層面的時間就差不多了。那么，忽略service返回后controller的其他時間，僅僅計算controller開始到調用service的時間為Tc,service開始到調用repository的時間為Ts，如圖2，這樣利用StopWatch就很容獲取時間統計結果。

4.線程不安全

我居然使用單例的一個成員變量做狀態存儲，真是。待改進

?

1.搭建項目

采用spring-boot-aop的框架來搭建。最終結構圖如下：

1.1在idea中，new project-》maven

1.2初始化pom，添加aop，web，test依賴：

<?xml version="1.0" encoding="UTF-8"?> <project xmlns="http://maven.apache.org/POM/4.0.0"xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd"><modelVersion>4.0.0</modelVersion><groupId>com.test</groupId><artifactId>spring-aop</artifactId><version>1.0-SNAPSHOT</version><dependencyManagement><dependencies><dependency><!-- Import dependency management from Spring Boot --><groupId>org.springframework.boot</groupId><artifactId>spring-boot-dependencies</artifactId><version>1.3.5.RELEASE</version><type>pom</type><scope>import</scope></dependency></dependencies></dependencyManagement><dependencies><dependency><groupId>org.springframework.boot</groupId><artifactId>spring-boot-starter-aop</artifactId></dependency><dependency><groupId>org.springframework.boot</groupId><artifactId>spring-boot-starter-web</artifactId></dependency><dependency><groupId>org.springframework.boot</groupId><artifactId>spring-boot-starter-test</artifactId><scope>test</scope></dependency><dependency><groupId>org.assertj</groupId><artifactId>assertj-core-java8</artifactId><version>1.0.0m1</version></dependency></dependencies><build><plugins><plugin><groupId>org.springframework.boot</groupId><artifactId>spring-boot-maven-plugin</artifactId></plugin></plugins></build></project>

　　

1.3創建啟動入口：com.test.spring.aop.Application.java

package com.test.spring.aop;import com.test.spring.aop.domain.service.IHelloService; import org.springframework.beans.factory.annotation.Autowired; import org.springframework.boot.CommandLineRunner; import org.springframework.boot.SpringApplication; import org.springframework.boot.autoconfigure.SpringBootApplication;/*** Created by miaorf on 2016/7/16.*/ @SpringBootApplication public class Application implements CommandLineRunner{@AutowiredIHelloService helloService;public void run(String... strings) throws Exception {System.out.println("start application by CommandLineRunner, the args:"+strings.length);helloService.sayHi();}public static void main(String[] args) throws Exception {SpringApplication.run(Application.class, args);} }

　　

1.4發現我們需要一個service:

創建com.test.spring.aop.domain.service.IHelloService

package com.test.spring.aop.domain.service;/*** Created by miaorf on 2016/7/16.*/ public interface IHelloService {void sayHi(); }

創建com.test.spring.aop.domain.service.impl.HelloService

package com.test.spring.aop.domain.service.impl;import com.test.spring.aop.domain.service.IHelloService; import org.springframework.beans.factory.annotation.Value; import org.springframework.stereotype.Service;/*** Created by miaorf on 2016/7/16.*/ @Service public class HelloService implements IHelloService {@Value("${name}")private String name;public void sayHi() {for (int i = 0; i < 100000; i++) {}System.out.println("Hi "+name);System.out.println("I'm running.");} }

　　

1.5發現我們需要一個屬性配置文件：

創建application.yml

1 name: Ryan View Code

?

1.6這時候可以測試一下啟動看看了

直接啟動：運行com.test.spring.aop.Application#main()即可。

命令行啟動：mvn spring-boot:run，

命令行bug啟動：mvn spring-boot:run -Drun.jvmArguments="-Xdebug -Xrunjdwp:transport=dt_socket,server=y,suspend=y,address=5005"

?

1.7創建測試com.test.spring.aop.ApplicationTest

package com.test.spring.aop;import org.junit.After; import org.junit.Before; import org.junit.Rule; import org.junit.Test; import org.springframework.boot.test.OutputCapture;import static org.assertj.core.api.Assertions.assertThat;/*** Created by miaorf on 2016/7/16.*/ public class ApplicationTest {@Rulepublic OutputCapture outputCapture = new OutputCapture();private String profiles;@Beforepublic void init() throws Exception {this.profiles = System.getProperty("spring.profiles.active");}@Afterpublic void tearDown() throws Exception {if (this.profiles != null){System.setProperty("spring.profiles.active",this.profiles);}else{System.out.println("spring.profiles.active");}}@Testpublic void testDefaultSettings() throws Exception{Application.main(new String[0]);String s = this.outputCapture.toString();assertThat(s).contains("Hi Ryan");}@Testpublic void testCommandLineOverrides() throws Exception {Application.main(new String[] {"--name=Leslie"});String s = this.outputCapture.toString();assertThat(s).contains("Hi Leslie");}} View Code

?

2.AOP - HelloWorld

2.1創建com.test.spring.aop.monitor.ServiceMonitor

package com.test.spring.aop.monitor;import org.aspectj.lang.ProceedingJoinPoint; import org.aspectj.lang.annotation.*; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.stereotype.Component; import org.springframework.util.StopWatch;/*** Created by miaorf on 2016/7/16.*/ @Aspect @Component public class ServiceMonitor {private static Logger logger = LoggerFactory.getLogger(ServiceMonitor.class);StopWatch stopWatch = new StopWatch("performance");/*** define point*/@Pointcut("execution(* com.test.spring.aop..*Service.*(..))")public void performance(){}// @Before("performance()") // public void startService(){ // System.out.println("-----------service start-------"); // } // @After("performance()") // public void endService(){ // System.out.println("-----------service end neither success or failed -------"); // } // // @AfterReturning("performance()") // public void logServiceAccess(JoinPoint joinPoint) { // System.out.println("service completed:"+joinPoint); // }/*** 必須要返回，不然后面收不到* @param point* @return*/@Around("performance()")public Object watchPerformance(ProceedingJoinPoint point){System.out.println("The service start:");stopWatch.start(point.getSignature().toString());try {return point.proceed();} catch (Throwable throwable) {logger.error("The service not work!",throwable);throwable.printStackTrace();}finally {stopWatch.stop();stopWatch.start("b");for (int i = 0; i < 12345; i++) {}stopWatch.stop();StopWatch.TaskInfo[] taskInfo = stopWatch.getTaskInfo();for (StopWatch.TaskInfo info : taskInfo) {System.out.println(info.getTaskName());System.out.println(info.getTimeMillis());}logger.info("The {} run time:{}",point.getSignature().toString(),stopWatch.prettyPrint());}return null;} } View Code

2.2測試

測試水平還沒開始，所以只能手動測試了，運行com.test.spring.aop.ApplicationTest可以看到在HelloService調用前后插入了日志。

?

3.時間統計

最終，生成類圖如下：

最終獲得的時間統計如下：

2016-07-16 21:25:09.361 INFO 16824 --- [nio-8080-exec-4] com.test.spring.aop.monitor.UserMonitor : StopWatch 'controller': running time (millis) = 3218 ----------------------------------------- ms % Task name ----------------------------------------- 01001 031% List com.test.spring.aop.domain.service.IUserService.getAll() 02000 062% Object com.test.spring.aop.domain.repository.IConnector.getSthFromRemote() 00217 007% List com.test.spring.aop.domain.repository.IUserDao.getAll()

?

3.1需要設計一個controller

創建com.test.spring.aop.web.UserController：

package com.test.spring.aop.web;import com.test.spring.aop.domain.entiry.User; import com.test.spring.aop.domain.service.IUserService; import org.springframework.beans.factory.annotation.Autowired; import org.springframework.stereotype.Controller; import org.springframework.web.bind.annotation.RequestMapping; import org.springframework.web.bind.annotation.ResponseBody;import java.util.List;/*** Created by miaorf on 2016/7/16.*/ @Controller @RequestMapping("/user") public class UserController {@Autowiredprivate IUserService userService;@ResponseBody@RequestMapping("/all")public List<User> users(){try {Thread.sleep(1000);} catch (InterruptedException e) {e.printStackTrace();}List<User> all = userService.getAll();return all;} } View Code

3.2發現需要一個service

創建com.test.spring.aop.domain.service.IUserService

package com.test.spring.aop.domain.service;import com.test.spring.aop.domain.entiry.User;import java.util.List;/*** Created by miaorf on 2016/7/16.*/ public interface IUserService {List<User> getAll(); } View Code

創建com.test.spring.aop.domain.service.impl.UserService

package com.test.spring.aop.domain.service.impl;import com.test.spring.aop.domain.entiry.User; import com.test.spring.aop.domain.repository.IConnector; import com.test.spring.aop.domain.repository.IUserDao; import com.test.spring.aop.domain.service.IUserService; import org.springframework.beans.factory.annotation.Autowired; import org.springframework.stereotype.Service;import java.util.List;/*** Created by miaorf on 2016/7/16.*/ @Service public class UserService implements IUserService {@Autowiredprivate IUserDao userDao;@Autowiredprivate IConnector connector;public List<User> getAll() {try {Thread.sleep(1000);} catch (InterruptedException e) {e.printStackTrace();}connector.getSthFromRemote();return userDao.getAll();} } View Code

3.3發現需要一個repository

創建com.test.spring.aop.domain.repository.IUserDao

package com.test.spring.aop.domain.repository;import com.test.spring.aop.domain.entiry.User;import java.util.List;/*** Created by miaorf on 2016/7/16.*/ public interface IUserDao {List<User> getAll(); } View Code

創建com.test.spring.aop.domain.repository.impl.UserDao

package com.test.spring.aop.domain.repository.impl;import com.test.spring.aop.domain.entiry.User; import com.test.spring.aop.domain.repository.IUserDao; import org.springframework.stereotype.Repository;import java.util.ArrayList; import java.util.List;/*** Created by miaorf on 2016/7/16.*/ @Repository public class UserDao implements IUserDao {public List<User> getAll() {//mock dataList<User> list = new ArrayList<User>(10000);for (int i = 0; i < 10000; i++) {list.add(new User(i,"name_"+i,getRondomString(6),i,i%2,getRondomString(100)));}return list;}private String getRondomString(int length){StringBuffer buf = new StringBuffer("a,b,c,d,e,f,g,h,i,g,k,l,m,n,o,p,q,r,s,t,u,v,w,x,y,z");buf.append(",A,B,C,D,E,F,G,H,I,G,K,L,M,N,O,P,Q,R,S,T,U,V,W,X,Y,Z");buf.append(",~,@,#,$,%,^,&,*,(,),_,+,|,`,.");buf.append(",1,2,3,4,5,6,7,8,9,0");String[] arr = buf.toString().split(",");StringBuffer result = new StringBuffer();for (int i = 0; i < length; i++) {int random = (int) (Math.random() * 10000 + 1);result.append(arr[random % arr.length]);}return result.toString();}} View Code

3.3.1臨時添加一個遠程調用

創建com.test.spring.aop.domain.repository.IConnector

package com.test.spring.aop.domain.repository;/*** Created by miaorf on 2016/7/16.*/ public interface IConnector {Object getSthFromRemote(); } View Code

創建com.test.spring.aop.domain.repository.impl.Connector

package com.test.spring.aop.domain.repository.impl;import com.test.spring.aop.domain.repository.IConnector; import org.springframework.stereotype.Component;/*** Created by miaorf on 2016/7/16.*/ @Component public class Connector implements IConnector {public Object getSthFromRemote() {//mock timetry {Thread.sleep(2000);} catch (InterruptedException e) {e.printStackTrace();}return null;} } View Code

?

3.4發現需要一個實體類

創建com.test.spring.aop.domain.entiry.User

package com.test.spring.aop.domain.entiry;/*** Created by miaorf on 2016/7/16.*/ public class User {Integer id;String username;String password;Integer age;Integer sex;String info;public User() {}public User(Integer id, String username, String password, Integer age, Integer sex, String info) {this.id = id;this.username = username;this.password = password;this.age = age;this.sex = sex;this.info = info;}public Integer getId() {return id;}public void setId(Integer id) {this.id = id;}public String getUsername() {return username;}public void setUsername(String username) {this.username = username;}public String getPassword() {return password;}public void setPassword(String password) {this.password = password;}public Integer getAge() {return age;}public void setAge(Integer age) {this.age = age;}public Integer getSex() {return sex;}public void setSex(Integer sex) {this.sex = sex;}public String getInfo() {return info;}public void setInfo(String info) {this.info = info;}@Overridepublic String toString() {return "User{" +"id=" + id +", username='" + username + '\'' +", password='" + password + '\'' +", age=" + age +", sex=" + sex +", info='" + info + '\'' +'}';} } View Code

3.5完成

以上就基本把一個web接口搞定了，可以運行測試一下，使用瀏覽器或者postman訪問localhost:8080/user/all就可以獲得user列表了。

?

3.6加入user時間統計

創建com.test.spring.aop.monitor.UserMonitor

package com.test.spring.aop.monitor;import org.aspectj.lang.ProceedingJoinPoint; import org.aspectj.lang.annotation.*; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.stereotype.Component; import org.springframework.util.StopWatch;/*** Created by miaorf on 2016/7/16.*/ @Aspect @Component public class UserMonitor {private static Logger logger = LoggerFactory.getLogger(UserMonitor.class);StopWatch stopWatch;@Pointcut("execution(* com.test.spring.aop.web.UserController.users())")public void controllerPerformance() {}@Pointcut("execution(* com.test.spring.aop.domain.service.impl.UserService.getAll())")public void servicePerformance() {}@Pointcut("execution(* com.test.spring.aop.domain.repository.impl.UserDao.getAll())")public void repositoryPerformance() {}@Pointcut("execution(* com.test.spring.aop.domain.repository.impl.Connector.getSthFromRemote())")public void connectorPerformance() {}@Before("controllerPerformance()")public void startWatch() {stopWatch = new StopWatch("controller");}@After("controllerPerformance()")public void endWatch() {logger.info(stopWatch.prettyPrint());stopWatch = null;}@Around("servicePerformance() || repositoryPerformance() || connectorPerformance()")public Object watchPerformance(ProceedingJoinPoint joinPoint) throws Throwable {System.out.println("---------------------------");try {//如果是一層一層的，這里只能統計到到下一層需要的時間，因為返回值后沒有統計，也就是說只能統計平行的調用if (stopWatch.isRunning()){stopWatch.stop();}stopWatch.start(joinPoint.getSignature().toString());} catch (IllegalStateException e) {logger.error("watch start error:",e);}Object proceed = joinPoint.proceed();try {if (stopWatch.isRunning()){stopWatch.stop();}} catch (IllegalStateException e) {logger.error("watch end error:",e);}return proceed;}} View Code

這里有幾點問題：

1.StopWatch不能重復創建，如果想統計每次controller訪問時間，必須在訪問前初始化，訪問后廢除。

2.這里的時間統計僅僅針對controller入口的統計，也就是說，如果別的調用了service，這個時間是不統計的，因為StopWatch沒有初始化。

3.StopWatch的prettyPrint是一個很好的東東

4.如果想要向開始那樣，完全統計每層耗時，這個設計需要重新設計。當前有這樣的想法。controller切點初始化三個或者多個StopWatch；service、repository等分別建立切點并計時；controller執行完畢之后的切點匯總統計數據，銷毀各個StopWatch。這樣就做到了每個層都統計了。然而問題來了，如果一個controller調用了多個service，顯然需要統計所有service耗時和單個service耗時。

?

Boo! Big Bug!!!

今早起來接著看，忽然想起spring bean管理是單例的，而且必須是單例的才可以使用共同的成員變量，但問題來了，spring的controller是多線程的。也就是說，這個切面進入不是排隊的，第一個請求過程中第二個請求也是可以進來的。那么，共享成員變量實在是愚蠢的決定。然而選擇創建一個類來管理對應一個請求的計時器也不好的，如果并發量超級大豈不是每個人都會產生一個類？

因此，這個計時器必須是一個過程量，可以在指定區間（即controller執行期間）生存，而后銷毀。對應的，顯然是每個并發請求會至少產生一個類。也就是說，我需要在controller請求的時候new 一個StopWatch的id，然后在接下來的一系列調用中都使用這個id對應的計時器，最后銷毀。如果幾百萬個并發量，那么就會產生幾百萬個類實例。懵逼。

?

最終選擇

通過一個實例來保存一次請求狀態太消耗性能，而如果不通過一個類實例保存狀態就無法匯總所有的時間。所以這個方案不合適。那么，剩下日志和傳入數據庫。當下就先記錄日志好了。記錄想要記錄的節點的時間：

package com.test.spring.aop.monitor;import org.aspectj.lang.ProceedingJoinPoint; import org.aspectj.lang.Signature; import org.aspectj.lang.annotation.Around; import org.aspectj.lang.annotation.Aspect; import org.aspectj.lang.annotation.Pointcut; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.stereotype.Component; import org.springframework.util.StopWatch;/*** Created by miaorf on 2016/7/16.*/ @Aspect @Component public class UserMonitor {private static Logger logger = LoggerFactory.getLogger(UserMonitor.class);@Pointcut("execution(* com.test.spring.aop.web.UserController.users())")public void controllerPerformance() {}@Pointcut("execution(* com.test.spring.aop.domain.service.impl.UserService.getAll())")public void servicePerformance() {}@Pointcut("execution(* com.test.spring.aop.domain.repository.impl.UserDao.getAll())")public void repositoryPerformance() {}@Pointcut("execution(* com.test.spring.aop.domain.repository.impl.Connector.getSthFromRemote())")public void connectorPerformance() {}@Around("controllerPerformance() || servicePerformance() || repositoryPerformance() || connectorPerformance()")public Object watchPerformance(ProceedingJoinPoint joinPoint) throws Throwable {Signature signature = joinPoint.getSignature();logger.info("=================start {}=====================",signature.getName());StopWatch stopWatch = new StopWatch("controller");try {if (stopWatch.isRunning()) {stopWatch.stop();}stopWatch.start(signature.toString());} catch (IllegalStateException e) {logger.error("watch start error:", e);}Object proceed = joinPoint.proceed();try {if (stopWatch.isRunning()) {stopWatch.stop();logger.info(stopWatch.prettyPrint()+"\n================= end {}=====================",signature.getName());}} catch (IllegalStateException e) {logger.error("watch end error:", e);}return proceed;}} View Code

?

壓力測試

1.建立test case

首先，測試controller：創建com.test.spring.aop.web.UserControllerTest

package com.test.spring.aop.web;import com.test.spring.aop.Application; import org.junit.Assert; import org.junit.Before; import org.junit.Test; import org.junit.runner.RunWith; import org.springframework.beans.factory.annotation.Autowired; import org.springframework.boot.test.SpringApplicationConfiguration; import org.springframework.test.context.junit4.SpringJUnit4ClassRunner; import org.springframework.test.context.web.WebAppConfiguration; import org.springframework.test.web.servlet.MockMvc; import org.springframework.test.web.servlet.MvcResult; import org.springframework.test.web.servlet.request.MockMvcRequestBuilders; import org.springframework.test.web.servlet.result.MockMvcResultHandlers; import org.springframework.test.web.servlet.result.MockMvcResultMatchers; import org.springframework.test.web.servlet.setup.MockMvcBuilders; import org.springframework.web.context.WebApplicationContext;import static org.junit.Assert.*;/*** Created by miaorf on 2016/7/17.*/ @RunWith(SpringJUnit4ClassRunner.class) @SpringApplicationConfiguration(Application.class) @WebAppConfiguration public class UserControllerTest {@Autowiredprivate WebApplicationContext wac;private MockMvc mockMvc;@Beforepublic void setUp() {mockMvc = MockMvcBuilders.webAppContextSetup(wac).build();}@Testpublic void testUsers() throws Exception {MvcResult result = mockMvc.perform(MockMvcRequestBuilders.get("/user/all")).andExpect(MockMvcResultMatchers.status().isOk()).andExpect(MockMvcResultMatchers.jsonPath("$[0].id").value(0)) // .andDo(MockMvcResultHandlers.print()) .andReturn();}@Testpublic void testUsersConcurrent() throws Exception{for (int i = 0; i < 10; i++) {new Thread(() -> {try {mockMvc.perform(MockMvcRequestBuilders.get("/user/all")).andExpect(MockMvcResultMatchers.status().isOk());} catch (Exception e) {e.printStackTrace();}}).run();}}} View Code

不知道為啥，我的new Thread并沒有并發執行，而是按順序執行的。也就是說，雖然我new 10 個Thread，但還是一個接一個的運行。

?

改進
于是，我想采用線程池：

@Testpublic void testUsersConcurrent() throws Exception{ThreadPoolExecutor executor = new ThreadPoolExecutor(5,10,200, TimeUnit.MILLISECONDS,new ArrayBlockingQueue<Runnable>(5));//不能超過15for (int i = 0; i < 15; i++) {executor.execute(()->{try {mockMvc.perform(MockMvcRequestBuilders.get("/user/all")).andExpect(MockMvcResultMatchers.status().isOk());} catch (Exception e) {e.printStackTrace();}});}//等待其他線程執行,方便查看控制臺打印結果Thread.sleep(100000);}

　　

這下就可以看到controller是多線程并發的了，因為瞬間就打印了10條controller訪問日志，正好是線程池的最大容量：

016-07-17 12:20:10.336 INFO 12792 --- [ main] o.s.t.web.servlet.TestDispatcherServlet : FrameworkServlet '': initialization completed in 24 ms 2016-07-17 12:20:10.431 INFO 12792 --- [pool-1-thread-8] com.test.spring.aop.monitor.UserMonitor : =================start UserController.users()===================== 2016-07-17 12:20:10.431 INFO 12792 --- [pool-1-thread-6] com.test.spring.aop.monitor.UserMonitor : =================start UserController.users()===================== 2016-07-17 12:20:10.431 INFO 12792 --- [pool-1-thread-4] com.test.spring.aop.monitor.UserMonitor : =================start UserController.users()===================== 2016-07-17 12:20:10.431 INFO 12792 --- [pool-1-thread-2] com.test.spring.aop.monitor.UserMonitor : =================start UserController.users()===================== 2016-07-17 12:20:10.432 INFO 12792 --- [ool-1-thread-10] com.test.spring.aop.monitor.UserMonitor : =================start UserController.users()===================== 2016-07-17 12:20:10.432 INFO 12792 --- [pool-1-thread-3] com.test.spring.aop.monitor.UserMonitor : =================start UserController.users()===================== 2016-07-17 12:20:10.432 INFO 12792 --- [pool-1-thread-7] com.test.spring.aop.monitor.UserMonitor : =================start UserController.users()===================== 2016-07-17 12:20:10.432 INFO 12792 --- [pool-1-thread-5] com.test.spring.aop.monitor.UserMonitor : =================start UserController.users()===================== 2016-07-17 12:20:10.432 INFO 12792 --- [pool-1-thread-1] com.test.spring.aop.monitor.UserMonitor : =================start UserController.users()===================== 2016-07-17 12:20:10.432 INFO 12792 --- [pool-1-thread-9] com.test.spring.aop.monitor.UserMonitor : =================start UserController.users()===================== View Code

?

2.采用Apache 的ab進行并發訪問

2.1下載Apache

參考：使用Apache Server 的ab進行web請求壓力測試

2.2測試

D:\Java\httpd-2.4.23-x64-vc14\Apache24\bin>ab -n 20 -c 10 localhost:8080/user/all This is ApacheBench, Version 2.3 <$Revision: 1748469 $> Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/ Licensed to The Apache Software Foundation, http://www.apache.org/ Benchmarking localhost (be patient).....doneServer Software: Apache-Coyote/1.1 Server Hostname: localhost Server Port: 8080Document Path: /user/all Document Length: 1836671 bytesConcurrency Level: 10 Time taken for tests: 31.199 seconds Complete requests: 20 Failed requests: 0 Total transferred: 36736380 bytes HTML transferred: 36733420 bytes Requests per second: 0.64 [#/sec] (mean) Time per request: 15599.677 [ms] (mean) Time per request: 1559.968 [ms] (mean, across all concurrent requests) Transfer rate: 1149.88 [Kbytes/sec] receivedConnection Times (ms)min mean[+/-sd] median max Connect: 0 0 0.4 0 1 Processing: 14785 15524 600.3 16085 16148 Waiting: 14593 15310 505.1 15781 15831 Total: 14785 15524 600.3 16085 16148Percentage of the requests served within a certain time (ms)50% 1608566% 1609075% 1609980% 1611490% 1614095% 1614898% 1614899% 16148100% 16148 (longest request) View Code

?

可以看到服務端是多線程的：

2016-07-17 12:26:28.455 INFO 18580 --- [ main] com.test.spring.aop.Application : Started Application in 8.37 seconds (JVM running for 9.23) 2016-07-17 12:26:40.966 INFO 18580 --- [nio-8080-exec-9] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring FrameworkServlet 'dispatcherServlet' 2016-07-17 12:26:40.966 INFO 18580 --- [nio-8080-exec-9] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization started 2016-07-17 12:26:40.992 INFO 18580 --- [nio-8080-exec-9] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization completed in 25 ms 2016-07-17 12:26:41.049 INFO 18580 --- [nio-8080-exec-5] com.test.spring.aop.monitor.UserMonitor : =================start UserController.users()===================== 2016-07-17 12:26:41.049 INFO 18580 --- [io-8080-exec-10] com.test.spring.aop.monitor.UserMonitor : =================start UserController.users()===================== 2016-07-17 12:26:41.049 INFO 18580 --- [nio-8080-exec-8] com.test.spring.aop.monitor.UserMonitor : =================start UserController.users()===================== 2016-07-17 12:26:41.050 INFO 18580 --- [nio-8080-exec-7] com.test.spring.aop.monitor.UserMonitor : =================start UserController.users()===================== 2016-07-17 12:26:41.050 INFO 18580 --- [nio-8080-exec-2] com.test.spring.aop.monitor.UserMonitor : =================start UserController.users()===================== 2016-07-17 12:26:41.050 INFO 18580 --- [nio-8080-exec-1] com.test.spring.aop.monitor.UserMonitor : =================start UserController.users()===================== 2016-07-17 12:26:41.050 INFO 18580 --- [nio-8080-exec-3] com.test.spring.aop.monitor.UserMonitor : =================start UserController.users()===================== 2016-07-17 12:26:41.050 INFO 18580 --- [nio-8080-exec-4] com.test.spring.aop.monitor.UserMonitor : =================start UserController.users()===================== 2016-07-17 12:26:41.051 INFO 18580 --- [nio-8080-exec-6] com.test.spring.aop.monitor.UserMonitor : =================start UserController.users()===================== 2016-07-17 12:26:41.051 INFO 18580 --- [nio-8080-exec-9] com.test.spring.aop.monitor.UserMonitor : =================start UserController.users()===================== 2016-07-17 12:26:51.061 INFO 18580 --- [nio-8080-exec-1] com.test.spring.aop.monitor.UserMonitor : =================start IUserService.getAll()===================== 2016-07-17 12:26:51.061 INFO 18580 --- [nio-8080-exec-6] com.test.spring.aop.monitor.UserMonitor : =================start IUserService.getAll()===================== 2016-07-17 12:26:51.061 INFO 18580 --- [nio-8080-exec-9] com.test.spring.aop.monitor.UserMonitor : =================start IUserService.getAll()===================== 2016-07-17 12:26:51.061 INFO 18580 --- [io-8080-exec-10] com.test.spring.aop.monitor.UserMonitor : =================start IUserService.getAll()===================== 2016-07-17 12:26:51.061 INFO 18580 --- [nio-8080-exec-3] com.test.spring.aop.monitor.UserMonitor : =================start IUserService.getAll()===================== 2016-07-17 12:26:51.061 INFO 18580 --- [nio-8080-exec-2] com.test.spring.aop.monitor.UserMonitor : =================start IUserService.getAll()===================== 2016-07-17 12:26:51.061 INFO 18580 --- [nio-8080-exec-4] com.test.spring.aop.monitor.UserMonitor : =================start IUserService.getAll()===================== 2016-07-17 12:26:51.061 INFO 18580 --- [nio-8080-exec-8] com.test.spring.aop.monitor.UserMonitor : =================start IUserService.getAll()===================== 2016-07-17 12:26:51.062 INFO 18580 --- [nio-8080-exec-5] com.test.spring.aop.monitor.UserMonitor : =================start IUserService.getAll()===================== 2016-07-17 12:26:51.062 INFO 18580 --- [nio-8080-exec-7] com.test.spring.aop.monitor.UserMonitor : =================start IUserService.getAll()===================== 2016-07-17 12:26:52.062 INFO 18580 --- [nio-8080-exec-9] com.test.spring.aop.monitor.UserMonitor : =================start IConnector.getSthFromRemote()===================== 2016-07-17 12:26:52.062 INFO 18580 --- [nio-8080-exec-6] com.test.spring.aop.monitor.UserMonitor : =================start IConnector.getSthFromRemote()===================== 2016-07-17 12:26:52.062 INFO 18580 --- [nio-8080-exec-1] com.test.spring.aop.monitor.UserMonitor : =================start IConnector.getSthFromRemote()===================== 2016-07-17 12:26:52.063 INFO 18580 --- [io-8080-exec-10] com.test.spring.aop.monitor.UserMonitor : =================start IConnector.getSthFromRemote()===================== 2016-07-17 12:26:52.063 INFO 18580 --- [nio-8080-exec-3] com.test.spring.aop.monitor.UserMonitor : =================start IConnector.getSthFromRemote()===================== 2016-07-17 12:26:52.063 INFO 18580 --- [nio-8080-exec-2] com.test.spring.aop.monitor.UserMonitor : =================start IConnector.getSthFromRemote()===================== 2016-07-17 12:26:52.063 INFO 18580 --- [nio-8080-exec-8] com.test.spring.aop.monitor.UserMonitor : =================start IConnector.getSthFromRemote()===================== 2016-07-17 12:26:52.063 INFO 18580 --- [nio-8080-exec-4] com.test.spring.aop.monitor.UserMonitor : =================start IConnector.getSthFromRemote()===================== 2016-07-17 12:26:52.063 INFO 18580 --- [nio-8080-exec-5] com.test.spring.aop.monitor.UserMonitor : =================start IConnector.getSthFromRemote()===================== 2016-07-17 12:26:52.063 INFO 18580 --- [nio-8080-exec-7] com.test.spring.aop.monitor.UserMonitor : =================start IConnector.getSthFromRemote()===================== 2016-07-17 12:26:54.063 INFO 18580 --- [nio-8080-exec-6] com.test.spring.aop.monitor.UserMonitor : StopWatch 'controller': running time (millis) = 2000 ----------------------------------------- ms % Task name ----------------------------------------- 02000 100% Object com.test.spring.aop.domain.repository.IConnector.getSthFromRemote()================= end IConnector.getSthFromRemote()===================== 2016-07-17 12:26:54.063 INFO 18580 --- [nio-8080-exec-9] com.test.spring.aop.monitor.UserMonitor : StopWatch 'controller': running time (millis) = 2001 ----------------------------------------- ms % Task name ----------------------------------------- 02001 100% Object com.test.spring.aop.domain.repository.IConnector.getSthFromRemote()================= end IConnector.getSthFromRemote()===================== 2016-07-17 12:26:54.063 INFO 18580 --- [nio-8080-exec-3] com.test.spring.aop.monitor.UserMonitor : StopWatch 'controller': running time (millis) = 2000 ----------------------------------------- ms % Task name ----------------------------------------- 02000 100% Object com.test.spring.aop.domain.repository.IConnector.getSthFromRemote()================= end IConnector.getSthFromRemote()===================== 2016-07-17 12:26:54.063 INFO 18580 --- [nio-8080-exec-1] com.test.spring.aop.monitor.UserMonitor : StopWatch 'controller': running time (millis) = 2000 ----------------------------------------- ms % Task name ----------------------------------------- 02000 100% Object com.test.spring.aop.domain.repository.IConnector.getSthFromRemote()================= end IConnector.getSthFromRemote()===================== 2016-07-17 12:26:54.063 INFO 18580 --- [io-8080-exec-10] com.test.spring.aop.monitor.UserMonitor : StopWatch 'controller': running time (millis) = 2000 ----------------------------------------- ms % Task name ----------------------------------------- 02000 100% Object com.test.spring.aop.domain.repository.IConnector.getSthFromRemote()================= end IConnector.getSthFromRemote()===================== 2016-07-17 12:26:54.064 INFO 18580 --- [nio-8080-exec-4] com.test.spring.aop.monitor.UserMonitor : StopWatch 'controller': running time (millis) = 2001 ----------------------------------------- ms % Task name ----------------------------------------- 02001 100% Object com.test.spring.aop.domain.repository.IConnector.getSthFromRemote() View Code

?

項目源碼：https://github.com/chenxing12/spring-aop

總結

以上是生活随笔為你收集整理的Spring-AOP实践 - 统计访问时间的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。