ARTEMIS-2157 Extra information on CriticalAnalyzer and its components

artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalAnalyzer.java

@@ -43,6 +43,8 @@ public interface CriticalAnalyzer extends ActiveMQComponent {
 
    long getTimeout(TimeUnit unit);
 
+   long getTimeoutNanoSeconds();
+
    CriticalAnalyzer addAction(CriticalAction action);
 
    void check();

artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalAnalyzerImpl.java

@@ -118,6 +118,11 @@ public class CriticalAnalyzerImpl implements CriticalAnalyzer {
       return unit.convert(timeoutNanoSeconds, TimeUnit.NANOSECONDS);
    }
 
+   @Override
+   public long getTimeoutNanoSeconds() {
+      return timeoutNanoSeconds;
+   }
+
    @Override
    public CriticalAnalyzer addAction(CriticalAction action) {
       this.actions.add(action);

artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalComponent.java

@@ -27,6 +27,9 @@ package org.apache.activemq.artemis.utils.critical;
  */
 public interface CriticalComponent {
 
+   default CriticalAnalyzer getCriticalAnalyzer() {
+      return null;
+   }
    /**
     * please save the time you entered here.
     * Use volatile variables.

artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalComponentImpl.java

@@ -25,6 +25,7 @@ public class CriticalComponentImpl implements CriticalComponent {
    private final CriticalMeasure[] measures;
    private final CriticalAnalyzer analyzer;
 
+   @Override
    public CriticalAnalyzer getCriticalAnalyzer() {
       return analyzer;
    }
@@ -38,7 +39,7 @@ public class CriticalComponentImpl implements CriticalComponent {
       if (analyzer.isMeasuring()) {
          measures = new CriticalMeasure[numberOfPaths];
          for (int i = 0; i < numberOfPaths; i++) {
-            measures[i] = new CriticalMeasure();
+            measures[i] = new CriticalMeasure(this, i);
          }
       } else {
          measures = null;

artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalMeasure.java

@@ -19,37 +19,87 @@ package org.apache.activemq.artemis.utils.critical;
 
 import java.util.concurrent.atomic.AtomicLongFieldUpdater;
 
+import org.jboss.logging.Logger;
+
 public class CriticalMeasure {
 
+   private static final Logger logger = Logger.getLogger(CriticalMeasure.class);
+
+   // this is used on enterCritical, if the logger is in trace mode
+   private volatile Exception traceEnter;
+
    //uses updaters to avoid creates many AtomicLong instances
-   private static final AtomicLongFieldUpdater<CriticalMeasure> TIME_ENTER_UPDATER = AtomicLongFieldUpdater.newUpdater(CriticalMeasure.class, "timeEnter");
+   static final AtomicLongFieldUpdater<CriticalMeasure> TIME_ENTER_UPDATER = AtomicLongFieldUpdater.newUpdater(CriticalMeasure.class, "timeEnter");
-   private static final AtomicLongFieldUpdater<CriticalMeasure> TIME_LEFT_UPDATER = AtomicLongFieldUpdater.newUpdater(CriticalMeasure.class, "timeLeft");
+   static final AtomicLongFieldUpdater<CriticalMeasure> TIME_LEFT_UPDATER = AtomicLongFieldUpdater.newUpdater(CriticalMeasure.class, "timeLeft");
 
    private volatile long timeEnter;
    private volatile long timeLeft;
 
-   public CriticalMeasure() {
+   private final int id;
+   private final CriticalComponent component;
+
+   public CriticalMeasure(CriticalComponent component, int id) {
+      this.id = id;
+      this.component = component;
       //prefer this approach instead of using some fixed value because System::nanoTime could change sign
       //with long running processes
-      enterCritical();
+      long time = System.nanoTime();
-      leaveCritical();
+      TIME_LEFT_UPDATER.set(this, time);
+      TIME_ENTER_UPDATER.set(this, time);
    }
 
    public void enterCritical() {
       //prefer lazySet in order to avoid heavy-weight full barriers on x86
       TIME_ENTER_UPDATER.lazySet(this, System.nanoTime());
+
+      if (logger.isTraceEnabled()) {
+         traceEnter = new Exception("entered");
+      }
    }
 
    public void leaveCritical() {
+
+      if (logger.isTraceEnabled()) {
+
+         CriticalAnalyzer analyzer = component != null ? component.getCriticalAnalyzer() : null;
+         if (analyzer != null) {
+            long nanoTimeout = analyzer.getTimeoutNanoSeconds();
+            if (isExpired(nanoTimeout)) {
+               logger.trace("Path " + id + " on component " + getComponentName() + " is taking too long, leaving at", new Exception("entered"));
+               logger.trace("Path " + id + " on component " + getComponentName() + " is taking too long, entered at", traceEnter);
+            }
+         }
+         traceEnter = null;
+      }
+
       TIME_LEFT_UPDATER.lazySet(this, System.nanoTime());
    }
 
+   protected String getComponentName() {
+      if (component == null) {
+         return "null";
+      } else {
+         return component.getClass().getName();
+      }
+   }
+
    public boolean isExpired(long timeout) {
       final long timeLeft = TIME_LEFT_UPDATER.get(this);
       final long timeEnter = TIME_ENTER_UPDATER.get(this);
       //due to how System::nanoTime works is better to use differences to prevent numerical overflow while comparing
       if (timeLeft - timeEnter < 0) {
-         return System.nanoTime() - timeEnter > timeout;
+         boolean expired = System.nanoTime() - timeEnter > timeout;
+
+         if (expired) {
+
+            Exception thistraceEnter = this.traceEnter;
+            if (thistraceEnter != null) {
+               logger.warn("Component " + getComponentName() + " is expired on path " + id, thistraceEnter);
+            } else {
+               logger.warn("Component " + getComponentName() + " is expired on path " + id);
+            }
+         }
+         return expired;
       }
       return false;
    }

artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/EmptyCriticalAnalyzer.java

@@ -55,6 +55,11 @@ public class EmptyCriticalAnalyzer implements CriticalAnalyzer {
 
    }
 
+   @Override
+   public long getTimeoutNanoSeconds() {
+      return 0;
+   }
+
    @Override
    public boolean isStarted() {
       return false;

artemis-commons/src/test/java/org/apache/activemq/artemis/utils/critical/CriticalMeasureTest.java

@@ -0,0 +1,59 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache License, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.apache.activemq.artemis.utils.critical;
+
+import java.util.concurrent.TimeUnit;
+
+import org.junit.Assert;
+import org.junit.Test;
+
+public class CriticalMeasureTest {
+
+   @Test
+   public void testCriticalMeasure() throws Exception {
+      CriticalMeasure measure = new CriticalMeasure(null, 1);
+      long time = System.nanoTime();
+      CriticalMeasure.TIME_ENTER_UPDATER.set(measure, time - TimeUnit.MINUTES.toNanos(5));
+      CriticalMeasure.TIME_LEFT_UPDATER.set(measure, time);
+      Assert.assertFalse(measure.isExpired(TimeUnit.SECONDS.toNanos(30)));
+   }
+
+   @Test
+   public void testCriticalMeasureTakingLongButSucceeding() throws Exception {
+      CriticalAnalyzer analyzer = new CriticalAnalyzerImpl();
+      CriticalComponent component = new CriticalComponentImpl(analyzer, 5);
+      CriticalMeasure measure = new CriticalMeasure(component, 1);
+      long time = System.nanoTime();
+      CriticalMeasure.TIME_ENTER_UPDATER.set(measure, time - TimeUnit.MINUTES.toNanos(5));
+      measure.leaveCritical();
+      Assert.assertFalse(measure.isExpired(TimeUnit.SECONDS.toNanos(30)));
+   }
+
+   @Test
+   public void testCriticalFailure() throws Exception {
+      CriticalAnalyzer analyzer = new CriticalAnalyzerImpl();
+      CriticalComponent component = new CriticalComponentImpl(analyzer, 5);
+      CriticalMeasure measure = new CriticalMeasure(component, 1);
+      long time = System.nanoTime();
+      measure.enterCritical();
+      CriticalMeasure.TIME_ENTER_UPDATER.set(measure, time - TimeUnit.MINUTES.toNanos(5));
+      CriticalMeasure.TIME_LEFT_UPDATER.set(measure, time - TimeUnit.MINUTES.toNanos(10));
+      Assert.assertTrue(measure.isExpired(TimeUnit.SECONDS.toNanos(30)));
+      measure.leaveCritical();
+   }
+}