基于 Slf4j 和 AOP 的自动化方法执行时间日志记录方案
前言
其实这个需求很简单，但是这个需求又是项目中必不可少的，尤其对于性能调优这块，但是使用哪种方式更加方便呢，这就是本篇博文需要讨论的重点
系统时间
可以通过 System.currentTimeMillis() 或 System.nanoTime() 来实现。
以下是一个简单的示例，展示如何记录某段代码的执行时间并打印日志：
import java.util.logging.Logger;
public class TimeLogger {
private static final Logger logger = Logger.getLogger(TimeLogger.class.getName());
public static void main(String[] args) {
long startTime = System.nanoTime(); // 记录开始时间
// 你的代码逻辑
performTask();
long endTime = System.nanoTime(); // 记录结束时间
long duration = endTime - startTime; // 计算耗时
logger.info("Task executed in " + duration + " nanoseconds.");
}
private static void performTask() {
try {
Thread.sleep(2000); // 模拟耗时操作
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
解释：
- System.nanoTime()：返回当前时间的纳秒值，适合计算时间差。
- 计算耗时后，通过日志框架（如 Logger）打印出来。
如果你使用的是其他日志框架（如 Log4j 或 SLF4J），可以相应地调整日志打印部分。
这个方法适用于测量较精确的时间差。如果是需要秒级别的时间，可以使用 System.currentTimeMillis()。
使用 Instant 和 Duration（Java 8+）
Java 8 引入了 java.time 包，可以使用 Instant 来获取时间戳，并使用 Duration 来计算时间差。
import java.time.Duration;
import java.time.Instant;
import java.util.logging.Logger;
public class TimeLogger {
private static final Logger logger = Logger.getLogger(TimeLogger.class.getName());
public static void main(String[] args) {
Instant start = Instant.now(); // 记录开始时间
// 你的代码逻辑
performTask();
Instant end = Instant.now(); // 记录结束时间
Duration duration = Duration.between(start, end); // 计算时间差
logger.info("Task executed in " + duration.toMillis() + " milliseconds.");
}
private static void performTask() {
try {
Thread.sleep(2000); // 模拟耗时操作
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
使用 StopWatch（Apache Commons Lang）
StopWatch 是 Apache Commons Lang 提供的一个便捷工具类，用于测量时间。它简单易用，并且可以多次启动和停止。
首先，你需要引入 Apache Commons Lang 库：
<dependency>
<groupId>org.apache.commons</groupId>
<artifactId>commons-lang3</artifactId>
<version>3.12.0</version>
</dependency>
然后，可以像这样使用 StopWatch：
import org.apache.commons.lang3.time.StopWatch;
import java.util.logging.Logger;
public class TimeLogger {
private static final Logger logger = Logger.getLogger(TimeLogger.class.getName());
public static void main(String[] args) {
StopWatch stopWatch = new StopWatch();
stopWatch.start(); // 开始计时
// 你的代码逻辑
performTask();
stopWatch.stop(); // 停止计时
logger.info("Task executed in " + stopWatch.getTime() + " milliseconds.");
}
private static void performTask() {
try {
Thread.sleep(2000); // 模拟耗时操作
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
使用 AOP 进行日志记录（面向切面编程）
如果你希望在多个方法或类中都记录耗时，可以使用 Spring AOP 或其他 AOP 框架来自动化这一过程。这样，你就不需要在每个方法中显式地编写时间计算代码。
假设你使用的是 Spring 框架，可以通过 AOP 实现：
自定义一个注解
@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface PrintExecutionTime {
}
面向切面
@Slf4j
@Aspect
@Component
@RequiredArgsConstructor
public class ExecutionTimeAspect {
private final LogConfig logConfig;
@Around("@annotation(PrintExecutionTime)")
public Object logExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
long startTime = System.currentTimeMillis();
Object result = joinPoint.proceed();
long endTime = System.currentTimeMillis();
long executionTime = endTime - startTime;
if (executionTime > logConfig.getTime()) {
log.warn("Code method time-consuming, class: {}, executionTime: {} ms", joinPoint.getSignature().toString(),
executionTime);
}
return result;
}
}
使用 Slf4j + Logback 配合计时器（例如，通过 MDC 传递信息）
如果你已经在使用 SLF4J 和 Logback，SLF4J 提供了一些扩展，可以通过 MDC 来传递方法的执行时间等信息。
import org.slf4j.MDC;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class TimeLogger {
private static final Logger logger = LoggerFactory.getLogger(TimeLogger.class);
public static void main(String[] args) {
long startTime = System.nanoTime(); // 记录开始时间
// 你的代码逻辑
performTask();
long endTime = System.nanoTime(); // 记录结束时间
long duration = endTime - startTime; // 计算耗时
MDC.put("executionTime", String.valueOf(duration)); // 将耗时信息放入 MDC
logger.info("Task executed.");
MDC.clear(); // 清理 MDC
}
private static void performTask() {
try {
Thread.sleep(2000); // 模拟耗时操作
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
在 Logback 配置中，你可以使用 %X{executionTime} 来输出 MDC 中的 executionTime：
<layout class="ch.qos.logback.classic.pattern.PatternLayout">
<Pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg - Execution Time: %X{executionTime}ms%n</Pattern>
</layout>
Slf4j + Logback +MDC+AOP
在实际项目中使用 Slf4j + Logback 配合计时器 并通过 MDC (Mapped Diagnostic Context) 传递信息来记录方法执行时间是一个很常见且高效的方案。这样可以在日志输出中直接查看方法的执行时间，而无需在每个方法中显式记录时间。
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Pointcut;
import org.aspectj.lang.ProceedingJoinPoint;
import org.slf4j.MDC;
import org.springframework.stereotype.Component;
import java.time.Duration;
import java.time.Instant;
@Aspect
@Component
public class PerformanceAspect {
@Pointcut("execution(* com.example..*(..))") // 定义切点，匹配指定包下的所有方法
public void performanceLogging() {
}
@Around("performanceLogging()") // 环绕通知
public Object logExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
// 记录方法开始时间
Instant start = Instant.now();
// 执行目标方法
Object proceed = joinPoint.proceed();
// 记录方法结束时间
Instant end = Instant.now();
long executionTime = Duration.between(start, end).toMillis();
// 将耗时信息传入 MDC
MDC.put("executionTime", String.valueOf(executionTime));
// 打印日志
String methodName = joinPoint.getSignature().toShortString();
// 如果你在日志中想要包括方法名称、类名等，可以在这里添加
logger.info("Method {} executed in {} ms", methodName, executionTime);
// 清除 MDC，避免 MDC 数据影响其他日志
MDC.clear();
return proceed;
}
}
<configuration>
<!-- Define the pattern for logging -->
<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg - Execution Time: %X{executionTime}ms%n</pattern>
</encoder>
</appender>
<!-- Root logger definition -->
<root level="debug">
<appender-ref ref="console"/>
</root>
</configuration>
使用 @EnableAspectJAutoProxy
如果你使用 Spring Boot，可以通过 @EnableAspectJAutoProxy 启用 AOP
在 @SpringBootApplication 或配置类中添加：
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.context.annotation.EnableAspectJAutoProxy;
@SpringBootApplication
@EnableAspectJAutoProxy
public class Application {
public static void main(String[] args) {
SpringApplication.run(Application.class, args);
}
}
总结
[开始方法] → [AOP 拦截] → [开始计时] → [业务逻辑执行] → [结束计时] → [MDC 存储时间]
↓
[日志输出] ← [MDC 输出时间]
通过结合 Slf4j + Logback 和 AOP，我们可以自动化地记录方法执行的时间，并将其通过 MDC 传递到日志系统中，而无需手动添加时间记录的代码。这种方式在生产环境中非常方便，可以让你实时了解应用的性能瓶颈，且对代码的侵入性非常低。