AOP实践: Java利用注解和反射实现一个方便的函数运行时间统计工具
BelleEdgar
8年前
<h2><strong>最初目的</strong></h2> <p>在学习Java的集合类时，有时候想要测试代码块的运行时间，以比较不同算法数据结构之间的性能差异。最简单的做法是在代码块的前后记录时间戳，最后相减得到该代码块的运行时间。</p> <p>下面是Java中的示例:</p> <pre> <code class="language-java">public static void main(String[] args){ long start = System.currentTimeMillis(); algo(); // 执行代码块 long end = System.currentTimeMillis(); System.out.println(end - start); }</code></pre> <p>当需要同时打印多个方法的运行时间以进行比较的时候就会变成这样:</p> <pre> <code class="language-java">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 }</code></pre> <h2><strong>初探</strong></h2> <p>显然上面的代码看起来非常冗余，由于Java不支持 func(func) 这样的直接传递函数指针，本人又不想引入JDK以外太重的工具，所以尝试写一个回调来实现代码块的传递:</p> <pre> <code class="language-java">public interface Callback { void execute(); }</code></pre> <pre> <code class="language-java">public class TimerUtil { public void getTime(Callback callback) { long start = System.currentTimeMillis(); callback.execute(); long end = System.currentTimeMillis(); System.out.println(end - start); } }</code></pre> <pre> <code class="language-java">// 测试类 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(); } }); } }</code></pre> <p>发现此时虽然封装了计时、打印等业务无关的代码，然而对使用者来说代码量并没有减少多少。若仔细观察，其实测试类中仍有一堆结构重复的代码，真正的业务藏在一堆匿名类中间，视觉上干扰很大。</p> <p>Java 8为了解决类似的问题，引入了lambda，可以将代码简化为 tu.getTime(() -> new Foo().algo()); 。lambda看起来很美，简化了许多，然而这种写法对于不熟悉的人写起来还是不太顺手，而且Java 8以下的环境无法这样写。</p> <p>更重要的是从代码的形式上看， algo() 还是被包在表达式内，仿佛 getTime() 才是主要逻辑一样。由于之前接触过Python，此时不禁想到，要是能像Python里那样用装饰器来解决就简洁又方便了:</p> <pre> <code class="language-java">@getTime def algo1(): # algo1 @getTime def algo2(): # algo2</code></pre> <p>不过Java中也没有这样的语法糖，只有注解，于是思考是否可以利用反射和注解来“反转”这种喧宾夺主的情况并使代码更具可读性。</p> <h2><strong>实现</strong></h2> <p>先看实现之后的效果:</p> <pre> <code class="language-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(); } }</code></pre> <p>运行输出如下:</p> <p style="text-align:center"><img src="https://simg.open-open.com/show/fa361a2cf6936d2594a803e725313454.png"></p> <p>可以看到此时加了@Timer注解的algo1()和algo2()的运行时间被统计了，而没加@Timer的algo3()未被统计在内。</p> <h3>思路</h3> <p>使用反射获取栈中当前类(测试类)的信息，遍历其中的方法，若方法包含@Timer注解，则执行该方法并进行时间戳相减。</p> <p>实现这样的效果仅需一个自定义注解和一个工具类:</p> <pre> <code class="language-java">@Retention(RetentionPolicy.RUNTIME) public @interface Timer { }</code></pre> <pre> <code class="language-java">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(); } } }</code></pre> <h2><strong>升级</strong></h2> <p>在同时统计多个方法时，要是能可视化的打印出类似Performance Index一样的柱状图，可以更直观的比较他们之间的性能差异，就像这样:</p> <p style="text-align: center;"><img src="https://simg.open-open.com/show/340b3eca58f2295888cb700273a8c5be.png"></p> <p>耗时最久的方法的Index固定为100，剩余的按相对的Index降序排列。</p> <h3><strong>思路</strong></h3> <p>修改 TimerUtil ，在之前的 getTime() 中返回一个HashMap，储存 方法名: 耗时 的键值结构。然后降序排序HashMap返回一个LinkedHashMap。最后遍历LinkedHashMap根据百分比求得各个方法的Index并输出相关信息。</p> <pre> <code class="language-java">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; } }</code></pre> <h2><strong>总结</strong></h2> <p>本文介绍的是一个计时工具比较粗糙的实现，然而这种思路可以同样应用在权限控制、日志、缓存等方面，方便的对代码进行解耦，让通用的功能“切入”原先的代码，使得开发时可以更专注于业务逻辑。</p> <p> </p> <p>来自：https://segmentfault.com/a/1190000007217125</p> <p> </p>