Log Execution Time

log_entry.json

{
  "message": "SqlSomethingStore.get 192ms args=[\"1\"]",
  "logger_name": "fr.app.SqlSomethingStore",
  "perf": {
    "args": "[\"1\"]",
    "durationInMs": 192,
    "kind": "STORE:READ",
    "function": "SqlSomethingStore.get"
  }
}

LogExecutionTime.java

@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface LogExecutionTime {

    /**
     * Returns the kind of execution time to log
     *
     * @return the kind of execution time to log
     */
    String kind() default "-";
}

LogRepositoryMethodExecutionTime.java

@Aspect
@Component
public class LogRepositoryMethodExecutionTimeAspect {

    private final Logger logger;

    public LogRepositoryMethodExecutionTimeAspect(LoggerFactory loggerFactory) {
        this.logger = loggerFactory.getLogger(LogRepositoryMethodExecutionTimeAspect.class);
    }

    @Around("@annotation(LogExecutionTime)")
    public Object logExecutionTime(ProceedingJoinPoint point) throws Throwable {
        long startTime = System.nanoTime();

        final Object proceed = point.proceed();
     
        Map<String, Object> perfEntries = new HashMap<>(5);
      
        long durationInMs = computeDuration(startTime);
        perfEntries.put("durationInMs", durationInMs);

        LogExecutionTime annotation = ((MethodSignature) point.getSignature()).getMethod().getAnnotation(LogExecutionTime.class);
        perfEntries.put("kind", annotation.kind());
      
        String classAndMethodName = point.getSignature().getDeclaringType().getSimpleName() + "." + point.getSignature().getName();
        perfEntries.put("function", classAndMethodName);
      
        String args = Arrays.toString(Arrays.stream(point.getArgs()).map(this::argToString).toArray());
        perfEntries.put("args", args);
      
        logger.info("{} {}ms args={}", classAndMethodName, durationInMs, args, keyValue("perf", perfEntries));
      
        return proceed;
    }

    private Object argToString(Object arg) {
        if (ClassUtils.isPrimitiveOrWrapper(arg.getClass()) || arg instanceof String) {
            return arg;
        }
        return arg.getClass().getSimpleName();
    }

    private static long computeDuration(long startTime) {
        long endTime = System.nanoTime();
        return (endTime - startTime) / 1000000;
    }
}

SqlSomethingStore.java

@Slf4j
@Component
public class SqlSomethingStore implements SomethingStore {

    private final SomethingRepository somethingRepository;

    public SqlSomethingStore(SomethingRepository somethingRepository) {
        this.somethingRepository = somethingRepository;
    }

    @Override
    @LogExecutionTime(kind = "STORE:READ")
    public Something get(String id) {
        return somethingRepository.get(id);
    }
}