diff --git a/pom.xml b/pom.xml index 6817d9f..5826395 100644 --- a/pom.xml +++ b/pom.xml @@ -12,6 +12,7 @@ server-bom server registry-server-runner + spring-utils diff --git a/registry-server-runner/src/main/resources/application.properties b/registry-server-runner/src/main/resources/application.properties index 0200aa8..4a0f580 100644 --- a/registry-server-runner/src/main/resources/application.properties +++ b/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 \ No newline at end of file +etcd.leader.key=/leader +service.registry.logging.aspectJ.enabled=true +service.registry.logging.aspectJ.timing.enabled=true \ No newline at end of file diff --git a/server/pom.xml b/server/pom.xml index 460f083..57d96dd 100644 --- a/server/pom.xml +++ b/server/pom.xml @@ -96,6 +96,12 @@ ${testcontainers-redis.version} test + + com.michael + spring-utils + 1.0.0 + compile + diff --git a/server/src/main/java/com/michael/container/config/AspectConfiguration.java b/server/src/main/java/com/michael/container/config/AspectConfiguration.java new file mode 100644 index 0000000..ab7bbb3 --- /dev/null +++ b/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(); + } +} diff --git a/server/src/main/java/com/michael/container/distributed/election/service/EtcdElectionProcess.java b/server/src/main/java/com/michael/container/distributed/election/service/EtcdElectionProcess.java index 1a878eb..21e0072 100644 --- a/server/src/main/java/com/michael/container/distributed/election/service/EtcdElectionProcess.java +++ b/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 { diff --git a/server/src/main/java/com/michael/container/health/client/HealthCheckClient.java b/server/src/main/java/com/michael/container/health/client/HealthCheckClient.java index 7b4e5d8..5df0110 100644 --- a/server/src/main/java/com/michael/container/health/client/HealthCheckClient.java +++ b/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(); diff --git a/server/src/main/java/com/michael/container/health/routines/HealthCheckRoutine.java b/server/src/main/java/com/michael/container/health/routines/HealthCheckRoutine.java index 81e1a2c..f36ed03 100644 --- a/server/src/main/java/com/michael/container/health/routines/HealthCheckRoutine.java +++ b/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 applicationEntities = Lists.newArrayList(applicationRepository.findAll()); diff --git a/server/src/main/java/com/michael/container/heartbeat/controller/HeartbeatController.java b/server/src/main/java/com/michael/container/heartbeat/controller/HeartbeatController.java index 79c0cec..12562b5 100644 --- a/server/src/main/java/com/michael/container/heartbeat/controller/HeartbeatController.java +++ b/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); } diff --git a/server/src/main/java/com/michael/container/notifications/client/NotificationClient.java b/server/src/main/java/com/michael/container/notifications/client/NotificationClient.java index b7b8577..9b44dca 100644 --- a/server/src/main/java/com/michael/container/notifications/client/NotificationClient.java +++ b/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 { diff --git a/server/src/main/java/com/michael/container/notifications/service/RegisterNotificationService.java b/server/src/main/java/com/michael/container/notifications/service/RegisterNotificationService.java index fb511e3..e8fdab4 100644 --- a/server/src/main/java/com/michael/container/notifications/service/RegisterNotificationService.java +++ b/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( diff --git a/server/src/main/java/com/michael/container/registry/controller/ServiceRegistryController.java b/server/src/main/java/com/michael/container/registry/controller/ServiceRegistryController.java index d327a81..19f4db0 100644 --- a/server/src/main/java/com/michael/container/registry/controller/ServiceRegistryController.java +++ b/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,6 +35,7 @@ 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); } @@ -41,6 +43,7 @@ public void registerService(@RequestBody @Valid RegisterServiceRequest registerS @GetMapping @Operation( summary = "Fetches all services, including: expired and not-expired registered services.") + @ExecutionTime public Map> retrieveAllServices() { return registryService.fetchAll(); } @@ -50,6 +53,7 @@ public Map> 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); } diff --git a/spring-utils/pom.xml b/spring-utils/pom.xml new file mode 100644 index 0000000..a51098c --- /dev/null +++ b/spring-utils/pom.xml @@ -0,0 +1,39 @@ + + + 4.0.0 + + com.michael + service-container-parent + 1.0.0 + + + spring-utils + + + 23 + 23 + UTF-8 + + + + + + com.michael + service-container-server-bom + ${project.version} + pom + import + + + + + + + org.springframework.boot + spring-boot-starter-aop + + + + \ No newline at end of file diff --git a/spring-utils/src/main/java/com/michael/spring/utils/logger/annotations/ExecutionTime.java b/spring-utils/src/main/java/com/michael/spring/utils/logger/annotations/ExecutionTime.java new file mode 100644 index 0000000..bb537a3 --- /dev/null +++ b/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; +} diff --git a/spring-utils/src/main/java/com/michael/spring/utils/logger/handlers/ExecutionTimeAspectHandler.java b/spring-utils/src/main/java/com/michael/spring/utils/logger/handlers/ExecutionTimeAspectHandler.java new file mode 100644 index 0000000..4ca53f5 --- /dev/null +++ b/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); + } + } +}