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

末蓝、 2022-02-26 13:35 1206阅读 0赞

### 多线程版本的StopWatch组件 ###

*  1. 背景介绍
 *  2. 为什么线程不安全
 *   *  2.1 线程安全的含义
     *  2.2 多线程环境下使用StopWatch会怎样
     *  2.3 为什么会出现这种结果
 *  3. 原理探索
 *   *  3.1 共享变量为何不安全
     *  3.2 ThreadLocal原理
 *  4. 线程安全的解决方案
 *   *  4.1 线程安全的ConcurrentStopWatch
     *  4.2 多线程环境并发测试
 *  5. 结论

# 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只有重量级锁的实现。

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