记录代码块耗时小工具

背景

最近在做一些性能优化的时候，经常遇到一个问题就是如何记录耗时，当然解决方案非常多，但是貌似每一种用起来又不是很顺手。
系统层面的耗时可以用AOP去实现，这种无侵入，高内聚的方式非常适合做这种事。但是AOP的支持更多是方法级的切面，对于代码块的监控并不是特别友好。本次想解决的问题就是如何让代码块级的耗时监控变得更简单。

---

• 第一个方案：最土的办法，就是在代码块执行之前去得到一个系统时间，在结束去得到一个时间，然后再去减得到差值。这个方法能达到想要的结果，但是缺点是比较难重用，代码比较冗余，对业务不友好。

        long time1 = System.currentTimeMillis();

        try {
            // 模拟业务逻辑
            Thread.sleep(1000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

        long time2 = System.currentTimeMillis();

        try {
            // 模拟业务逻辑
            Thread.sleep(2000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

        long time3 = System.currentTimeMillis();

        try {
            // 模拟业务逻辑
            Thread.sleep(5000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

        long time4 = System.currentTimeMillis();

        // 开始记录耗时
        System.out.println("record index : 1-->2, costs : " + (time2 - time1));
        System.out.println("record index : 2-->3, costs : " + (time3 - time2));
        System.out.println("record index : 3-->4, costs : " + (time4 - time3));

• 第二个方案：AOP，这种方式很好，缺点是只能支持方法级的耗时。
• 第三个方案：StopWatch.这是apache和spring都有在用的一个时间监控工具。例如典型的Spring boot启动里，记录耗时就是用这个工具。

public ConfigurableApplicationContext run(String... args) {
		StopWatch stopWatch = new StopWatch();
		stopWatch.start();
		// 省略部分代码
			stopWatch.stop();
			if (this.logStartupInfo) {
				new StartupInfoLogger(this.mainApplicationClass)
						.logStarted(getApplicationLog(), stopWatch);
			}
			listeners.started(context);
		}
		// ..
	}

它用起来简单，不过只是针对它的场景，我的场景有点不一样，我是一个代码块可能需要多个点之间的耗时希望一并输出.

而StopWatch很难直观的封装各个点之间的耗时，因此我开始思考我需要的一个时间耗时监控的需求是怎样的：
侵入小，这样避免业务过度耦合导致后面维护困难。
可扩展，有一些逻辑是不稳定的，可能随着环境的改变需要移植，或则说需要去填充新的逻辑，需要考虑到这样的扩展需求。
使用简单，这本身就是一个技术需求点，没必要太重，使用方便很重要。
无关业务，这个功能应该脱离于业务场景的，这样才能做到复用方便。

于是开始着手设计这样一个“小玩具”.

public class TimeProfiler {

    /**
     * 全局开关
     */
    private static boolean open = false;

    /**
     * 记录时间点的方式
     */
    private static Map<Integer, Long> recordMap = getCacheMap();

    /**
     * 这里使用的各个节点的时间记录方式可能不一样。我这里默认用的treeMap。
     * 不排出在其他情况下使用其他的载体。
     */
    protected static Map<Integer, Long> getCacheMap() {
        return new TreeMap<>((o1, o2) -> {
            if (o1 > o2) {
                return 1;
            } else if (o1 < o2) {
                return -1;
            }
            return 0;
        });
    }

    public static void record(int i) {
        if (recordMap.keySet().contains(i)) {
            throw new RuntimeException("duplicate record : " + i);
        }
        recordMap.put(i, System.currentTimeMillis());
    }

    /**
     * 这里描述了核心的
     * @param isOpen
     */
    public static void start(boolean isOpen) {
        open = isOpen;
        if (!open) {
            return ;
        }

        long last = 0;
        // print
        for (Map.Entry<Integer, Long> entry : recordMap.entrySet()) {
            if (last == 0) {
                last = entry.getValue();
            } else {
                printRecord(entry.getKey(), entry.getValue() - last);
                last = entry.getValue();
            }
        }
    }

    public static void start() {
        start(true);
    }

    /**
     * 此处独立出来一个方法，因为输出的形式，可能是不同的，如果在生产环境，可能是日志输出，可能格式也会根据需求不同需要改变，本地用就直接print
     * @param key
     * @param value
     */
    protected static void printRecord(Integer key, Long value) {
        System.out.println("record index : " + (key - 1) + "-->" + key + ", costs : " + value);
    }
}

主要的思考，都写在注释上了，protected的方法都是可以去扩展的，可以简单理解成我这里写了一些模板方法里钩子的默认实现，也可以使用接口去隔离解耦，但是那样会增加类的数量，优点是职责更加清晰，对于我当前的场景，简洁就好了。

使用方式

        TimeProfiler.record(1);

        try {
            // 模拟业务逻辑
            Thread.sleep(1000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

        TimeProfiler.record(2);

        try {
            // 模拟业务逻辑
            Thread.sleep(2000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

        TimeProfiler.record(3);

        try {
            // 模拟业务逻辑
            Thread.sleep(5000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

        TimeProfiler.record(4);

        // 开始记录耗时
        TimeProfiler.start();

输出如下：
record index : 1–>2, costs : 1005
record index : 2–>3, costs : 2004
record index : 3–>4, costs : 5005
这样就能非常清晰的看到每个节点之间的耗时了，使用方式比之前的版本，更加简洁，也更加容易复用，也易于扩展。