AOP实践: Java利用注解和反射实现一个方便的函数运行时间统计工具

最初目的

在学习Java的集合类时,有时候想要测试代码块的运行时间,以比较不同算法数据结构之间的性能差异。最简单的做法是在代码块的前后记录时间戳,最后相减得到该代码块的运行时间。

下面是Java中的示例:

public static void main(String[] args){
    long start = System.currentTimeMillis();
    algo(); // 执行代码块
    long end = System.currentTimeMillis();
    System.out.println(end - start);
}

当需要同时打印多个方法的运行时间以进行比较的时候就会变成这样:

public static void main(String[] args){
    long start = System.currentTimeMillis();
    algo1(); // 算法1
    long end = System.currentTimeMillis();
    System.out.println(end - start);
    
    long start = System.currentTimeMillis();
    algo2(); // 算法2
    long end = System.currentTimeMillis();
    System.out.println(end - start);
  
    long start = System.currentTimeMillis();
    algo3(); // 算法3
    long end = System.currentTimeMillis();
    System.out.println(end - start);
  
    // more
}

初探

显然上面的代码看起来非常冗余,由于Java不支持func(func)这样的直接传递函数指针,本人又不想引入JDK以外太重的工具,所以尝试写一个回调来实现代码块的传递:

public interface Callback {
    void execute();
}
public class TimerUtil {
    public void getTime(Callback callback) {
        long start = System.currentTimeMillis();
        callback.execute();
        long end = System.currentTimeMillis();
        System.out.println(end - start);
    }
}
// 测试类
public class Foo {
    
    void algo1() {
        // algo1
    }
    
    void algo2() {
        // algo2
    }
    
    void algo3() {
        // algo3
    }
    
    public static void main(String[] foo){
        TimerUtil tu = new TimerUtil();
        tu.getTime(new Callback() {
            @Override
            public void execute() {
                new Foo().algo1();
            }
        });
        tu.getTime(new Callback() {
            @Override
            public void execute() {
                new Foo().algo2();
            }
        });
        tu.getTime(new Callback() {
            @Override
            public void execute() {
                new Foo().algo3();
            }
        });
    }
}

发现此时虽然封装了计时、打印等业务无关的代码,然而对使用者来说代码量并没有减少多少。若仔细观察,其实测试类中仍有一堆结构重复的代码,真正的业务藏在一堆匿名类中间,视觉上干扰很大。

Java 8为了解决类似的问题,引入了lambda,可以将代码简化为tu.getTime(() -> new Foo().algo());。lambda看起来很美,简化了许多,然而这种写法对于不熟悉的人写起来还是�不太顺手,而且Java 8以下的环境无法这样写。

更重要的是从代码的形式上看,algo() 还是被包在表达式内,仿佛getTime()才是主要逻辑一样。由于之前接触过Python,此时不禁想到,要是能像Python里那样用装饰器来解决就简洁�又方便了:

@getTime
def algo1():
    # algo1

@getTime
def algo2():
    # algo2

不过Java中也没有这样的语法糖,只有注解,于是思考是否可以利用反射和注解来“反转”这种喧宾夺主的情况并使代码更具可读性。

实现

先看实现之后的效果:

// 测试类Foo
public class Foo {

    @Timer
    public void algo1() {
        ArrayList<Integer> l = new ArrayList<>();
        for (int i = 0; i < 10000000; i++) {
            l.add(1);
        }
    }

    @Timer
    public void algo2() {
        LinkedList<Integer> l = new LinkedList<>();
        for (int i = 0; i < 10000000; i++) {
            l.add(1);
        }
    }

    public void algo3() {
        Vector<Integer> v = new Vector<>();
        for (int i = 0; i < 10000000; i++) {
            v.add(1);
        }
    }

    public static void main(String[] foo){
        TimerUtil tu = new TimerUtil();
        tu.getTime();
    }
}

运行输出如下:

可以看到此时加了@Timer注解的algo1()和algo2()的运行时间被统计了,而没加@Timer的algo3()未被统计在内。

思路

使用反射获取栈中当前类(测试类)的信息,遍历�其中的方法,若方法包含@Timer注解,则执行该方法并进行时间戳相减。

实现这样的效果仅需一个自定义注解和一个工具类:

@Retention(RetentionPolicy.RUNTIME)
public @interface Timer {
}
public class TimerUtil {

    public void getTime() {
        // 获取当前类型名字
        String className = Thread.currentThread().getStackTrace()[2].getClassName();
        System.out.println("current className(expected): " + className);
        try {
            Class c = Class.forName(className);
            Object obj = c.newInstance();
            Method[] methods = c.getDeclaredMethods();
            for (Method m : methods) {
                // 判断该方法是否包含Timer注解
                if (m.isAnnotationPresent(Timer.class)) {
                    m.setAccessible(true);
                    long start = System.currentTimeMillis();
                    // 执行该方法
                    m.invoke(obj);
                    long end = System.currentTimeMillis();
                    System.out.println(m.getName() + "() time consumed: " + String.valueOf(end - start) + "\\\\n");
                }
            }
        } catch (IllegalAccessException e) {
            e.printStackTrace();
        } catch (InstantiationException e) {
            e.printStackTrace();
        } catch (InvocationTargetException e) {
            e.printStackTrace();
        } catch (ClassNotFoundException e) {
            e.printStackTrace();
        }
    }
}

升级

在同时统计多个方法时,要是能可视化的打印出类似Performance Index一样的柱状图,可以更直观的比较他们之间的性能差异,就像这样:

耗时最久的方法的Index固定为100,剩余的按相对�的Index降序排列。

思路

修改TimerUtil,在之前的getTime()中返回一个HashMap,储存方法名: 耗时的键值结构。然后降序排序HashMap返回一个LinkedHashMap。最后遍历LinkedHashMap根据百分比求得各个方法的Index并输出相关信息。

public class TimerUtil {

    // 修改getTime()
    public HashMap<String, Long> getMethodsTable() {
        HashMap<String, Long> methodsTable = new HashMap<>();
        String className = Thread.currentThread().getStackTrace()[3].getClassName();
        // ...
        return methodsTable;
    }

    public void printChart() {
        Map<String, Long> result = sortByValue(getMethodsTable());
        double max = result.values().iterator().next();
        for (Map.Entry<String, Long> e : result.entrySet()) {
            double index = e.getValue() / max * 100;
            for (int i = 0; i < index; i++) {
                System.out.print("=");
            }
            System.out.println(e.getKey() + "()" + " Index:" + (long) index + " Time:" + e.getValue());
        }
    }

    <K, V extends Comparable<? super V>> Map<K, V> sortByValue(Map<K, V> map) {
        List<Map.Entry<K, V>> list = new LinkedList<>(map.entrySet());
        // desc order
        Collections.sort(list, new Comparator<Map.Entry<K, V>>() {
            public int compare(Map.Entry<K, V> o1, Map.Entry<K, V> o2) {
                return (o2.getValue()).compareTo(o1.getValue());
            }
        });
        Map<K, V> result = new LinkedHashMap<>();
        for (Map.Entry<K, V> entry : list) {
            result.put(entry.getKey(), entry.getValue());
        }
        return result;
    }
}

总结

本文介绍的是一个计时工具比较粗糙的实现,然而这种思路可以同样应用在权限控制、日志、缓存等方面,方便的对代码进行解耦,让通用的功能“切入”原先的代码,使得开发时可以更专注于业务逻辑。

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 203,324评论 5 476
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 85,303评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 150,192评论 0 337
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,555评论 1 273
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,569评论 5 365
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,566评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 37,927评论 3 395
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,583评论 0 257
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 40,827评论 1 297
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,590评论 2 320
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,669评论 1 329
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,365评论 4 318
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 38,941评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,928评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,159评论 1 259
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 42,880评论 2 349
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,399评论 2 342

推荐阅读更多精彩内容

  • 一、基本数据类型 注释 单行注释:// 区域注释:/* */ 文档注释:/** */ 数值 对于byte类型而言...
    龙猫小爷阅读 4,253评论 0 16
  • Android 自定义View的各种姿势1 Activity的显示之ViewRootImpl详解 Activity...
    passiontim阅读 171,392评论 25 707
  • 桃花渐落叶渐成 荏苒又 再老了春风 拈笔写景 无非是 一地飞红 两三座楼亭 四五只燕子悄呢哝 往事闲情 笺里幽明 ...
    黛眉居阅读 236评论 14 17
  • 我记得以前看到池莉写的一篇文章。 她在家里写作的时候忘记吃饭,等肚子饿的时候,看到有一些剩饭,就把这些剩饭按照想象...
    沙棘花儿阅读 478评论 1 10
  • "任时光匆匆流去,我只在乎你…",曾记否,多年前听到的这首歌?那时讨厌音乐,却能记住这首歌,或许是能感同身受...
    i丶看4阅读 255评论 0 0