Spring-AOP实践 - 统计访问时间

分手后的思念是犯贱 2022-07-16 07:42 85阅读 0赞

公司的项目有的页面超级慢，20s以上，不知道用户会不会疯掉，于是老大说这个页面要性能优化。于是，首先就要搞清楚究竟是哪一步耗时太多。

我采用spring aop来统计各个阶段的用时，其中计时器工具为StopWatch。

文章结构：

1.  遇到的问题
2.  创建项目
3.  AOP-HelloWorld
4.  时间统计
5.  bug
6.  final
7.  压力测试
8.  源码

# 其中，遇到的问题: #

**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：

![686418-20160716205830217-1223638777.png][]                ![686418-20160716212137404-315235209.png][]

图一                                                                 图二

这样的话，我应该分别获得Tc,Ts,Tr的时间，然后计算百分比或者别的统计工作。也就是说，log仅仅是log，记录而已，想要得到一个统计结果还需要针对数据二次开发，这就需要将时间存储起来或者进行日志挖掘，然而这统计的工作会越来越复杂，最终我都不知会加多少任务进去。

事实上，我们这个页面耗费时间主要是多个webservice调用产生的io耗时，也就是说其实统计一个层面的时间就差不多了。那么，忽略service返回后controller的其他时间，仅仅计算controller开始到调用service的时间为Tc,service开始到调用repository的时间为Ts，如图2，这样利用StopWatch就很容获取时间统计结果。

**4.线程不安全**

我居然使用单例的一个成员变量做状态存储，真是。待改进

# 1.搭建项目 #

采用spring-boot-aop的框架来搭建。最终结构图如下：

![686418-20160716212732467-1264755031.png][]

**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>
                    
                    <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{
    
        @Autowired
        IHelloService 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

![ContractedBlock.gif][] ![ExpandedBlockStart.gif][]

1 name: Ryan

**1.6这时候可以测试一下启动看看了**

直接启动：运行com.test.spring.aop.Application\#main()即可。

命令行启动：[mvn spring-boot:run][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**

![ContractedBlock.gif][] ![ExpandedBlockStart.gif][]

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 {
        @Rule
        public OutputCapture outputCapture = new OutputCapture();
    
        private String profiles;
    
        @Before
        public void init() throws Exception {
            this.profiles = System.getProperty("spring.profiles.active");
        }
    
        @After
        public void tearDown() throws Exception {
            if (this.profiles != null){
                System.setProperty("spring.profiles.active",this.profiles);
            }else{
                System.out.println("spring.profiles.active");
            }
        }
    
        @Test
        public void testDefaultSettings() throws Exception{
            Application.main(new String[0]);
            String s = this.outputCapture.toString();
            assertThat(s).contains("Hi Ryan");
        }
        @Test
        public void testCommandLineOverrides() throws Exception {
            Application.main(new String[] {"--name=Leslie"});
            String s = this.outputCapture.toString();
            assertThat(s).contains("Hi Leslie");
        }
    
    
    }

# 2.AOP - HelloWorld #

**2.1创建com.test.spring.aop.monitor.ServiceMonitor**

![ContractedBlock.gif][] ![ExpandedBlockStart.gif][]

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;
        }
    }

**2.2测试**

测试水平还没开始，所以只能手动测试了，运行**com.test.spring.aop.ApplicationTest**可以看到在HelloService调用前后插入了日志。

# 3.时间统计 #

最终，生成类图如下：

![686418-20160716220034311-2058592042.png][]

最终获得的时间统计如下：

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：

![ContractedBlock.gif][] ![ExpandedBlockStart.gif][]

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 {
    
        @Autowired
        private 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;
        }
    }

**3.2发现需要一个service**

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

![ContractedBlock.gif][] ![ExpandedBlockStart.gif][]

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();
    }

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

![ContractedBlock.gif][] ![ExpandedBlockStart.gif][]

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 {
    
        @Autowired
        private IUserDao userDao;
    
        @Autowired
        private IConnector connector;
    
        public List<User> getAll() {
            try {Thread.sleep(1000);} catch (InterruptedException e) {e.printStackTrace();}
            connector.getSthFromRemote();
            return userDao.getAll();
        }
    }

**3.3发现需要一个repository**

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

![ContractedBlock.gif][] ![ExpandedBlockStart.gif][]

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();
    }

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

![ContractedBlock.gif][] ![ExpandedBlockStart.gif][]

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 data
            List<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();
        }
    
    
    
    }

**3.3.1临时添加一个远程调用**

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

![ContractedBlock.gif][] ![ExpandedBlockStart.gif][]

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

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

![ContractedBlock.gif][] ![ExpandedBlockStart.gif][]

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 time
            try {Thread.sleep(2000);} catch (InterruptedException e) {e.printStackTrace();}
            return null;
        }
    }

**3.4发现需要一个实体类**

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

![ContractedBlock.gif][] ![ExpandedBlockStart.gif][]

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;
        }
    
        @Override
        public String toString() {
            return "User{" +
                    "id=" + id +
                    ", username='" + username + '\'' +
                    ", password='" + password + '\'' +
                    ", age=" + age +
                    ", sex=" + sex +
                    ", info='" + info + '\'' +
                    '}';
        }
    }

**3.5完成**

以上就基本把一个web接口搞定了，可以运行测试一下，使用浏览器或者postman访问localhost:8080/user/all就可以获得user列表了。

**3.6加入user时间统计**

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

