基于 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)); // 将耗时信息放入 MDClogger.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();// 将耗时信息传入 MDCMDC.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 传递到日志系统中，而无需手动添加时间记录的代码。这种方式在生产环境中非常方便，可以让你实时了解应用的性能瓶颈，且对代码的侵入性非常低。