(felix-dev) branch master updated: FELIX-6663 add logging when the HC executions exceeds the timeout

[ghenzler]

This is an automated email from the ASF dual-hosted git repository.

ghenzler pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/felix-dev.git


The following commit(s) were added to refs/heads/master by this push:
     new 5b9162d13f FELIX-6663 add logging when the HC executions exceeds the 
timeout
     new fc6f4c171d Merge pull request #239 from joerghoh/FELIX-6663-log-timing
5b9162d13f is described below

commit 5b9162d13ffa750d86a240d4c9b41645d511c72c
Author: Joerg Hoh <j...@adobe.com>
AuthorDate: Tue Oct 24 10:38:28 2023 +0200

    FELIX-6663 add logging when the HC executions exceeds the timeout
---
 .../impl/executor/HealthCheckExecutorImpl.java     | 39 +++++++++++++++++-----
 1 file changed, 30 insertions(+), 9 deletions(-)

diff --git 
a/healthcheck/core/src/main/java/org/apache/felix/hc/core/impl/executor/HealthCheckExecutorImpl.java
 
b/healthcheck/core/src/main/java/org/apache/felix/hc/core/impl/executor/HealthCheckExecutorImpl.java
index 9702626742..0f7508af13 100644
--- 
a/healthcheck/core/src/main/java/org/apache/felix/hc/core/impl/executor/HealthCheckExecutorImpl.java
+++ 
b/healthcheck/core/src/main/java/org/apache/felix/hc/core/impl/executor/HealthCheckExecutorImpl.java
@@ -203,16 +203,17 @@ public class HealthCheckExecutorImpl implements 
ExtendedHealthCheckExecutor, Ser
     @Override
     public List<HealthCheckExecutionResult> execute(final 
ServiceReference<HealthCheck>[] healthCheckReferences,
             HealthCheckExecutionOptions options) {
+        
+        long effectiveTimeout = getEffectiveTimeout(options);
         final long startTime = System.currentTimeMillis();
 
-        final List<HealthCheckExecutionResult> results = new 
ArrayList<HealthCheckExecutionResult>();
+        final List<HealthCheckExecutionResult> results = new ArrayList<>();
         final List<HealthCheckMetadata> healthCheckDescriptors = 
getHealthCheckMetadata(healthCheckReferences);
 
+        final long intermediateTiming = System.currentTimeMillis();
+        
         createResultsForDescriptors(healthCheckDescriptors, results, options);
-
-        if (logger.isDebugEnabled()) {
-            logger.debug("Time consumed for all checks: {}", 
msHumanReadable(System.currentTimeMillis() - startTime));
-        }
+        
 
         // sort result
         Collections.sort(results, new Comparator<HealthCheckExecutionResult>() 
{
@@ -224,6 +225,20 @@ public class HealthCheckExecutorImpl implements 
ExtendedHealthCheckExecutor, Ser
             }
 
         });
+
+        final long completionTime = System.currentTimeMillis();
+
+        if (logger.isDebugEnabled()) {
+            logger.debug("Time consumed for all checks: {}", 
msHumanReadable(completionTime - startTime));
+        }
+
+        // the completion of this request exceeds the provided timeout 
configuration, we should warn about it
+        if (completionTime - startTime > effectiveTimeout) {
+            logger.warn("execution of healthchecks exceeded the timeout value 
of {}ms. "
+                    + "(Creation of descriptors={}ms, execution of the 
checks={}ms, total={}ms)", effectiveTimeout,
+                    intermediateTiming-startTime, completionTime - 
intermediateTiming, completionTime - startTime);
+        }
+
         return results;
     }
 
@@ -368,10 +383,7 @@ public class HealthCheckExecutorImpl implements 
ExtendedHealthCheckExecutor, Ser
         final long callExcutionStartTime = System.currentTimeMillis();
         boolean allFuturesDone;
 
-        long effectiveTimeout = this.timeoutInMs;
-        if (options != null && options.getOverrideGlobalTimeout() > 0) {
-            effectiveTimeout = options.getOverrideGlobalTimeout();
-        }
+        long effectiveTimeout = getEffectiveTimeout(options);
 
         if (futuresForResultOfThisCall.isEmpty()) {
             return; // nothing to wait for (usually because of cached results)
@@ -480,4 +492,13 @@ public class HealthCheckExecutorImpl implements 
ExtendedHealthCheckExecutor, Ser
         this.longRunningFutureThresholdForRedMs = 
longRunningFutureThresholdForRedMs;
     }
 
+    // Calculates the effective timeout based on global configuration and the 
provided options
+    private long getEffectiveTimeout(HealthCheckExecutionOptions options) {
+        long effectiveTimeout = this.timeoutInMs;
+        if (options != null && options.getOverrideGlobalTimeout() > 0) {
+            effectiveTimeout = options.getOverrideGlobalTimeout();
+        }
+        return effectiveTimeout;
+    }
+    
 }