Added ExecutionTime

pom.xml

@@ -12,6 +12,7 @@
         <module>server-bom</module>
         <module>server</module>
         <module>registry-server-runner</module>
+        <module>spring-utils</module>
     </modules>
 
     <properties>

registry-server-runner/src/main/resources/application.properties

@@ -3,4 +3,6 @@ server.port=9095
 server.servlet.context-path=/service-registry/api/v2
 spring.redis.host=${REDIS_HOST}
 spring.redis.port=${REDIS_PORT}
-etcd.leader.key=/leader
+etcd.leader.key=/leader
+service.registry.logging.aspectJ.enabled=true
+service.registry.logging.aspectJ.timing.enabled=true

server/pom.xml

@@ -96,6 +96,12 @@
             <version>${testcontainers-redis.version}</version>
             <scope>test</scope>
         </dependency>
+        <dependency>
+            <groupId>com.michael</groupId>
+            <artifactId>spring-utils</artifactId>
+            <version>1.0.0</version>
+            <scope>compile</scope>
+        </dependency>
     </dependencies>
     <build>
         <plugins>

server/src/main/java/com/michael/container/config/AspectConfiguration.java

@@ -0,0 +1,19 @@
+package com.michael.container.config;
+
+import com.michael.spring.utils.logger.handlers.ExecutionTimeAspectHandler;
+import org.springframework.boot.autoconfigure.condition.ConditionalOnProperty;
+import org.springframework.context.annotation.Bean;
+import org.springframework.context.annotation.Configuration;
+
+@Configuration
+@ConditionalOnProperty(value = "service.registry.logging.aspectJ.enabled", havingValue = "true")
+public class AspectConfiguration {
+
+  @Bean
+  @ConditionalOnProperty(
+      value = "service.registry.logging.aspectJ.timing.enabled",
+      havingValue = "true")
+  public ExecutionTimeAspectHandler executionTimeAspectHandler() {
+    return new ExecutionTimeAspectHandler();
+  }
+}

server/src/main/java/com/michael/container/distributed/election/service/EtcdElectionProcess.java

@@ -6,6 +6,7 @@
 import com.michael.container.distributed.election.model.LockResult;
 import com.michael.container.distributed.election.observer.LeaseRenewalStreamObserver;
 import com.michael.container.distributed.election.state.ElectionState;
+import com.michael.spring.utils.logger.annotations.ExecutionTime;
 import io.etcd.jetcd.ByteSequence;
 import io.etcd.jetcd.Client;
 import io.etcd.jetcd.options.WatchOption;
