Stage 32: measure a method with @LogExecutionTime
Learning path / Stage 32 of 37
Observe extra behaviour around an existing product service without mixing it into the business operation.
Download the complete Stage 32 project · Open the project guide
Before you start
Use JDK 21 or newer and Maven 3.9 or newer. Verify with java -version and mvn -version. Extract this project into its own folder; do not merge its files with another stage.
This lesson reuses the product catalog and Todo responsibilities from Stages 8–14. Only the feature described below is new. Read the ordered explanation before opening the complete files.
What we change and why
Keep business logic in the service
ProductService.count returns the product count. The aspect contains the additional logging concern; the service does not call the aspect itself.
Enable proxy-based interception
@EnableAspectJAutoProxy installs Spring’s annotation-driven AOP support. We request class-based proxies to keep the concrete service lookup simple. AspectJ annotations and pointcut expressions are used with Spring runtime proxies, not AspectJ bytecode weaving.
Name the AOP pieces
The service method execution is the join point. The pointcut selects executions. The advice is the extra method that runs. The aspect groups these rules. In Spring AOP, interception applies to method execution through eligible managed proxies, not arbitrary source-code lines.
Select one annotated method
Our @LogExecutionTime annotation is retained at runtime so the pointcut can inspect it. Only methods carrying that annotation are selected.
Preserve the original operation
Around advice calls proceed exactly once, returns its result and allows exceptions to propagate. finally records elapsed time even if the method fails. Timing output varies; this is an observation example rather than a performance benchmark.
Keep the demonstration counter in context
TimingAspect.invocations exists only to verify these sequential console calls. This mutable counter is not a production metric for concurrent requests.
Run this example
Open a terminal in the extracted folder containing pom.xml. Run one command at a time.
mvn test
mvn spring-boot:runThis is a console lesson. It does not open a web port. Application.main starts a Spring context, calls the demonstration and closes the context. Read the terminal, not a browser. Spring Boot’s Maven plugin is used as a convenient launcher; these examples show Spring Framework directly.
Expected result
Timed count: <varying number> ns
External result: 2Object identifiers and elapsed times can vary. Compare the relationship between values rather than copying an identifier.
Understand each complete file
Create the following files at exactly these paths, or use the ZIP. Source files include their imports. The test checks the behaviour described in the lesson.
pom.xml
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd">
<modelVersion>4.0.0</modelVersion>
<parent><groupId>org.springframework.boot</groupId><artifactId>spring-boot-starter-parent</artifactId><version>4.1.1</version><relativePath/></parent>
<groupId>com.edupoly</groupId><artifactId>spring-stage-32-execution-time</artifactId><version>1.0.0</version>
<properties><java.version>21</java.version></properties>
<dependencies>
<dependency><groupId>org.springframework.boot</groupId><artifactId>spring-boot-starter</artifactId></dependency>
<dependency><groupId>org.springframework.boot</groupId><artifactId>spring-boot-starter-test</artifactId><scope>test</scope></dependency>
<dependency><groupId>org.springframework</groupId><artifactId>spring-aop</artifactId></dependency>
<dependency><groupId>org.aspectj</groupId><artifactId>aspectjweaver</artifactId></dependency>
</dependencies>
<build><plugins><plugin><groupId>org.springframework.boot</groupId><artifactId>spring-boot-maven-plugin</artifactId></plugin></plugins></build>
</project>
src/main/java/com/edupoly/lesson/AppConfig.java
package com.edupoly.lesson;
import org.springframework.context.annotation.*;
@Configuration @ComponentScan("com.edupoly.lesson") @EnableAspectJAutoProxy(proxyTargetClass = true)
public class AppConfig { }
src/main/java/com/edupoly/lesson/LogExecutionTime.java
package com.edupoly.lesson;
import java.lang.annotation.*;
@Retention(RetentionPolicy.RUNTIME) @Target(ElementType.METHOD)
public @interface LogExecutionTime { }
src/main/java/com/edupoly/lesson/TimingAspect.java
package com.edupoly.lesson;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.*;
import org.springframework.stereotype.Component;
@Aspect @Component public class TimingAspect {
private int invocations;
public int invocations() { return invocations; }
@Around("@annotation(com.edupoly.lesson.LogExecutionTime)")
public Object time(ProceedingJoinPoint point) throws Throwable {
invocations++;
long start = System.nanoTime();
try { return point.proceed(); }
finally { System.out.println("Timed " + point.getSignature().getName() + ": " + (System.nanoTime() - start) + " ns"); }
}
}
src/main/java/com/edupoly/lesson/ProductService.java
package com.edupoly.lesson;
import org.springframework.stereotype.Service;
@Service public class ProductService {
@LogExecutionTime public int count() { return 2; }
public int countInternally() { return this.count(); }
}
src/main/java/com/edupoly/lesson/Lesson.java
package com.edupoly.lesson;
import org.springframework.stereotype.Component;
@Component public class Lesson {
private final ProductService service; private final TimingAspect aspect;
public Lesson(ProductService service, TimingAspect aspect) { this.service = service; this.aspect = aspect; }
public void run() {
System.out.println("External result: " + service.count());
}
}
src/main/java/com/edupoly/lesson/Application.java
package com.edupoly.lesson;
import org.springframework.context.annotation.AnnotationConfigApplicationContext;
public class Application {
public static void main(String[] args) throws Exception {
try (var context = new AnnotationConfigApplicationContext(AppConfig.class)) {
context.getBean(Lesson.class).run();
}
}
}
src/test/java/com/edupoly/lesson/LessonTest.java
package com.edupoly.lesson;
import org.junit.jupiter.api.Test;
import static org.junit.jupiter.api.Assertions.*;
import org.springframework.context.annotation.AnnotationConfigApplicationContext;
class LessonTest {
@Test void advicePreservesReturnValueAndUsesProxy() {
try (var context = new AnnotationConfigApplicationContext(AppConfig.class)) {
var service = context.getBean(ProductService.class);
assertTrue(org.springframework.aop.support.AopUtils.isAopProxy(service));
assertEquals(2, service.count());
var aspect = context.getBean(TimingAspect.class);
assertEquals(1, aspect.invocations());
assertEquals(2, service.countInternally());
assertEquals(1, aspect.invocations());
}
}
}
Try a failure, then correct it
Remove proceed() from around advice. The original method is no longer executed. Restore exactly one call and return its result.
Words you can now explain
| Word | Meaning in this example |
|---|---|
| @Around | Advice wrapping the selected invocation. |
| proceed() | Executes the wrapped method and obtains its result. |
Practice assignment
Add another service method. Predict whether the current pointcut matches it, then run the example to check. Keep the service return value unchanged.
Concepts used in this stage
Use the right column for a quick reminder, or open a concept above for its full explanation.