![ContractedBlock.gif][] ![ExpandedBlockStart.gif][]

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;
    
        }
    
    }

这里有几点问题：

1.StopWatch不能重复创建，如果想统计每次controller访问时间，必须在访问前初始化，访问后废除。

2.这里的时间统计仅仅针对controller入口的统计，也就是说，如果别的调用了service，这个时间是不统计的，因为StopWatch没有初始化。

3.StopWatch的prettyPrint是一个很好的东东

4.如果想要向开始那样，完全统计每层耗时，这个设计需要重新设计。当前有这样的想法。controller切点初始化三个或者多个StopWatch；service、repository等分别建立切点并计时；controller执行完毕之后的切点汇总统计数据，销毁各个StopWatch。这样就做到了每个层都统计了。然而问题来了，如果一个controller调用了多个service，显然需要统计所有service耗时和单个service耗时。

![686418-20160716223625404-199179455.png][]![686418-20160716223452170-102413566.png][]

# Boo! Big Bug!!! #

今早起来接着看，忽然想起spring bean管理是单例的，而且必须是单例的才可以使用共同的成员变量，但问题来了，spring的controller是多线程的。也就是说，这个切面进入不是排队的，第一个请求过程中第二个请求也是可以进来的。那么，共享成员变量实在是愚蠢的决定。然而选择创建一个类来管理对应一个请求的计时器也不好的，如果并发量超级大岂不是每个人都会产生一个类？

因此，这个计时器必须是一个过程量，可以在指定区间（即controller执行期间）生存，而后销毁。对应的，显然是每个并发请求会至少产生一个类。也就是说，我需要在controller请求的时候new 一个StopWatch的id，然后在接下来的一系列调用中都使用这个id对应的计时器，最后销毁。如果几百万个并发量，那么就会产生几百万个类实例。懵逼。

# 最终选择 #

通过一个实例来保存一次请求状态太消耗性能，而如果不通过一个类实例保存状态就无法汇总所有的时间。所以这个方案不合适。那么，剩下日志和传入数据库。当下就先记录日志好了。记录想要记录的节点的时间：

![ContractedBlock.gif][] ![ExpandedBlockStart.gif][]

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;
        }
    
    }

# 压力测试 #

## 1.建立test case ##

首先，测试controller：创建com.test.spring.aop.web.UserControllerTest

![ContractedBlock.gif][] ![ExpandedBlockStart.gif][]

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 {
        @Autowired
        private WebApplicationContext wac;
        private MockMvc mockMvc;
    
        @Before
        public void setUp() {
            mockMvc = MockMvcBuilders.webAppContextSetup(wac).build();
        }
    
        @Test
        public 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();
        }
    
        @Test
        public 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();
            }
        }
    
    }

不知道为啥，我的new Thread并没有并发执行，而是按顺序执行的。也就是说，虽然我new 10 个Thread，但还是一个接一个的运行。

**改进**  
于是，我想采用线程池：

@Test
        public void testUsersConcurrent() throws  Exception{
    
            ThreadPoolExecutor executor = new ThreadPoolExecutor(5,10,200, TimeUnit.MILLISECONDS,new ArrayBlockingQueue<Runnable>(5));
            //不能超过15
            for (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访问日志，正好是线程池的最大容量：

![ContractedBlock.gif][] ![ExpandedBlockStart.gif][]

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()=====================

## 2.采用Apache 的ab进行并发访问 ##

**2.1下载Apache**

参考：[使用Apache Server 的ab进行web请求压力测试][Apache Server _ab_web]

**2.2测试**

![ContractedBlock.gif][] ![ExpandedBlockStart.gif][]

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).....done
    
    
    Server Software:        Apache-Coyote/1.1
    Server Hostname:        localhost
    Server Port:            8080
    
    Document Path:          /user/all
    Document Length:        1836671 bytes
    
    Concurrency 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] received
    
    Connection 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   16148
    
    Percentage of the requests served within a certain time (ms)
      50%  16085
      66%  16090
      75%  16099
      80%  16114
      90%  16140
      95%  16148
      98%  16148
      99%  16148
     100%  16148 (longest request)

可以看到服务端是多线程的：

![ContractedBlock.gif][] ![ExpandedBlockStart.gif][]

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()

项目源码：https://github.com/chenxing12/spring-aop

[686418-20160716205830217-1223638777.png]: http://images2015.cnblogs.com/blog/686418/201607/686418-20160716205830217-1223638777.png
[686418-20160716212137404-315235209.png]: /images/20220716/a330a825c1ba4de99cc53fcdb6677b2d.png
[686418-20160716212732467-1264755031.png]: /images/20220716/cb434f065ec04ca89e48322256b41f26.png
[ContractedBlock.gif]: http://images.cnblogs.com/OutliningIndicators/ContractedBlock.gif
[ExpandedBlockStart.gif]: /images/20220716/3156914bf3f24be3bc06098fa6f34df2.png
[mvn spring-boot_run]: http://www.cnblogs.com/woshimrf/p/5602051.html
[686418-20160716220034311-2058592042.png]: /images/20220716/93e0295c522f4b2eb8eaf20f9b193ae0.png
[686418-20160716223625404-199179455.png]: http://images2015.cnblogs.com/blog/686418/201607/686418-20160716223625404-199179455.png
[686418-20160716223452170-102413566.png]: /images/20220716/ec1142aa7f424fea805e15fdd035b5ff.png
[Apache Server _ab_web]: http://www.cnblogs.com/woshimrf/p/5678348.html