AOP 实现方法耗时统计 -

都将会收录于 202308

2023-08-14 2023-08-14 约 1243 字预计阅读 3 分钟 - 次阅读

AOP = Aspect Oriented Programming 面相切面编程

前置知识

连接点是一个方法，切入点是连接点的子集，指要追加功能的方法。
cron 表达式：秒分时日月年，/k 表示每隔 k 个时间单位执行一次。
@Retention 注解保留策略
- RetentionPolicy.SOURCE ：编译时，静态代码检查的场景
- RetentionPolicy.CLASS ：编译后，ORM（对象关系映射）的场景
- RetentionPolicy.RUNTIME ：运行时通过反射机制处理，IOC、AOP 的场景

声明注解

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
package aop;

import java.lang.annotation.*;

/**
 * 统计方法耗时的注解
 */
@Retention(RetentionPolicy.RUNTIME) // 反射
@Target(ElementType.METHOD)
public @interface MethodMeasureAnnotation {} // 注解类型的声明

切面

  1
  2
  3
  4
  5
  6
  7
  8
  9
 10
 11
 12
 13
 14
 15
 16
 17
 18
 19
 20
 21
 22
 23
 24
 25
 26
 27
 28
 29
 30
 31
 32
 33
 34
 35
 36
 37
 38
 39
 40
 41
 42
 43
 44
 45
 46
 47
 48
 49
 50
 51
 52
 53
 54
 55
 56
 57
 58
 59
 60
 61
 62
 63
 64
 65
 66
 67
 68
 69
 70
 71
 72
 73
 74
 75
 76
 77
 78
 79
 80
 81
 82
 83
 84
 85
 86
 87
 88
 89
 90
 91
 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
package aop;

import cn.hutool.core.date.DateUtil;
import cn.hutool.core.map.MapUtil;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.reflect.MethodSignature;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;

import java.io.BufferedWriter;
import java.io.File;
import java.io.FileWriter;
import java.util.ArrayList;
import java.util.IntSummaryStatistics;
import java.util.List;
import java.util.Map;
import java.util.concurrent.ConcurrentHashMap;
import java.util.stream.Collectors;

/**
 * 统计方法耗时的切面
 */
@Component
@Aspect
public class MethodMeasureAspect {
    private static final Logger LOG = LoggerFactory.getLogger(MethodMeasureAspect.class);
    // 记录方法执行次数
    private Map<String, Integer> methodCount = new ConcurrentHashMap();
    // 记录方法每次执行耗时(ms，毫秒)
    private Map<String, List<Integer>> methodCost = new ConcurrentHashMap();

    // 记录方法每次报错日志
    private Map<String, List<String>> methodErrors = new ConcurrentHashMap();


    /**
     * @param proceedingJoinPoint 切入点
     * @return
     */
    @SuppressWarnings(value = "unchecked") // 抑制编译器对未检查的转换操作的警告
    @Around("@annotation(MethodMeasureAnnotation)") // 环绕通知指定的切入点表达式，拦截 @MethodMeasureAnnotation 注解修饰的方法
    public Object proccess(ProceedingJoinPoint proceedingJoinPoint) {
        Object object = null;
        String className = proceedingJoinPoint.getTarget().getClass().getSimpleName(); // 类名
        String methodName = ((MethodSignature) proceedingJoinPoint.getSignature()).getMethod().getName(); // 方法名
        String methodId = className + methodName; // 类名+方法名，唯一标识某类中的某方法
        long startTime = System.currentTimeMillis(); // 记录开始时间 ms
        try {
            object = proceedingJoinPoint.proceed(); // 执行原方法
        } catch (Throwable t) { // 捕捉所有 Exception 和 Error
            // 记录方法每次报错日志
            List<String> errorList = methodErrors.getOrDefault(methodId, new ArrayList<>());
            errorList.add(t.getMessage());
            LOG.error(t.getMessage(), t);
        } finally {
            long endTime = System.currentTimeMillis(); // 记录结束时间 ms
            long costTime = endTime - startTime; // 方法耗时 ms
            LOG.info("method={}, cost_time={}", methodId, costTime);
            // 记录方法执行次数
            methodCount.put(methodId, methodCount.getOrDefault(methodName, 0) + 1);
            // 记录方法每次执行耗时
            List<Integer> costList = methodCost.getOrDefault(methodId, new ArrayList<>());
            costList.add((int) costTime);
            methodCost.put(methodId, costList);
        }
        return object;
    }

