diff --git a/changelog.txt b/changelog.txt index c04eafff4..ff9811d73 100644 --- a/changelog.txt +++ b/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 diff --git a/src/main/groovy/io/seqera/util/trace/TraceElapsedTime.groovy b/src/main/groovy/io/seqera/util/trace/TraceElapsedTime.groovy new file mode 100644 index 000000000..5a08b4cf5 --- /dev/null +++ b/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 . + */ + +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 + */ +@Documented +@Retention(RUNTIME) +@Target([TYPE, METHOD]) +@Around +@interface TraceElapsedTime { + String thresholdMillis() default '0' +} diff --git a/src/main/groovy/io/seqera/util/trace/TraceElapsedTimeInterceptor.groovy b/src/main/groovy/io/seqera/util/trace/TraceElapsedTimeInterceptor.groovy new file mode 100644 index 000000000..cfb8218a6 --- /dev/null +++ b/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 . + */ + +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 + */ +@CompileStatic +@Slf4j +@Singleton +@InterceptorBean(TraceElapsedTime) +class TraceElapsedTimeInterceptor implements MethodInterceptor { + + @Override + Object intercept(MethodInvocationContext 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 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 + } +} diff --git a/src/main/groovy/io/seqera/wave/core/RegistryProxyService.groovy b/src/main/groovy/io/seqera/wave/core/RegistryProxyService.groovy index 8b2e39249..eadbdc09e 100644 --- a/src/main/groovy/io/seqera/wave/core/RegistryProxyService.groovy +++ b/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> headers) { + @TraceElapsedTime(thresholdMillis = '${wave.trace.proxy-service.threshold:750}') + protected DelegateResponse handleRequest0(RoutePath route, Map> headers) { ProxyClient proxyClient = client(route) final resp1 = proxyClient.getStream(route.path, headers, false) final redirect = resp1.headers().firstValue('Location').orElse(null) diff --git a/src/main/groovy/io/seqera/wave/filter/TraceSlowEndpointPublisher.java b/src/main/groovy/io/seqera/wave/filter/TraceSlowEndpointPublisher.java index affb671f7..7909c9db5 100644 --- a/src/main/groovy/io/seqera/wave/filter/TraceSlowEndpointPublisher.java +++ b/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 diff --git a/src/main/groovy/io/seqera/wave/service/persistence/impl/LocalPersistenceService.groovy b/src/main/groovy/io/seqera/wave/service/persistence/impl/LocalPersistenceService.groovy index 002f60752..a3848a6eb 100644 --- a/src/main/groovy/io/seqera/wave/service/persistence/impl/LocalPersistenceService.groovy +++ b/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 buildStore = new HashMap<>() diff --git a/src/main/groovy/io/seqera/wave/service/persistence/impl/SurrealPersistenceService.groovy b/src/main/groovy/io/seqera/wave/service/persistence/impl/SurrealPersistenceService.groovy index 829c6a384..adf51d82c 100644 --- a/src/main/groovy/io/seqera/wave/service/persistence/impl/SurrealPersistenceService.groovy +++ b/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 diff --git a/src/main/resources/application-dev.yml b/src/main/resources/application-dev.yml index 57b48bf8f..5f12ef2aa 100644 --- a/src/main/resources/application-dev.yml +++ b/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: