526互联

性能优化：如何定位耗时区域

发布时间 2023-08-06 17:14:43作者: 琴水玉

对一个系统的量化工作越深入，掌握的关键数字越多，意味着对这个系统的认识也就越深入。


引子

随着系统功能的不断垒积，系统运行会变慢，甚至慢得难以忍受，用户会强烈吐槽，这时候，就需要性能优化了。

要做性能优化，首要的就是先定位耗时区域。耗时区域也成为“热点”。不做热点定位的性能优化都是耍流氓，—— 很可能花费了很大力气，自我感觉良好，实际上收益甚微，而且不知道优化效果如何。

测量与耗时

要定位耗时区域，首先要了解下耗时。我们需要对程序运行的耗时有一个基本的理解。先来看 arthas trace 的一个方法的耗时：

[arthas@7]$ trace com.xxx.yyy.zzz.msg.LoginEventKafkaReceiver onRecord -n 1000
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 497 ms, listenerId: 1
`---ts=2023-07-27 11:35:11;thread_name=tc_ids_login_event_kafka-worker-93;id=c5;is_daemon=false;priority=5;TCCL=org.springframework.boot.loader.LaunchedURLClassLoader@21b8d17c
    `---[36.115748ms] com.xxx.yyy.zzz.msg.LoginEventKafkaReceiver:onRecord()
        +---[0.40% 0.145356ms ] com.xxx.yyy.zzz.util.RequestContextUtils:initRequestContext() #154
        +---[0.05% 0.016523ms ] org.apache.kafka.clients.consumer.ConsumerRecord:value() #156
        +---[1.20% 0.433854ms ] com.xxx.yyy.zzz.util.JsonUtils:readTree() #156
        +---[1.80% 0.651734ms ] com.xxx.yyy.zzz.msg.LoginEventKafkaReceiver:parse() #157
        +---[0.05% 0.016316ms ] org.apache.commons.collections4.CollectionUtils:isEmpty() #159
        +---[0.03% 0.009452ms ] com.xxx.yyy.zzz.lib.event.agent.LoginEventDTO:getAgentId() #163
        +---[0.36% 0.1307ms ] com.xxx.yyy.zzz.helper.info.HostInfoHelper:getHost() #164
        +---[56.30% 20.334184ms ] com.xxx.yyy.zzz.msg.LoginEventKafkaReceiver:saveLoginEvents() #170
        +---[26.53% 9.580277ms ] com.xxx.yyy.zzz.msg.LoginEventKafkaReceiver:sendToBigdataForHandling() #173
        +---[5.55% 2.006107ms ] com.xxx.yyy.zzz.msg.handler.MultiLoginEventHandler:handle() #176
        `---[4.99% 1.802963ms ] com.xxx.yyy.zzz.msg.handler.BeyondRangeLoginEventHandler:handle() #178

从这段耗时我们可以了解到：

  • 大多数“无害”的轻量级方法，耗时大概在 0.1ms 及以下，比如简单的赋值、判断是否非空、简单的 Get 方法及运算；
  • 部分“无害”的方法，耗时在 0.1ms - 1ms 之间，比如 大 JSON 解析、大对象的 Bean copy, 日志打印等， 这些大多时候都可以不理会，除非是要优化到极致做微调的时候。
  • 需要注意的可以优化的方法，往往在 IO、正则以及分布式锁上。比如 mongo, MySQL、Redis 读写、API 调用。这些快的通常在 1-3ms，慢的可能会达到 10-100ms，更慢的可能会到 100ms-1000ms。

性能优化的第一步，就是先找到这些耗时在 10ms 以上的方法。

测量的另一个优点是，你甚至无需实际执行实验，就能“预见”优化效果。比如有个 100ms 的方法，由 40ms 和 60ms 的两个方法组成。 如果你把 60ms 优化到 10ms ，那么优化效果提升多少？ 可以算出来的。 原来的 TPS = 10， 优化后的 TPS = 20。性能提升一倍！你可以在测试同学面前自豪地说：性能提升 100%。等他或她执行完实验，发现果真如此，才会更加敬佩你呢！

预见力来自数学。著名的摩尔定律，也是基于晶体管数量每年增长一倍的数学规律来预见的。

工具

工欲善其事，必先利其器。

可以说，做软件这一行，我们少不了各种工具。 IDE（编辑器+编译器+调试器+项目管理+各种插件功能），Git，Postman，MySQL Client, Shell，Xmind, Notebook，JProfiler，放眼望去都是工具。

现有的性能神器之一当属阿里出品的 arthas。arthas trace 对于单个入口方法的追踪很管用，可以在定位某个耗时组件后，进一步持续深入追踪直到某个点，然后优化。可称之为“精确制导”。

不过 arthas trace 无法追踪整个链路的方法耗时。入侵检测流程需要经历告警过滤、告警降噪、恶意行为检测、检测结果预处理、构建告警详情、保存告警前处理、保存告警、保存告警后处理、白名单匹配、发送通知、发送大数据等一系列子流程（组件）。单靠 arthas 来 trace 是比较麻烦的。因为你不知道哪个子流程（组件）是耗时的，得一个个去 trace 。此外，trace 的时候也没法做其它的事情，需要全身心集中在这里。

因此，需要写个工具，测量整个链路的方法耗时，并记录在文件里，待稍后再分析。

链路耗时测量

链路耗时测量工具通常有两种方法实现：

  • 注解 + 切面 + 反射。在方法上加注解，然后通过切面和反射来统计和搜集方法耗时。
  • 通过 agent。涉及字节码。

本文主要谈谈第一种方法的实现。直接上代码。


方法测量注解

package com.xxx.yyy.zzzperf;
 
import java.lang.annotation.Documented;
import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;
 
/**
 * 记录方法调用
 */
@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
@Documented
public @interface MethodMeasureAnnotation {
 
}

方法耗时统计

package com.xxx.yyy.zzzperf;

import com.xxx.yyy.zzz.util.DateTimeUtils;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.Signature;
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.lang.reflect.Method;
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();

    private Map<String, List<Integer>> methodCost = new ConcurrentHashMap();

    @SuppressWarnings(value = "unchecked")
    @Around("@annotation(com.xxx.yyy.zzzperf.MethodMeasureAnnotation)")
    public Object process(ProceedingJoinPoint joinPoint) {
        Object obj = null;
        String className = joinPoint.getTarget().getClass().getSimpleName();
        String methodName = className + "_" + getMethodName(joinPoint);
        long startTime = System.currentTimeMillis();
        try {
            obj = joinPoint.proceed();
        } catch (Throwable t) {
            LOG.error(t.getMessage(), t);
        } finally {
            long costTime = System.currentTimeMillis() - startTime;
            LOG.info("method={}, cost_time={}", methodName, costTime);
            methodCount.put(methodName, methodCount.getOrDefault(methodName, 0) + 1);
            List<Integer> costList = methodCost.getOrDefault(methodName, new ArrayList<>());
            costList.add((int)costTime);
            methodCost.put(methodName, costList);
        }
        return obj;
    }

    public String getMethodName(ProceedingJoinPoint joinPoint) {
        Signature signature = joinPoint.getSignature();
        MethodSignature methodSignature = (MethodSignature) signature;
        Method method = methodSignature.getMethod();
        return method.getName();
    }

    public String toString() {

        StringBuilder sb = new StringBuilder("MethodCount:\n");
        Map<String,Integer> sorted =  MapUtils.sortByValue(methodCount);
        sorted.forEach(
                (method, count) -> {
                    sb.append("method=" + method + ", " + "count=" + count+'\n');
                }
        );
        sb.append('\n');
        sb.append("MethodCosts:\n");
        methodCost.forEach(
                (method, costList) -> {
                    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('\n');
        sb.append("DetailOfMethodCosts:\n");
        methodCost.forEach(
                (method, costList) -> {
                    String info = String.format("method=%s, cost=%s", method, costList);
                    sb.append(info+'\n');
                }
        );
        return sb.toString();
    }

    public void writeCostsToFile() {
        String datetimestr = DateTimeUtils.formatToString(System.currentTimeMillis(), DateTimeUtils.DATE_TIME_NEW);
        File file = new File(String.format("/tmp/ids_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;
            }
        }
    }

    public int methodCount() {
        int count = methodCount.values().stream()
                .mapToInt(Integer::intValue)
                .sum();
        return count;
    }
}

方法耗时持久化

起一个定时任务，将方法耗时统计写到文件里

package com.xxx.yyy.zzz.zzzperf;

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;

/**
 * MonitorThread:
 * created by qin.shu 2023/7/19
 */
@Component
public class MonitorThread {

    private final Logger LOG = LoggerFactory.getLogger(MonitorThread.class);

    private MethodMeasureAspect methodMeasureAspect;

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

    @Scheduled(cron = "0 0/5 * * * ?")
    public void writeCosts() {
        if (methodMeasureAspect.methodCount() >= 100) {
            methodMeasureAspect.writeCostsToFile();
        }
    }

}

注解使用

只要把注解写在方法上即可。

由于 注解切面使用了 Spring AOP 代理，会把相应类加强，改变类名，因此需要做点处理。

package com.xxx.yyy.zzz.core.eventflow.factory;

import com.xxx.yyy.zzz.definitions.BizComponent;
import com.xxx.yyy.zzz.AbstractComponentFactory;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.BeansException;
import org.springframework.context.ApplicationContext;
import org.springframework.context.ApplicationContextAware;
import org.springframework.stereotype.Component;

import javax.annotation.PostConstruct;
import java.util.Map;

/**
 * 业务组件工厂
 */
@Component
public class DefaultComponentFactory extends AbstractComponentFactory implements ApplicationContextAware {

    private final Logger LOG = LoggerFactory.getLogger(this.getClass());

    private ApplicationContext applicationContext;

    private static final String ENHANCER_CLASS = "$$Enhancer";

    @Override
    public void setApplicationContext(ApplicationContext applicationContext) throws BeansException {
        this.applicationContext = applicationContext;
    }

    @PostConstruct
    public void init() {
        initBeans(this::getOriginClassName);
    }

    @Override
    public Map<String, BizComponent> getComponentBeans() {
        Map<String, BizComponent> componentMap = applicationContext.getBeansOfType(BizComponent.class);
        LOG.info("components-keys: {}", componentMap.keySet());
        return componentMap;
    }

    /**
     * 当类被 AOP 代理后，类名会发送变化 (比如 WebshellCdcChecker => WebshellCdcChecker$$EnhancerBySpringCGLIB$$2e63ab2d)，
     * 此时加载到组件工厂的类名与 eventflows_detection.yml 不一致，从而找不到对应组件类执行
     * @param className 可能被代理加强的类名
     * @return 原始类名
     */
    private String getOriginClassName(String className) {
        int index = className.indexOf(ENHANCER_CLASS);
        if (index == -1) {
            return className;
        }
        return className.substring(0, index);
    }
}

最终生成的耗时文件如下（这里仅截取一次小的运行）：

可以很明显看到哪些方法耗时是值得关注的（通过 avg 可以知道，需要重点优化）、哪些方法的波动比较大（通过 max 与 avg 的对比可以知道，对 TPS 也有影响），需要特别关注。

这样，我们就可以通过 arthas trace 这些方法，进一步找到耗时点。通常是某个数据库操作（没加索引、IO 不太好等因素导致） 或者外部 API 性能不佳。

性能优化的具体方法，我们在下一篇文章再见。

MethodCount:
method=HandleBeforeDetectionSaver_process, count=12
method=HandleAfterDetectionSaver_process, count=12
method=FillDetectionRuleDoBuilder_process, count=12
method=DetectionDuplicateChecker_process, count=12
method=NotifyConsumer_consume, count=12
method=DetectionNotifySender_process, count=12
method=DetectionDoBuilder_process, count=12
method=HandleBeforeWhiteRuleChecker_process, count=12
method=WhiteRulesHitRelationSaver_process, count=12
method=DetectionPreparationHandler_process, count=12

MethodCosts:
method=HandleBeforeDetectionSaver_process, sum=1, avg=0, max=1, min=0, count=12
method=HandleAfterDetectionSaver_process, sum=4134, avg=344, max=1145, min=24, count=12
method=FillDetectionRuleDoBuilder_process, sum=199, avg=16, max=187, min=0, count=12
method=DetectionDuplicateChecker_process, sum=18, avg=1, max=3, min=1, count=12
method=NotifyConsumer_consume, sum=1778, avg=148, max=754, min=54, count=12
method=DetectionNotifySender_process, sum=15, avg=1, max=9, min=0, count=12
method=DetectionDoBuilder_process, sum=427, avg=35, max=138, min=12, count=12
method=HandleBeforeWhiteRuleChecker_process, sum=1, avg=0, max=1, min=0, count=12
method=WhiteRulesHitRelationSaver_process, sum=3, avg=0, max=2, min=0, count=12
method=DetectionPreparationHandler_process, sum=8, avg=0, max=2, min=0, count=12

DetailOfMethodCosts:
method=HandleBeforeDetectionSaver_process, cost=[1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
method=HandleAfterDetectionSaver_process, cost=[1066, 1098, 49, 1145, 69, 52, 47, 158, 361, 33, 24, 32]
method=FillDetectionRuleDoBuilder_process, cost=[187, 1, 1, 1, 1, 1, 1, 3, 1, 0, 1, 1]
method=DetectionDuplicateChecker_process, cost=[3, 1, 1, 2, 1, 2, 1, 1, 1, 1, 2, 2]
method=NotifyConsumer_consume, cost=[754, 80, 103, 104, 220, 92, 67, 91, 85, 67, 54, 61]
method=DetectionNotifySender_process, cost=[9, 3, 0, 0, 1, 0, 0, 1, 1, 0, 0, 0]
method=DetectionDoBuilder_process, cost=[106, 38, 138, 18, 18, 12, 31, 17, 12, 13, 12, 12]
method=HandleBeforeWhiteRuleChecker_process, cost=[1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
method=WhiteRulesHitRelationSaver_process, cost=[2, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
method=DetectionPreparationHandler_process, cost=[2, 1, 0, 1, 1, 0, 1, 0, 0, 1, 0, 1]

疑问

反射是否会影响耗时呢？一般来说，反射虽然有性能开销，但相比耗时业务方法来说，是可以忽略不计的。因此，使用反射来统计方法耗时，对最终统计结果是不影响的，基本可以反映业务方法的真实耗时（可能会差个0.x ms）。

小结

本文给出一个测量链路耗时的工具。结合 arthas ，就可以容易地定位到应用层的热点区域，为下一步（应用层）性能优化提供充足的数据参考基础。

对一个系统的量化工作越深入，掌握的关键数字越多，意味着对这个系统的认识也就越深入。

参考资料