    @Override
    public String toString() {
        // 统计方法执行次数
        StringBuilder sb = new StringBuilder("MethodCount:\n");
        Map<String, Integer> sorted = MapUtil.sortByValue(methodCount, true); // 根据方法执行次数降序排列
        sorted.forEach(
                (method, count) -> {
                    sb.append("method=" + method + ", " + "count=" + count + '\n');
                }
        );
        // 统计方法耗时
        sb.append("\nMethodCosts:\n");
        methodCost.forEach(
                (method, costList) -> {
                    // summarizingInt:返回一个 Collector，该收集器将 int 生成映射函数应用于每个输入元素，并返回结果值的汇总统计信息。
                    IntSummaryStatistics stat = costList.stream().collect(Collectors.summarizingInt(x -> x));
                    String info = String.format("method=%s, sum=%d, avg=%d, max=%d, min=%d, count=%d", method,
                            (int) stat.getSum(), (int) stat.getAverage(), stat.getMax(), stat.getMin(), (int) stat.getCount());
                    sb.append(info + '\n');
                }
        );
        // 方法耗时源数据
        sb.append("\nDetailOfMethodCosts:\n");
        methodCost.forEach(
                (method, costList) -> {
                    String info = String.format("method=%s, cost=%s", method, costList);
                    sb.append(info + '\n');
                }
        );
        // 报错日志源数据
        sb.append("\nDetailOfMethod Errors:\n");
        methodCost.forEach(
                (method, errorList) -> {
                    String info = String.format("method=%s, error=%s", method, errorList);
                    sb.append(info + '\n');
                }
        );
        return sb.toString();
    }

    /**
     * 持久化
     */
    public void writeCostsToFile() {
        String dateTimeStr = DateUtil.now();
        File file = new File(String.format("/tmp/method_costs_%s.txt", dateTimeStr));
        String costContent = this.toString();
        if (!file.exists()) {
            try {
                file.createNewFile();
            } catch (Exception ex) {
                LOG.error("failed to create file /tmp/ids_method_costs.txt", ex);
                return;
            }
            BufferedWriter br;
            try {
                br = new BufferedWriter(new FileWriter(file));
            } catch (Exception ex) {
                LOG.error("failed to open /tmp/ids_method_costs.txt", ex);
                return;
            }
            try {
                br.write(costContent);
                br.flush();
            } catch (Exception ex) {
                LOG.error("failed to write file");
                return;
            }
        }
    }

    /**
     * 总共执行了多少方法
     *
     * @return
     */
    public int methodCount() {
        int count = methodCount.values().stream()
                .mapToInt(Integer::intValue)
                .sum();
        return count;
    }
}

持久化线程通过定时任务输出日志

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
package aop;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.scheduling.annotation.Scheduled;
import org.springframework.stereotype.Component;

/**
 * 持久化线程
 */
@Component
public class MonitorThread {
    private final Logger LOG = LoggerFactory.getLogger(MonitorThread.class);
    private MethodMeasureAspect methodMeasureAspect;

    @Autowired
    public MonitorThread(MethodMeasureAspect methodMeasureAspect) {
        this.methodMeasureAspect = methodMeasureAspect;
    }

    // cron 表达式：秒 分 时 日 月 年
    @Scheduled(cron = "0 0 0/12 * * ?") // 每隔 12 小时执行一次
    public void writeCosts() {
        if (methodMeasureAspect.methodCount() >= 100) { // 执行 100 个方法以上才写日志
            methodMeasureAspect.writeCostsToFile();
        }
    }
}

通过以上注解，可以测量并输出链路耗时，结合 arthas ，就可以容易地定位到应用层的热点区域，为下一步（应用层）性能优化提供充足的数据参考基础。

参考资料

https://www.cnblogs.com/lovesqcc/p/17609593.html