Add trace execution elapsed time logic (#497)

Signed-off-by: Paolo Di Tommaso <paolo.ditommaso@gmail.com>
Co-authored-by: Munish Chouhan <munish.chouhan@seqera.io>

changelog.txt

@@ -7,8 +7,8 @@
 - Fix JWT token refresh [52a5ebd7]
 
 1.16.1 - 20 Dec 2024
-- Add tiered chache for HTTP proxied responses (#778) [00b6add7]
-- Improve boostrap info [d5c086da]
+- Add tiered cache for HTTP proxied responses (#778) [00b6add7]
+- Improve bootstrap info [d5c086da]
 - Remove jitpack [67f91c8b]
 
 1.16.0 - 17 Dec 2024 

src/main/groovy/io/seqera/util/trace/TraceElapsedTime.groovy

@@ -0,0 +1,41 @@
+/*
+ *  Wave, containers provisioning service
+ *  Copyright (c) 2023-2024, Seqera Labs
+ *
+ *  This program is free software: you can redistribute it and/or modify
+ *  it under the terms of the GNU Affero General Public License as published by
+ *  the Free Software Foundation, either version 3 of the License, or
+ *  (at your option) any later version.
+ *
+ *  This program is distributed in the hope that it will be useful,
+ *  but WITHOUT ANY WARRANTY; without even the implied warranty of
+ *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ *  GNU Affero General Public License for more details.
+ *
+ *  You should have received a copy of the GNU Affero General Public License
+ *  along with this program.  If not, see <https://www.gnu.org/licenses/>.
+ */
+
+package io.seqera.util.trace
+
+import java.lang.annotation.Documented
+import java.lang.annotation.Retention
+import java.lang.annotation.Target
+
+import io.micronaut.aop.Around
+import static java.lang.annotation.ElementType.METHOD
+import static java.lang.annotation.ElementType.TYPE
+import static java.lang.annotation.RetentionPolicy.RUNTIME
+/**
+ * When applied to a method or a class the elapsed time to carry out the method execution
+ * is reported in the application log file
+ *
+ * @author Paolo Di Tommaso <paolo.ditommaso@gmail.com>
+ */
+@Documented
+@Retention(RUNTIME)
+@Target([TYPE, METHOD])
+@Around
+@interface TraceElapsedTime {
+    String thresholdMillis() default '0'
+}

src/main/groovy/io/seqera/util/trace/TraceElapsedTimeInterceptor.groovy

@@ -0,0 +1,74 @@
+/*
+ *  Wave, containers provisioning service
+ *  Copyright (c) 2023-2024, Seqera Labs
+ *
+ *  This program is free software: you can redistribute it and/or modify
+ *  it under the terms of the GNU Affero General Public License as published by
+ *  the Free Software Foundation, either version 3 of the License, or
+ *  (at your option) any later version.
+ *
+ *  This program is distributed in the hope that it will be useful,
+ *  but WITHOUT ANY WARRANTY; without even the implied warranty of
+ *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ *  GNU Affero General Public License for more details.
+ *
+ *  You should have received a copy of the GNU Affero General Public License
+ *  along with this program.  If not, see <https://www.gnu.org/licenses/>.
+ */
+
+package io.seqera.util.trace
+
+import java.time.Duration
+
+import groovy.transform.CompileStatic
+import groovy.util.logging.Slf4j
+import io.micronaut.aop.InterceptorBean
+import io.micronaut.aop.MethodInterceptor
+import io.micronaut.aop.MethodInvocationContext
+import jakarta.inject.Singleton
+/**
+ * Implements an method interceptor that logs the elapsed time to carry out the execution
+ * of method invocation.
+ *
+ * This interceptor is applied to classes or methods marked in the {@link TraceElapsedTime} annotation
+ *
+ * @author Paolo Di Tommaso <paolo.ditommaso@gmail.com>
+ */
+@CompileStatic
+@Slf4j
+@Singleton
+@InterceptorBean(TraceElapsedTime)
+class TraceElapsedTimeInterceptor implements MethodInterceptor<Object,Object> {
+
+    @Override
+    Object intercept(MethodInvocationContext<Object, Object> context) {
+        // get the threshold value from the TraceElapsedTime annotation
+        final annot = context.getAnnotation(TraceElapsedTime)
+        final threshold = annot.intValue('thresholdMillis').orElse(0)
+
+        // apply it
+        Object result=null
+        final begin = System.currentTimeMillis()
+        try {
+            return result = context.proceed()
+        }
+        finally {
+            final delta = System.currentTimeMillis() - begin
+            if( delta>=threshold ) {
+                log.warn(msg(delta,context,result))
+            }
+        }
+    }
+
+    static private String msg(long delta,MethodInvocationContext<Object, Object> context, Object result) {
+        final method = context.getDeclaringType().getSimpleName() + '.' + context.getMethodName()
+        def msg = "Slow method detected - elapsed time: ${Duration.ofMillis(delta)}"
+        msg += "\n - name     : ${method}"
+        for( Map.Entry entry : context.getParameterValueMap() ) {
+            msg += "\n - parameter: ${entry.key}=${entry.value}"
+        }
+        if( !context.getReturnType().isVoid() )
+            msg += "\n - result   : ${result}"
+        return msg
+    }
+}

src/main/groovy/io/seqera/wave/core/RegistryProxyService.groovy

@@ -47,6 +47,7 @@ import io.seqera.wave.service.persistence.PersistenceService
 import io.seqera.wave.storage.DigestStore
 import io.seqera.wave.storage.Storage
 import io.seqera.wave.tower.PlatformId
+import io.seqera.util.trace.TraceElapsedTime
 import io.seqera.wave.util.RegHelper
 import io.seqera.wave.util.Retryable
 import jakarta.inject.Inject
@@ -217,7 +218,8 @@ class RegistryProxyService {
                 })
     }
 
-    private DelegateResponse handleRequest0(RoutePath route, Map<String,List<String>> headers) {
+    @TraceElapsedTime(thresholdMillis = '${wave.trace.proxy-service.threshold:750}')
+    protected DelegateResponse handleRequest0(RoutePath route, Map<String,List<String>> headers) {
         ProxyClient proxyClient = client(route)
         final resp1 = proxyClient.getStream(route.path, headers, false)
         final redirect = resp1.headers().firstValue('Location').orElse(null)

src/main/groovy/io/seqera/wave/filter/TraceSlowEndpointPublisher.java

@@ -106,7 +106,7 @@ public void onComplete() {
     protected void traceResponse(HttpResponse<?> response) {
         final long delta = System.currentTimeMillis()-begin;
         if( delta>=duration.toMillis() )
-            log.warn("Slow request detected - elapsed time {}\n{}", Duration.ofMillis(delta), dumpRequest(request,response));
+            log.warn("Slow request detected - elapsed time: {}\n{}", Duration.ofMillis(delta), dumpRequest(request,response));
     }
 
     @CompileStatic

src/main/groovy/io/seqera/wave/service/persistence/impl/LocalPersistenceService.groovy

@@ -25,6 +25,7 @@ import io.seqera.wave.service.persistence.PersistenceService
 import io.seqera.wave.service.persistence.WaveBuildRecord
 import io.seqera.wave.service.persistence.WaveContainerRecord
 import io.seqera.wave.service.persistence.WaveScanRecord
+import io.seqera.util.trace.TraceElapsedTime
 import jakarta.inject.Singleton
 /**
  * Basic persistence for dev purpose
@@ -33,6 +34,7 @@ import jakarta.inject.Singleton
  */
 @Singleton
 @CompileStatic
+@TraceElapsedTime(thresholdMillis = '${wave.trace.local-persistence.threshold:100}')
 class LocalPersistenceService implements PersistenceService {
 
     private Map<String,WaveBuildRecord> buildStore = new HashMap<>()

src/main/groovy/io/seqera/wave/service/persistence/impl/SurrealPersistenceService.groovy

@@ -37,6 +37,7 @@ import io.seqera.wave.service.persistence.WaveBuildRecord
 import io.seqera.wave.service.persistence.WaveContainerRecord
 import io.seqera.wave.service.persistence.WaveScanRecord
 import io.seqera.wave.service.scan.ScanVulnerability
+import io.seqera.util.trace.TraceElapsedTime
 import io.seqera.wave.util.JacksonHelper
 import jakarta.inject.Inject
 import jakarta.inject.Singleton
@@ -51,6 +52,7 @@ import jakarta.inject.Singleton
 @Slf4j
 @Singleton
 @CompileStatic
+@TraceElapsedTime(thresholdMillis = '${wave.trace.surreal-persistence.threshold:200}')
 class SurrealPersistenceService implements PersistenceService {
 
     @Inject

src/main/resources/application-dev.yml

@@ -20,6 +20,13 @@ wave:
     succeeded: '10s'
     failed: '45s'
     strategy: 'onsuccess'
+  trace:
+    local-persistence:
+      threshold: 100
+    surreal-persistence:
+      threshold: 100
+    proxy-service:
+      threshold: 100
 ---
 endpoints:
   metrics: