StopWatch单线程问题及多线程ConcurrentStopWatch解决方案

1. 背景介绍

相信很多人都知道，spring-core中有个非常实用的监控类StopWatch，在Spring Boot应用启动过程中也有使用，可以监控代码段执行耗时以及占整个监控过程耗时百分比，这样很容易监控出比较耗时的代码，及时发现问题，优化性能。但不足的是，StopWatch是个线程不安全的工具类，不能用于多线程环境，因此基于StopWatch的不足，自定义组件mbyx-component-concurrent-stopwatch提供一个多线程版本的ConcurrentStopWatch便于在多线程环境监控代码执行耗时。

2. 为什么线程不安全

2.1 线程安全的含义

线程安全问题发生在共享变量或静态变量的情况，多个线程想要同时对共享变量或静态变量进行修改操作，就形成线程竞争，存在竞争即线程不安全，反之，如果对共享变量或静态变量修改时，一次只允许有一个线程执行，不存在竞争，这种情况是线程安全的。

2.2 多线程环境下使用StopWatch会怎样

先多线程环境下测试一下StopWatch监控结果

package com.mbyx.component.concurrent.stopwatch;
import org.springframework.util.StopWatch;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.TimeUnit;

/**
 * @author zhuxiaolong
 * @package PACKAGE_NAME
 * @description
 * @date 2019/3/27 15:35
 */
public class Main {
    public static void main(String[] args) {
        ExecutorService service = Executors.newFixedThreadPool(10);
        for (int i = 0; i < 10000; i++) {
            service.execute(Test.getInstance());
        }

    }
}

class Test implements Runnable {
    StopWatch watch = new StopWatch();

    @Override
    public void run() {
        try {
            watch.start("111111111111");
            TimeUnit.SECONDS.sleep(1);

            watch.stop();
            watch.start("222222222222");
            TimeUnit.SECONDS.sleep(1);

            watch.stop();
            watch.start("333333333333");
            TimeUnit.SECONDS.sleep(1);

            watch.stop();
            watch.start("444444444444");
            TimeUnit.SECONDS.sleep(1);

            watch.stop();
            String out = watch.prettyPrint();
            System.out.println(out);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }

    private static class SingleHolder {
        private static Test test = new Test();
    }
    public static Test getInstance() {
        return SingleHolder.test;
    }
}

• 想要的结果：

StopWatch '': running time (millis) = 4002
-----------------------------------------
ms     %     Task name
-----------------------------------------
01000  025%  111111111111
01001  025%  222222222222
01000  025%  333333333333
01001  025%  444444444444

StopWatch '': running time (millis) = 4018
-----------------------------------------
ms     %     Task name
-----------------------------------------
01000  025%  111111111111
01001  025%  222222222222
01000  025%  333333333333
01017  025%  444444444444

StopWatch '': running time (millis) = 4002
-----------------------------------------
ms     %     Task name
-----------------------------------------
01000  025%  111111111111
01001  025%  222222222222
01000  025%  333333333333
01001  025%  444444444444
.........

• 实际的结果：

Connected to the target VM, address: '127.0.0.1:58560', transport: 'socket'
Exception in thread "pool-1-thread-2" java.lang.IllegalStateException: Can't start StopWatch: it's already running
	at org.springframework.util.StopWatch.start(StopWatch.java:128)
	at com.mbyx.component.concurrent.stopwatch.Test.run(Main.java:32)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Exception in thread "pool-1-thread-3" java.lang.IllegalStateException: Can't start StopWatch: it's already running
	at org.springframework.util.StopWatch.start(StopWatch.java:128)
	at com.mbyx.component.concurrent.stopwatch.Test.run(Main.java:32)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Exception in thread "pool-1-thread-4" java.lang.IllegalStateException: Can't start StopWatch: it's already running
	at org.springframework.util.StopWatch.start(StopWatch.java:128)
	at com.mbyx.component.concurrent.stopwatch.Test.run(Main.java:32)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Exception in thread "pool-1-thread-5" java.lang.IllegalStateException: Can't start StopWatch: it's already running
	at org.springframework.util.StopWatch.start(StopWatch.java:128)
	at com.mbyx.component.concurrent.stopwatch.Test.run(Main.java:32)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Exception in thread "pool-1-thread-6" java.lang.IllegalStateException: Can't start StopWatch: it's already running
	at org.springframework.util.StopWatch.start(StopWatch.java:128)
	at com.mbyx.component.concurrent.stopwatch.Test.run(Main.java:32)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
	......

2.3 为什么会出现这种结果

• 线程不安全原因：
  watch对象是个线程共享变量，假如线程A执行了watch.start()，watch对象内部的属性被改变，线程A还未来得及执行watch.stop()，线程B就执行watch.start()。根据下面StopWatch源码可以看出，watch.start()和watch.stop()是一组操作，如果顺序被打乱，那么就会抛出异常。

    public void start(String taskName) throws IllegalStateException {
        if (this.currentTaskName != null) {
            throw new IllegalStateException("Can't start StopWatch: it's already running");
        } else {
            this.currentTaskName = taskName;
            this.startTimeMillis = System.currentTimeMillis();
        }
    }

    public void stop() throws IllegalStateException {
        if (this.currentTaskName == null) {
            throw new IllegalStateException("Can't stop StopWatch: it's not running");
        } else {
            long lastTime = System.currentTimeMillis() - this.startTimeMillis;
            this.totalTimeMillis += lastTime;
            this.lastTaskInfo = new StopWatch.TaskInfo(this.currentTaskName, lastTime);
            if (this.keepTaskList) {
                this.taskList.add(this.lastTaskInfo);
            }

            ++this.taskCount;
            this.currentTaskName = null;
        }
    }

3. 原理探索

3.1 共享变量为何不安全

假设主存中有共享变量a（初始值1），现在线程A和线程B要执行a++

• 线程不安全的做法：

线程A和线程B同时从主存读取a到本地线程工作内存，并执行a++，然后线程A和线程B分别将结果写回主存，无论线程A和线程B谁先写回主存，执行最终结果a的值为2（与预期值3不符合），这就是线程不安全导致的错误数据

• 线程安全的做法：

线程A从主存读取a到本地线程工作内存（线程B正在等待），并执行a++，然后线程A将结果写回主存，此时a的值为2。接着线程B从主存读取a到本地线程工作内存，并执行a++，然后线程B将结果写回主存，此时a的值为3（与预期值3符合），不存在竞争的情况即为线程安全

3.2 ThreadLocal原理

结合源码分析，ThreadLocal核心为get()和set()方法

/**
     * Returns the value in the current thread's copy of this
     * thread-local variable.  If the variable has no value for the
     * current thread, it is first initialized to the value returned
     * by an invocation of the {@link #initialValue} method.
     *
     * @return the current thread's value of this thread-local
     */
    public T get() {
        Thread t = Thread.currentThread();
        // 获取当前线程的threadLocals属性
        ThreadLocalMap map = getMap(t);
        if (map != null) {
        	// threadLocals不为空，通过当前的ThreadLocal对象（this）获取存入ThreadLocal中的对象e.value
            ThreadLocalMap.Entry e = map.getEntry(this);
            if (e != null) {
                @SuppressWarnings("unchecked")
                T result = (T)e.value;
                return result;
            }
        }
        // 如果threadLocals 为null，执行初始化设置初始值
        return setInitialValue();
    }

    /**
     * Variant of set() to establish initialValue. Used instead
     * of set() in case user has overridden the set() method.
     *
     * @return the initial value
     */
    private T setInitialValue() {
        T value = initialValue();
        Thread t = Thread.currentThread();
        ThreadLocalMap map = getMap(t);
        if (map != null)
            map.set(this, value);
        else
            createMap(t, value);
        return value;
    }

    /**
     * Sets the current thread's copy of this thread-local variable
     * to the specified value.  Most subclasses will have no need to
     * override this method, relying solely on the {@link #initialValue}
     * method to set the values of thread-locals.
     *
     * @param value the value to be stored in the current thread's copy of
     *        this thread-local.
     */
    public void set(T value) {
        Thread t = Thread.currentThread();
        ThreadLocalMap map = getMap(t);
        if (map != null)
            map.set(this, value);
        else
            createMap(t, value);
    }

    /**
     * Removes the current thread's value for this thread-local
     * variable.  If this thread-local variable is subsequently
     * {@linkplain #get read} by the current thread, its value will be
     * reinitialized by invoking its {@link #initialValue} method,
     * unless its value is {@linkplain #set set} by the current thread
     * in the interim.  This may result in multiple invocations of the
     * {@code initialValue} method in the current thread.
     *
     * @since 1.5
     */
     public void remove() {
         ThreadLocalMap m = getMap(Thread.currentThread());
         if (m != null)
             m.remove(this);
     }

    /**
     * Get the map associated with a ThreadLocal. Overridden in
     * InheritableThreadLocal.
     *
     * @param  t the current thread
     * @return the map
     */
    ThreadLocalMap getMap(Thread t) {
        return t.threadLocals;
    }

    /**
     * Create the map associated with a ThreadLocal. Overridden in
     * InheritableThreadLocal.
     *
     * @param t the current thread
     * @param firstValue value for the initial entry of the map
     */
    void createMap(Thread t, T firstValue) {
        t.threadLocals = new ThreadLocalMap(this, firstValue);
    }

Thread类有个属性ThreadLocal.ThreadLocalMap threadLocals = null;,这个map键为ThreadLocal共享变量，value是ThreadLocal.ThreadLocalMap.Entry静态类对象，Entry的键为ThreadLocal共享变量，value为存入ThreadLocal中的对象。因此ThreadLocal最终是每个线程有个ThreadLocal.ThreadLocalMap对象，多线程拥有各自的ThreadLocal.ThreadLocalMap副本，不存在竞争，所以是线程安全的。

和Synchronized相比：

• Synchronized以时间换空间，不需要额外的空间，但较耗时，性能没有ThreadLocal好
• ThreadLocal以空间换时间，增加了额外的存储空间，但带来的是性能的提升

备注：网上有不少博文说ThreadLocal有内存泄露的可能，看过相关的文章及ThreadLocal的源码，发现ThreadLocal.ThreadLocalMap.Entry是继承自WeakReference类的，即弱引用。根据JVM垃圾收集器原理，如果是弱引用类型的，当虚拟机执行垃圾回收时，会将其列入回收集，因此笔者认为是不存在内存泄露的问题（JDK1.6+）

4. 线程安全的解决方案

4.1 线程安全的ConcurrentStopWatch

基于ThreadLocal，提供一个线程安全的ConcurrentStopWatch类

• ConcurrentStopWatch.java

package com.mbyx.component.concurrent.stopwatch;

import org.springframework.util.StopWatch;


/**
 * @author zhuxiaolong
 * @package com.mbyx.component.stopwatch
 * @description 支持多线程的代码执行耗时监控类，以空间换时间，多线程情况下，为每个线程提供一个StopWatch对象，支持更高的并发，相比synchronized的以时间换空间方式，不需要加锁，性能更好
 * @date 2019/3/27 16:51
 */
public class ConcurrentStopWatch {

    private ThreadLocal<StopWatch> stopWatch;

    public ConcurrentStopWatch() {
        this.stopWatch = new ThreadLocal<StopWatch>() {
            @Override
            protected StopWatch initialValue() {
                return new StopWatch();
            }
        };
    }


