I am working on a spring boot application and I am trying to implement a custom annotation to log execution time and memory used by the method annotated with my custom annotation. I am not able to make it work and have no clue why its not working. I have found similar posts and found various example but none of it work on my case.
Please let me know if I am doing anything wrong here.
Please find my code details below:
build.gradle dependencies :
dependencies {
implementation 'org.springframework.boot:spring-boot-starter-web'
implementation 'org.springframework.boot:spring-boot-starter-webflux'
implementation 'org.springframework.boot:spring-boot-starter-mail'
implementation 'org.springframework.cloud:spring-cloud-starter-sleuth'
implementation "org.springframework.boot:spring-boot-starter-oauth2-resource-server"
implementation 'io.pivotal.spring.cloud:spring-cloud-services-starter-service-registry'
implementation 'io.pivotal.spring.cloud:spring-cloud-services-starter-config-client'
compileOnly 'org.projectlombok:lombok'
annotationProcessor 'org.projectlombok:lombok'
implementation 'com.google.cloud:spring-cloud-gcp-starter'
implementation 'com.google.cloud:spring-cloud-gcp-starter-pubsub'
implementation 'com.google.cloud:spring-cloud-gcp-starter-storage'
implementation 'org.springframework.integration:spring-integration-core'
implementation 'javax.xml.bind:jaxb-api:2.3.0'
implementation 'com.sun.xml.bind:jaxb-core:2.3.0'
implementation 'com.sun.xml.bind:jaxb-impl:2.3.0'
implementation 'javax.annotation:javax.annotation-api:1.3.2'
implementation 'org.springdoc:springdoc-openapi-ui:1.4.3'
implementation 'io.swagger:swagger-annotations:1.6.1'
implementation 'javax.validation:validation-api:2.0.1.Final'
implementation 'org.openapitools:jackson-databind-nullable:0.2.1'
implementation 'org.springframework.boot:spring-boot-starter-actuator'
implementation 'org.springframework.cloud:spring-cloud-starter-loadbalancer'
implementation 'org.springframework.boot:spring-boot-starter-data-jpa'
runtimeOnly 'com.h2database:h2'
implementation('com.oracle.database.jdbc:ojdbc8')
implementation 'org.dom4j:dom4j:2.1.0'
implementation 'com.github.ulisesbocchio:jasypt-spring-boot-starter:3.0.4'
testImplementation 'org.springframework.security:spring-security-test'
testImplementation 'org.springframework.boot:spring-boot-starter-test'
implementation 'org.springframework.boot:spring-boot-starter-amqp'
//testImplementation 'io.projectreactor:reactor-test'
testImplementation 'org.springframework.amqp:spring-rabbit-test'
implementation 'org.springframework.boot:spring-boot-starter-aop'
implementation 'org.aspectj:aspectjweaver'
}
Custom annotation interface:
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)
public @interface LogExecutionProfile {}
Logging Aspect class
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.reflect.MethodSignature;
import org.springframework.stereotype.Component;
import lombok.extern.slf4j.Slf4j;
@Slf4j
@Aspect
@Component
public class LoggingAspect {
@Around("@annotation(LogExecutionProfile) || execution(public * @LogExecutionProfile *.*(..)))")
public Object profileMethod(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
MethodSignature methodSignature = (MethodSignature) proceedingJoinPoint.getSignature();
String className = methodSignature.getDeclaringType().getSimpleName();
String methodName = methodSignature.getName();
long startTime = System.currentTimeMillis();
long memoryAtStart = Runtime.getRuntime().totalMemory() - Runtime.getRuntime().freeMemory();
Object result = proceedingJoinPoint.proceed();
long endTime = System.currentTimeMillis();
long memoryAtEnd = Runtime.getRuntime().totalMemory() - Runtime.getRuntime().freeMemory();
log.debug("execution time: " + (endTime - startTime) + " ms"
+ " memory used: " + (memoryAtEnd - memoryAtStart) + " bytes of memory");
return result;
}
}
Service class :
@Service
public class MyService {
@LogExecutionProfile
public void someServiceMethod(){
log.debug("service log");
// service method logic
}
}
Expected Result :
service log
execution time: XX ms memory used: XX bytes of memory
Actual Result :
service log
I have also tried below :
Example 1 : Not Working
@Pointcut("execution(@com.example.LogExecutionProfile * *.*(..))")
public void annotatedMethod() {}
@Around("annotatedMethod()")
public Object profileMethod(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
**
}
Example 2 : Not Working
@Pointcut("@annotation(com.example.LogExecutionProfile)")
public void annotatedMethod() {}
@Around("execution(* *(..)) && (annotatedMethod())")
public Object profileMethod(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
**
}
Example 3 : Not Working
@Around("@annotation(com.example.LogExecutionProfile)")
public Object profileMethod(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
**
}
An aspect in spring AOP must be annotated by @Configuration and @Aspect . So change your LoggingAspect class with this class
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.reflect.MethodSignature;
import org.springframework.stereotype.Configuration;
import lombok.extern.slf4j.Slf4j;
@Slf4j
@Aspect
@Configuration
public class LoggingAspect {
@Around("@annotation(LogExecutionProfile) || execution(public * @LogExecutionProfile *.*(..)))")
public Object profileMethod(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
MethodSignature methodSignature = (MethodSignature) proceedingJoinPoint.getSignature();
String className = methodSignature.getDeclaringType().getSimpleName();
String methodName = methodSignature.getName();
long startTime = System.currentTimeMillis();
long memoryAtStart = Runtime.getRuntime().totalMemory() - Runtime.getRuntime().freeMemory();
Object result = proceedingJoinPoint.proceed();
long endTime = System.currentTimeMillis();
long memoryAtEnd = Runtime.getRuntime().totalMemory() - Runtime.getRuntime().freeMemory();
log.debug("execution time: " + (endTime - startTime) + " ms"
+ " memory used: " + (memoryAtEnd - memoryAtStart) + " bytes of memory");
return result;
}
There is a sample aspect that you can use
package com.dpco.aop;
import com.dpco.business.exception.CustomException;
import com.dpco.logger.Logger4j;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.context.annotation.Configuration;
import org.springframework.http.HttpStatus;
import org.springframework.web.bind.annotation.RequestMapping;
import java.io.File;
import java.io.FileWriter;
import java.io.IOException;
import java.util.Date;
@Aspect
@Configuration
public class LoggerAspect {
@Autowired
private Logger4j logger4j;
@Pointcut("execution(* com.dpco.controller.*.*(..)) && @annotation(requestMapping)")
public void controller(RequestMapping requestMapping){
}
@Around("controller(requestMapping)")
public Object around(ProceedingJoinPoint joinPoint , RequestMapping requestMapping) throws Throwable {
Object[] obj = joinPoint.getArgs();
File file = new File("log.txt");
Object object = null;
try {
if (file.createNewFile()) {
FileWriter fileWriter = new FileWriter(file);
fileWriter.write("\n\n-----------------------------------------this is the logger of project , you can see the methods that calls and information of them in here------------------------------------\n\n");
fileWriter.close();
}
FileWriter fileWriter = new FileWriter(file, true);
Date first = new Date();
fileWriter.write("\n---------------------------------------" + joinPoint.getSignature().getName() + "-------------------------------------------\n");
fileWriter.write("path is : " + requestMapping.path()[0] + "\n");
fileWriter.write("the method of request is :" + requestMapping.method()[0] + "\n");
StringBuilder builder = new StringBuilder();
for (Object arg : obj) {
builder.append(arg.toString() + ",");
}
if(builder.length() != 0) {
builder.deleteCharAt(builder.indexOf(builder.toString()));
}
fileWriter.write("the arguments of this method is : " + builder.toString() + "\n");
object = joinPoint.proceed();
Date second = new Date();
fileWriter.write("the milli seconds that left : " + String.valueOf(second.getTime() - first.getTime()));
fileWriter.close();
} catch (IOException e) {
logger4j.getLogger(e);
throw new CustomException("hello", HttpStatus.MULTI_STATUS);
}
return object;
}
}
This aspect will be executed around any method in controller package wich annotated by request mapping.
I think after using @Configuration up to your aspect class and omit @Component it will work correctly .