ARTEMIS-2157 Extra information on CriticalAnalyzer and its components
Project: http://git-wip-us.apache.org/repos/asf/activemq-artemis/repo Commit: http://git-wip-us.apache.org/repos/asf/activemq-artemis/commit/8f9b75cc Tree: http://git-wip-us.apache.org/repos/asf/activemq-artemis/tree/8f9b75cc Diff: http://git-wip-us.apache.org/repos/asf/activemq-artemis/diff/8f9b75cc Branch: refs/heads/master Commit: 8f9b75cc5dc4c2c2a77635ebf2c71cb10504f02d Parents: 2489020 Author: Clebert Suconic <clebertsuco...@apache.org> Authored: Tue Oct 30 16:10:35 2018 -0400 Committer: Clebert Suconic <clebertsuco...@apache.org> Committed: Wed Oct 31 11:41:55 2018 -0400 ---------------------------------------------------------------------- .../utils/critical/CriticalAnalyzer.java | 2 + .../utils/critical/CriticalAnalyzerImpl.java | 5 ++ .../utils/critical/CriticalComponent.java | 3 + .../utils/critical/CriticalComponentImpl.java | 3 +- .../artemis/utils/critical/CriticalMeasure.java | 62 ++++++++++++++++++-- .../utils/critical/EmptyCriticalAnalyzer.java | 5 ++ .../utils/critical/CriticalMeasureTest.java | 59 +++++++++++++++++++ 7 files changed, 132 insertions(+), 7 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/activemq-artemis/blob/8f9b75cc/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalAnalyzer.java ---------------------------------------------------------------------- diff --git a/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalAnalyzer.java b/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalAnalyzer.java index 9bfa3e6..b593dc2 100644 --- a/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalAnalyzer.java +++ b/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(); http://git-wip-us.apache.org/repos/asf/activemq-artemis/blob/8f9b75cc/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalAnalyzerImpl.java ---------------------------------------------------------------------- diff --git a/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalAnalyzerImpl.java b/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalAnalyzerImpl.java index b767649..b77479c 100644 --- a/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalAnalyzerImpl.java +++ b/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalAnalyzerImpl.java @@ -119,6 +119,11 @@ public class CriticalAnalyzerImpl implements CriticalAnalyzer { } @Override + public long getTimeoutNanoSeconds() { + return timeoutNanoSeconds; + } + + @Override public CriticalAnalyzer addAction(CriticalAction action) { this.actions.add(action); return this; http://git-wip-us.apache.org/repos/asf/activemq-artemis/blob/8f9b75cc/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalComponent.java ---------------------------------------------------------------------- diff --git a/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalComponent.java b/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalComponent.java index 367e9c5..ee64816 100644 --- a/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalComponent.java +++ b/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. http://git-wip-us.apache.org/repos/asf/activemq-artemis/blob/8f9b75cc/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalComponentImpl.java ---------------------------------------------------------------------- diff --git a/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalComponentImpl.java b/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalComponentImpl.java index 07d5a3f..826ed62 100644 --- a/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalComponentImpl.java +++ b/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; http://git-wip-us.apache.org/repos/asf/activemq-artemis/blob/8f9b75cc/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalMeasure.java ---------------------------------------------------------------------- diff --git a/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalMeasure.java b/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalMeasure.java index 5b78a4a..cc24c41 100644 --- a/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/CriticalMeasure.java +++ b/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"); - private static final AtomicLongFieldUpdater<CriticalMeasure> TIME_LEFT_UPDATER = AtomicLongFieldUpdater.newUpdater(CriticalMeasure.class, "timeLeft"); + static final AtomicLongFieldUpdater<CriticalMeasure> TIME_ENTER_UPDATER = AtomicLongFieldUpdater.newUpdater(CriticalMeasure.class, "timeEnter"); + 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(); - leaveCritical(); + long time = System.nanoTime(); + 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; } http://git-wip-us.apache.org/repos/asf/activemq-artemis/blob/8f9b75cc/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/EmptyCriticalAnalyzer.java ---------------------------------------------------------------------- diff --git a/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/EmptyCriticalAnalyzer.java b/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/EmptyCriticalAnalyzer.java index 516605e..936f06b 100644 --- a/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/EmptyCriticalAnalyzer.java +++ b/artemis-commons/src/main/java/org/apache/activemq/artemis/utils/critical/EmptyCriticalAnalyzer.java @@ -56,6 +56,11 @@ public class EmptyCriticalAnalyzer implements CriticalAnalyzer { } @Override + public long getTimeoutNanoSeconds() { + return 0; + } + + @Override public boolean isStarted() { return false; } http://git-wip-us.apache.org/repos/asf/activemq-artemis/blob/8f9b75cc/artemis-commons/src/test/java/org/apache/activemq/artemis/utils/critical/CriticalMeasureTest.java ---------------------------------------------------------------------- diff --git a/artemis-commons/src/test/java/org/apache/activemq/artemis/utils/critical/CriticalMeasureTest.java b/artemis-commons/src/test/java/org/apache/activemq/artemis/utils/critical/CriticalMeasureTest.java new file mode 100644 index 0000000..b75b092 --- /dev/null +++ b/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(); + } +}