引语
作为工程师，不能仅仅满足于实现了现有的功能逻辑，还必须深入认识系统。一次请求，流经了哪些方法，执行了多少次DB操作，访问了多少次文件操作，调用多少次API操作，总共有多少次IO操作，多少CPU操作，各耗时多少 ？ 开发者应当知道这些运行时数据，才能对系统的运行有更深入的理解，更好滴提升系统的性能和稳定性。
完成一次订单导出任务，实际上是一个比较复杂的过程：需要访问ES 来查询订单，调用批量API接口 及访问 Hbase 获取订单详情数据，格式化报表字段数据，写入和上传报表文件，更新数据库，上报日志数据等；在大流量导出的情形下，采用批量并发策略，多线程来获取订单详情数据，整个请求的执行流程会更加复杂。
本文主要介绍使用AOP拦截器来获取一次请求流经方法的调用次数和调用耗时。
总体思路
使用AOP思想来解决。增加一个注解，然后增加一个AOP methodAspect ，记录方法的调用次数及耗时。
methodAspect 内部含有两个变量 methodCount, methodCost ，都采用了 ConcurrentHashMap 。这是因为方法执行时，可能是多线程写入这两个变量。
使用：
(1) 将需要记录次数和耗时的方法加上 MethodMeasureAnnotation 即可；
(2) 将 MethodMeasureAspect 作为组件注入到 ServiceAspect 中，并在 ServiceAspect 中打印 MethodMeasureAspect 的内容。
关注哪些方法
通常重点关注一个任务流程中的如下方法：
- IO阻塞操作：文件操作， DB操作，API操作， ES访问，Hbase访问；
- 同步操作：lock, synchronized, 同步工具所施加的代码块等；
- CPU耗时：大数据量的format, sort 等。
一般集中在如下包：
- service, core , report, sort 等。根据具体项目而定。
源代码
MethodMeasureAnnotation.java
MapUtil.java
AOP基本概念
理解概念至关重要。优雅设计的框架，通常包含一组相互紧密关联的概念。这些概念经过精心抽象和提炼而成。 AOP的基本概念主要有：
- Aspect：应用程序的某个模块化的关注点；通常是日志、权限、事务、打点、监控等。
- JointPoint：连接点，程序执行过程中明确的点，一般是方法的调用。
- Pointcut: 切点。指定施加于满足指定表达式的方法集合。Spring 默认使用 AspectJ pointcut 表达式。
- Advance: 通知。指定在方法执行的什么时机，不同的Advance对应不同的切面方法；有before,after,afterReturning,afterThrowing,around。
- TargetObject: 目标对象。通过Pointcut表达式指定的将被通知执行切面逻辑的实际对象。
- AOP proxy: 代理对象。由AOP框架创建的代理，用于回调实际对象的方法，并执行切面逻辑。Spring实现中，若目标对象实现了至少一个接口，则使用JDK动态代理，否则使用 CGLIB 代理。优先使用JDK动态代理。
- Weaving：织入。将切面类与应用对象关联起来。Spring使用运行时织入。通常 Pointcut 和 Advance 联合使用。即在方法上加上 @Advance(@Pointcut)
采用多种策略
@Around(“@annotation(zzz.study.aop.MethodMeasureAnnotation)”) 仅仅指定了在携带指定注解的方法上执行。实际上，可以指定多种策略，比如指定类，指定包下。可以使用逻辑运算符 || , && , ! 来指明这些策略的组合。 例如：
指明了五种策略的组合： 带有 MethodMeasureAnnotation 注解的方法； BizOrderDataService 类的所有方法； zzz.study.core.service 下的所有类的方法； zzz.study.core.strategy 包及其子包下的所有类的方法；zzz.study.core.report 包下所有类的以 generate 开头的方法。
execution表达式
@Pointcut 中， execution 使用最多。 其格式如下：
括号中各个pattern分别表示：
- 修饰符匹配（modifier-pattern?）
- 返回值匹配（ret-type-pattern）可以为*表示任何返回值,全路径的类名等
- 类路径匹配（declaring-type-pattern?）
- 方法名匹配（name-pattern）可以指定方法名 或者 代表所有, set 代表以set开头的所有方法
- 参数匹配（(param-pattern)）可以指定具体的参数类型，多个参数间用“,”隔开，各个参数也可以用“”来表示匹配任意类型的参数，如(String)表示匹配一个String参数的方法；(,String) 表示匹配有两个参数的方法，第一个参数可以是任意类型，而第二个参数是String类型；可以用(..)表示零个或多个任意参数
- 异常类型匹配（throws-pattern?）其中后面跟着“?”的是可选项。
何时不会被通知
并不是满足 pointcut 指定条件的所有方法都会执行切面逻辑。 如果类 C 有三个公共方法，a,b,c ; a 调用 b ，b 调用 c 。会发现 b,c 是不会执行切面逻辑的。这是因为Spring的AOP主要基于动态代理机制。当调用 a 时，会调用代理的 a 方法，也就进入到切面逻辑，但是当 a 调用 b 时， b 是直接在目标对象上执行，而不是在代理对象上执行，因此，b 是不会进入到切面逻辑的。总结下，如下情形是不会执行切面逻辑的：
- 被切面方法调用的内部方法；
- final 方法；
- private 方法；
- 静态方法。
可参阅参考文献的 “8.6.1 Understanding AOP proxies”
其含义是说，a, b 都是类 C 的方法，a 调用了 b ；如果需要对 b 方法进行切面，那么最好能将 b 抽离出来放在类D的公共方法中，因为 b 是一个需要切面关注点的重要方法。
再比如，排序方法实现为静态方法 DefaultReportItemSorter.sort ，这样是不能被通知到切面的。需要将 DefaultReportItemSorter 改为组件 @Component 注入到依赖的类里， 然后将 sort 改为实例方法。
运行数据分析
运行结果
导出订单数处于[11500,12000]区间的一次运行结果截取如下：
耗时占比
- 总耗时 52638 ms ， 报表生成部分 46962 ms (89.2%)，ES 查询订单部分 4470 ms (8.5%) , 其他 1206 ms (2.3%) 。
- 报表生成部分：每批次的“报表数据生成+格式化报表行数据+写入文件” appendItemsReportCommon 耗时 46818 ms ；批次切分及进度打印耗时 53ms；报表报表头写入文件 60 ms；appendItemsReportCommon ≈ generateFinalReportItemList + generateReportDatas + output ；
- 报表生成部分(★)：批量详情API接口 getAllOrderDetails 耗时 12684 ms (24%), 除详情API之外的其他详情数据拉取耗时37498-12684=24814 ms (47%) ，获取所有订单的详情数据 generateFinalReportItemList 总占比 71%。
- 报表生成部分(2) : 生成报表行数据 generateReportDatas 耗时 6764 ms (12.9%)， 写入文件 output 耗时 2442 ms (4.6%)。
耗时细分
这里部分方法的调用次数取决于获取订单详情时对keyList的切分策略。方法调用耗时是值得关注的点。重点关注耗时区间。
- 访问ES的耗时平均 4062 ~ 4798ms。随着要查询的订单数线性增长。
- 批量调用详情API 的平均 532 ~ 570 ms (5个并发)。
- Hbase 访问的 getRowsWithColumnPrefixFilter 平均 40 ~ 45 ms , scanByPrefixFilterList 平均 10 ~ 15 ms 。注意，这并不代表 batchGet 的性能比 scanByPrefixFilterList 差。 因为 batchGet 一次取 500 个 rowkey 的数据，而 scanByPrefixFilterList 为了避免超时一次才取 200 个 rowkey 数据。
- appendItemsReportCommon： 平均 1996 ~ 2304 ms 。这个方法是生成报表加格式化报表字段数据加写文件。可见，格式化报表字段数据的耗时还是比较多的。
- generateReportDatas： 报表字段格式化耗时，平均 294 ms。
- output：向报表追加数据耗时，平均 104 ms。
- 更新数据库操作平均 40 ~ 88ms。
- 创建和写文件的操作平均 6~15 ms 。 append 内容在 100KB ~ 200KB 之间。
- 上传文件的操作平均 151~279 ms 。整个文件的上传时间，取决于文件的大小。
注意到，以上是串行策略下运行的结果。也就是所有过程都是顺序执行的。顺序执行策略的优点是排除并发干扰，便于分析基本耗时。
在多线程情形下，单个IO操作会增大，有时会达到 1s ~ 3s 左右。此时，很容易造成线程阻塞，进而影响系统稳定性。
小结
通过方法调用的次数统计及耗时分析，更清晰地理解了一个导出请求的总执行流程及执行耗时占比，为性能和稳定性优化提供了有力的数据依据。
欢迎工作一到五年的Java工程师朋友们加入Java程序员开发： 854393687
群内提供免费的Java架构学习资料（里面有高可用、高并发、高性能及分布式、Jvm性能调优、Spring源码，MyBatis，Netty,Redis,Kafka,Mysql,Zookeeper,Tomcat,Docker,Dubbo,Nginx等多个知识点的架构资料）合理利用自己每一分每一秒的时间来学习提升自己，不要再用"没有时间“来掩饰自己思想上的懒惰！趁年轻，使劲拼，给未来的自己一个交代！