    public ConcurrentStopWatch(final String name) {
        this.stopWatch = new ThreadLocal<StopWatch>() {
            @Override
            protected StopWatch initialValue() {
                return new StopWatch(name);
            }
        };
    }

    public void start(String taskName) {
        try {
            if (!this.stopWatch.get().isRunning()) {
                this.stopWatch.get().start(taskName);
            } else {
                this.stopWatch.get().stop();
            }
        } catch (Exception e) {
            System.err.println(String.format("开始监控任务%s失败,原因:%s", taskName, e.getCause()));
        }
    }

    public void stop() {
        try {
            if (this.stopWatch.get().isRunning()) {
                this.stopWatch.get().stop();
            }
        } catch (Exception e) {
            System.err.println(String.format("停止监控任务失败,原因:%s", e.getCause()));
        }
    }

    public String prettyPrint() {
        try {
            return this.stopWatch.get().prettyPrint();
        } catch (Exception e) {
            System.err.println(String.format("打印监控日志失败,原因:%s", e.getCause()));
        }
        return "";
    }
}

4.2 多线程环境并发测试

• Main.java测试类

package com.mbyx.component.concurrent.stopwatch;

import org.springframework.util.StopWatch;

import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.TimeUnit;

/**
 * @author zhuxiaolong
 * @package PACKAGE_NAME
 * @description
 * @date 2019/3/27 15:35
 */
public class Main {
    public static void main(String[] args) {
        ExecutorService service = Executors.newFixedThreadPool(100);
        for (int i = 0; i < 1000; i++) {
            service.execute(Test.getInstance());
        }

    }
}


class Test implements Runnable {
    ConcurrentStopWatch watch = new ConcurrentStopWatch();

    @Override
    public void run() {
        try {
            watch.start("111111111111");
            TimeUnit.SECONDS.sleep(1);

            watch.stop();
            watch.start("222222222222");
            TimeUnit.SECONDS.sleep(1);

            watch.stop();
            watch.start("333333333333");
            TimeUnit.SECONDS.sleep(1);

            watch.stop();
            watch.start("444444444444");
            TimeUnit.SECONDS.sleep(1);

            watch.stop();
            String out = watch.prettyPrint();
            System.out.println(out);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }

    private static class SingleHolder {
        private static Test test = new Test();
    }

    public static Test getInstance() {
        return SingleHolder.test;
    }
}

• 测试结果

Connected to the target VM, address: '127.0.0.1:60728', transport: 'socket'
StopWatch '': running time (millis) = 4056
-----------------------------------------
ms     %     Task name
-----------------------------------------
01054  026%  111111111111
01001  025%  222222222222
01000  025%  333333333333
01001  025%  444444444444

StopWatch '': running time (millis) = 4057
-----------------------------------------
ms     %     Task name
-----------------------------------------
01055  026%  111111111111
01001  025%  222222222222
01000  025%  333333333333
01001  025%  444444444444

StopWatch '': running time (millis) = 4057
-----------------------------------------
ms     %     Task name
-----------------------------------------
01055  026%  111111111111
01001  025%  222222222222
01000  025%  333333333333
01001  025%  444444444444

StopWatch '': running time (millis) = 4057
-----------------------------------------
ms     %     Task name
-----------------------------------------
01055  026%  111111111111
01001  025%  222222222222
01000  025%  333333333333
01001  025%  444444444444
......

5. 结论

在多线程环境需要访问共享变量时，可以用ThreadLocal让每个线程保持一份副本，代价是增加了存储空间，优点是性能好。
如果不追求性能，也可以使用synchronized进行多线程同步访问，代价是多线程不能并发，需要排队执行，另外synchronized在jdk1.6之后做了很大的优化，从偏向锁、自旋锁、自适应自旋锁、轻量级锁、重量级锁有个锁升级的过程，只要不膨胀成重量级锁，synchronized也不是很差。在jdk1.6之前，synchronized只有重量级锁的实现。

上述文章中如有技术性错误，请指正