性能优化：如何定位耗时区域
对一个系统的量化工作越深入，掌握的关键数字越多，意味着对这个系统的认识也就越深入。
引子
随着系统功能的不断垒积，系统运行会变慢，甚至慢得难以忍受，用户会强烈吐槽，这时候，就需要性能优化了。
要做性能优化，首要的就是先定位耗时区域。耗时区域也成为“热点”。不做热点定位的性能优化都是耍流氓，—— 很可能花费了很大力气，自我感觉良好，实际上收益甚微，而且不知道优化效果如何。
测量与耗时
要定位耗时区域，首先要了解下耗时。我们需要对程序运行的耗时有一个基本的理解。先来看 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%。等他或她执行完实验，发现果真如此，才会更加敬佩你呢！
预见力来自数学。著名的摩尔定律，也是基于晶体管数量每18个月增长一倍的数学规律来预见的。
工具
工欲善其事，必先利其器。
可以说，做软件这一行，我们少不了各种工具。 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 代理后，类名会发送变化 (比如 XYZChecker => XYZChecker$$EnhancerBySpringCGLIB$$2e63ab2d)，
* 此时加载到组件工厂的类名与组件编排文件不一致，从而找不到对应组件类执行
* @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=XYZSaver_process, count=12
method=ZZZSaver_process, count=12
method=XYZBuilder_process, count=12
method=XYZChecker_process, count=12
method=XYZConsumer_consume, count=12
method=XYZSender_process, count=12
method=ZZZBuilder_process, count=12
method=XYZChecker_process, count=12
method=XXXSaver_process, count=12
method=XYZHandler_process, count=12
MethodCosts:
method=XYZSaver_process, sum=1, avg=0, max=1, min=0, count=12
method=ZZZSaver_process, sum=4134, avg=344, max=1145, min=24, count=12
method=XYZBuilder_process, sum=199, avg=16, max=187, min=0, count=12
method=XYZChecker_process, sum=18, avg=1, max=3, min=1, count=12
method=XYZConsumer_consume, sum=1778, avg=148, max=754, min=54, count=12
method=XYZSender_process, sum=15, avg=1, max=9, min=0, count=12
method=ZZZBuilder_process, sum=427, avg=35, max=138, min=12, count=12
method=XYZChecker_process, sum=1, avg=0, max=1, min=0, count=12
method=XXXSaver_process, sum=3, avg=0, max=2, min=0, count=12
method=XYZHandler_process, sum=8, avg=0, max=2, min=0, count=12
DetailOfMethodCosts:
method=XYZSaver_process, cost=[1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
method=ZZZSaver_process, cost=[1066, 1098, 49, 1145, 69, 52, 47, 158, 361, 33, 24, 32]
method=XYZBuilder_process, cost=[187, 1, 1, 1, 1, 1, 1, 3, 1, 0, 1, 1]
method=XYZChecker_process, cost=[3, 1, 1, 2, 1, 2, 1, 1, 1, 1, 2, 2]
method=XYZConsumer_consume, cost=[754, 80, 103, 104, 220, 92, 67, 91, 85, 67, 54, 61]
method=XYZSender_process, cost=[9, 3, 0, 0, 1, 0, 0, 1, 1, 0, 0, 0]
method=ZZZBuilder_process, cost=[106, 38, 138, 18, 18, 12, 31, 17, 12, 13, 12, 12]
method=XYZChecker_process, cost=[1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
method=XXXSaver_process, cost=[2, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
method=XYZHandler_process, cost=[2, 1, 0, 1, 1, 0, 1, 0, 0, 1, 0, 1]
疑问
反射是否会影响耗时呢？一般来说，反射虽然有性能开销，但相比耗时业务方法来说，是可以忽略不计的。因此，使用反射来统计方法耗时，对最终统计结果是不影响的，基本可以反映业务方法的真实耗时（可能会差个0.x ms）。
小结
本文给出一个测量链路耗时的工具。结合 arthas ，就可以容易地定位到应用层的热点区域，为下一步（应用层）性能优化提供充足的数据参考基础。
对一个系统的量化工作越深入，掌握的关键数字越多，意味着对这个系统的认识也就越深入。