@@ -47,6 +48,7 @@ public EtcdElectionProcess(
    * will also trigger various cleanup actions of the election state.
    */
   @Override
+  @ExecutionTime
   public void releaseLeadership() {
     try {
       if (electionState.getRole() == Role.LEADER) {
@@ -67,6 +69,7 @@ public void releaseLeadership() {
    * 5) Listen for the leader key's deletion, and if deleted, start a new election process.
    */
   @Override
+  @ExecutionTime
   public void startLeaderElection() {
     boolean acquiredLeadership = false;
     try {

server/src/main/java/com/michael/container/health/client/HealthCheckClient.java

@@ -1,6 +1,7 @@
 package com.michael.container.health.client;
 
 import com.michael.container.health.exception.HealthCheckInvalidException;
+import com.michael.spring.utils.logger.annotations.ExecutionTime;
 import jakarta.annotation.Nonnull;
 import java.time.Duration;
 import org.springframework.http.client.SimpleClientHttpRequestFactory;
@@ -27,6 +28,7 @@ public HealthCheckClient(RestClient.Builder restClientBuilder) {
    *
    * @param url the URL of the health check endpoint
    */
+  @ExecutionTime
   public void checkHealth(@Nonnull String url) {
     try {
       restClient.get().uri(url).retrieve().toBodilessEntity();

server/src/main/java/com/michael/container/health/routines/HealthCheckRoutine.java

@@ -11,6 +11,7 @@
 import com.michael.container.registry.cache.entity.BaseInstance;
 import com.michael.container.registry.cache.entity.HealthQueueEntity;
 import com.michael.container.registry.cache.repositories.ApplicationRepository;
+import com.michael.spring.utils.logger.annotations.ExecutionTime;
 import jakarta.annotation.Nullable;
 import java.util.List;
 import java.util.Objects;
@@ -52,6 +53,7 @@ public HealthCheckRoutine(
   @Scheduled(fixedRate = 10000L)
   @SkipIfFollower
   @SkipIfAutomationEnvironment
+  @ExecutionTime
   public void populateHealthCheckQueue() {
     List<ApplicationEntity> applicationEntities =
         Lists.newArrayList(applicationRepository.findAll());

server/src/main/java/com/michael/container/heartbeat/controller/HeartbeatController.java

@@ -3,6 +3,7 @@
 import com.michael.container.heartbeat.model.HeartbeatRequest;
 import com.michael.container.heartbeat.model.HeartbeatResponse;
 import com.michael.container.heartbeat.service.HeartbeatService;
+import com.michael.spring.utils.logger.annotations.ExecutionTime;
 import io.swagger.v3.oas.annotations.Operation;
 import jakarta.validation.Valid;
 import org.springframework.web.bind.annotation.PostMapping;
@@ -25,6 +26,7 @@ public HeartbeatController(HeartbeatService heartbeatService) {
           "Used for clients to perform heartbeats. This will re-register the TTL of the record."
               + " If TTL has expired, or no record found, "
               + "it will return RE_REGISTER, in which the client is expected to re-register.")
+  @ExecutionTime
   public HeartbeatResponse heartbeat(@RequestBody @Valid HeartbeatRequest heartbeatRequest) {
     return heartbeatService.heartbeat(heartbeatRequest);
   }

server/src/main/java/com/michael/container/notifications/client/NotificationClient.java

@@ -2,6 +2,7 @@
 
 import com.michael.container.notifications.exception.NotificationException;
 import com.michael.container.notifications.model.ServiceNotificationRequest;
+import com.michael.spring.utils.logger.annotations.ExecutionTime;
 import jakarta.annotation.Nonnull;
 import java.time.Duration;
 import org.springframework.http.MediaType;
@@ -33,6 +34,7 @@ public NotificationClient(RestClient.Builder restClientBuilder) {
    * @param url the URL to which the service notification should be sent
    * @param serviceNotificationRequest the {@link ServiceNotificationRequest} containing the details of the notification
    */
+  @ExecutionTime
   public void sendNotification(
       @Nonnull String url, @Nonnull ServiceNotificationRequest serviceNotificationRequest) {
     try {

server/src/main/java/com/michael/container/notifications/service/RegisterNotificationService.java

@@ -9,6 +9,7 @@
 import com.michael.container.registry.cache.crud.CrudRegistry;
 import com.michael.container.registry.cache.entity.PendingServiceNotificationEntity;
 import com.michael.container.registry.model.RegisterServiceResponse;
+import com.michael.spring.utils.logger.annotations.ExecutionTime;
 import jakarta.annotation.Nonnull;
 import java.util.Set;
 import org.slf4j.Logger;
@@ -63,6 +64,7 @@ public void notify(@Nonnull ServiceNotificationRequest serviceNotificationReques
   @Scheduled(fixedRate = 4000L)
   @SkipIfFollower
   @SkipIfAutomationEnvironment
+  @ExecutionTime
   public void processPendingNotifications() {
     pendingServiceNotificationQueueRepository.dequeue().parallelStream()
         .forEach(

server/src/main/java/com/michael/container/registry/controller/ServiceRegistryController.java

@@ -5,6 +5,7 @@
 import com.michael.container.registry.model.RemoveServiceRequest;
 import com.michael.container.registry.model.UpdateStatusRequest;
 import com.michael.container.registry.service.ServiceRegistryService;
+import com.michael.spring.utils.logger.annotations.ExecutionTime;
 import io.swagger.v3.oas.annotations.Operation;
 import jakarta.validation.Valid;
 import java.util.Map;
@@ -34,13 +35,15 @@ public ServiceRegistryController(ServiceRegistryService registryService) {
       summary =
           "Register a service. If the service already exists matching down "
               + "to the unique identifier (application-name + url + port + version), it will update the TTL.")
+  @ExecutionTime
   public void registerService(@RequestBody @Valid RegisterServiceRequest registerServiceRequest) {
     registryService.registerService(registerServiceRequest);
   }
 
   @GetMapping
   @Operation(
       summary = "Fetches all services, including: expired and not-expired registered services.")
+  @ExecutionTime
   public Map<String, Set<RegisterServiceResponse>> retrieveAllServices() {
     return registryService.fetchAll();
   }
@@ -50,6 +53,7 @@ public Map<String, Set<RegisterServiceResponse>> retrieveAllServices() {
   @Operation(
       summary =
           "Deregister a service. Upon deregister, all dependent services will receive a DE_REGISTER event.")
+  @ExecutionTime
   public void deregisterService(@RequestBody @Valid RemoveServiceRequest deregisterRequest) {
     registryService.removeService(deregisterRequest);
   }
@@ -59,6 +63,7 @@ public void deregisterService(@RequestBody @Valid RemoveServiceRequest deregiste
   @Operation(
       summary =
           "Updates the status of a service. All dependent services will become aware of this transition.")
+  @ExecutionTime
   public void updateStatusOnService(@RequestBody @Valid UpdateStatusRequest updateStatusRequest) {
     registryService.updateStatusOnService(updateStatusRequest, true);
   }

spring-utils/pom.xml

@@ -0,0 +1,39 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<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 http://maven.apache.org/xsd/maven-4.0.0.xsd">
+    <modelVersion>4.0.0</modelVersion>
+    <parent>
+        <groupId>com.michael</groupId>
+        <artifactId>service-container-parent</artifactId>
+        <version>1.0.0</version>
+    </parent>
+
+    <artifactId>spring-utils</artifactId>
+
+    <properties>
+        <maven.compiler.source>23</maven.compiler.source>
+        <maven.compiler.target>23</maven.compiler.target>
+        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
+    </properties>
+
+    <dependencyManagement>
+        <dependencies>
+            <dependency>
+                <groupId>com.michael</groupId>
+                <artifactId>service-container-server-bom</artifactId>
+                <version>${project.version}</version>
+                <type>pom</type>
+                <scope>import</scope>
+            </dependency>
+        </dependencies>
+    </dependencyManagement>
+
+    <dependencies>
+        <dependency>
+            <groupId>org.springframework.boot</groupId>
+            <artifactId>spring-boot-starter-aop</artifactId>
+        </dependency>
+    </dependencies>
+
+</project>

spring-utils/src/main/java/com/michael/spring/utils/logger/annotations/ExecutionTime.java

@@ -0,0 +1,12 @@
+package com.michael.spring.utils.logger.annotations;
+
+import java.lang.annotation.ElementType;
+import java.lang.annotation.Retention;
+import java.lang.annotation.RetentionPolicy;
+import java.lang.annotation.Target;
+
+@Target(ElementType.METHOD)
+@Retention(RetentionPolicy.RUNTIME)
+public @interface ExecutionTime {
+  double chance() default 1.0;
+}

spring-utils/src/main/java/com/michael/spring/utils/logger/handlers/ExecutionTimeAspectHandler.java

@@ -0,0 +1,46 @@
+package com.michael.spring.utils.logger.handlers;
+
+import com.michael.spring.utils.logger.annotations.ExecutionTime;
+import java.lang.reflect.Method;
+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.aspectj.lang.reflect.MethodSignature;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+@Aspect
+public class ExecutionTimeAspectHandler {
+  private static final long ONE_MILLION = 1_000_000L;
+  private static final Logger logger = LoggerFactory.getLogger(ExecutionTimeAspectHandler.class);
+  private static final String LOG_MESSAGE = "{}.{} time {} ms";
+
+  @Pointcut("@annotation(com.michael.spring.utils.logger.annotations.ExecutionTime)")
+  public void pointCutOnExecutionTimeAnnotation() {}
+
+  @Around("pointCutOnExecutionTimeAnnotation()")
+  public Object around(ProceedingJoinPoint joinPoint) throws Throwable {
+    MethodSignature signature = (MethodSignature) joinPoint.getSignature();
+    ExecutionTime executionTime = signature.getMethod().getAnnotation(ExecutionTime.class);
+    Method method = signature.getMethod();
+    String methodName = method.getName();
+    String className = joinPoint.getTarget().getClass().getSimpleName();
+
+    double clampedChance = Math.clamp(executionTime.chance(), 0.0, 1.0);
+
+    if (clampedChance < Math.random()) {
+      return joinPoint.proceed();
+    }
+
+    long start = System.nanoTime();
+
+    try {
+      return joinPoint.proceed();
+    } finally {
+      long end = System.nanoTime();
+      long inMilliseconds = (end - start) / ONE_MILLION;
+      logger.info(LOG_MESSAGE, className, methodName, inMilliseconds);
+    }
+  }
+}