Author: catholicon
Date: Tue Jul 12 11:53:45 2016
New Revision: 1752282
URL: http://svn.apache.org/viewvc?rev=1752282&view=rev
Log:
OAK-4542: Implement startForInfo and add end() methods to provide info
threshold (backport r1752273 and r1752274 from trunk)
Added tests for existing functionality and more for new methods.
Added:
jackrabbit/oak/branches/1.4/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerIT.java
- copied, changed from r1752273,
jackrabbit/oak/trunk/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerIT.java
Modified:
jackrabbit/oak/branches/1.4/ (props changed)
jackrabbit/oak/branches/1.4/oak-core/src/main/java/org/apache/jackrabbit/oak/util/PerfLogger.java
jackrabbit/oak/branches/1.4/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerTest.java
Propchange: jackrabbit/oak/branches/1.4/
------------------------------------------------------------------------------
--- svn:mergeinfo (original)
+++ svn:mergeinfo Tue Jul 12 11:53:45 2016
@@ -1,3 +1,3 @@
/jackrabbit/oak/branches/1.0:1665962
-/jackrabbit/oak/trunk:1733615,1733875,1733913,1733929,1734230,1734254,1734279,1734941,1735052,1735405,1735484,1735549,1735564,1735588,1735622,1735638,1735919,1735983,1736176,1737309-1737310,1737334,1737349,1737998,1738004,1738775,1738795,1738833,1738950,1738957,1738963,1739894,1740116,1740625-1740626,1740971,1741032,1741339,1741343,1742520,1742888,1742916,1743097,1743172,1743343,1744265,1744959,1745038,1745197,1745368,1746086,1746117,1746342,1746345,1746696,1746981,1747341-1747342,1747492,1747512,1748505,1748553,1748722,1748870,1749275,1749350,1749464,1749475,1749645,1749662,1749815,1749872,1749875,1749899,1750076-1750077,1750287,1750457,1750465,1750495,1750626,1750809,1751410,1751478,1751755
+/jackrabbit/oak/trunk:1733615,1733875,1733913,1733929,1734230,1734254,1734279,1734941,1735052,1735405,1735484,1735549,1735564,1735588,1735622,1735638,1735919,1735983,1736176,1737309-1737310,1737334,1737349,1737998,1738004,1738775,1738795,1738833,1738950,1738957,1738963,1739894,1740116,1740625-1740626,1740971,1741032,1741339,1741343,1742520,1742888,1742916,1743097,1743172,1743343,1744265,1744959,1745038,1745197,1745368,1746086,1746117,1746342,1746345,1746696,1746981,1747341-1747342,1747492,1747512,1748505,1748553,1748722,1748870,1749275,1749350,1749464,1749475,1749645,1749662,1749815,1749872,1749875,1749899,1750076-1750077,1750287,1750457,1750465,1750495,1750626,1750809,1751410,1751478,1751755,1752273-1752274
/jackrabbit/trunk:1345480
Modified:
jackrabbit/oak/branches/1.4/oak-core/src/main/java/org/apache/jackrabbit/oak/util/PerfLogger.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/branches/1.4/oak-core/src/main/java/org/apache/jackrabbit/oak/util/PerfLogger.java?rev=1752282&r1=1752281&r2=1752282&view=diff
==============================================================================
---
jackrabbit/oak/branches/1.4/oak-core/src/main/java/org/apache/jackrabbit/oak/util/PerfLogger.java
(original)
+++
jackrabbit/oak/branches/1.4/oak-core/src/main/java/org/apache/jackrabbit/oak/util/PerfLogger.java
Tue Jul 12 11:53:45 2016
@@ -59,32 +59,57 @@ public final class PerfLogger {
}
/**
- * Returns quickly if log level is not DEBUG or TRACE - otherwise just
- * returns the current time in millis.
- *
- * @return the current time if level is DEBUG or TRACE, -1 otherwise
+ * Shortcut to {@code #start(null, false)}
*/
public final long start() {
- if (!delegate.isDebugEnabled()) {
- // if log level is not at least DEBUG, then return fast, no-op
+ if (canExitEarly()) {
+ return -1;
+ }
+ return start(null, false);
+ }
+
+ /**
+ * Shortcut to {@code start(null, true)}
+ */
+ public final long startForInfoLog() {
+ if (canExitEarly(true)) {
+ return -1;
+ }
+ return start(null, true);
+ }
+
+ /**
+ * Shortcut to {@code start(traceMsgOrNull, false)}
+ */
+ public final long start(String traceMsgOrNull) {
+ if (canExitEarly()) {
return -1;
}
- return start(null);
+ return start(traceMsgOrNull, false);
+ }
+
+ /**
+ * Shortcut to {@code start(traceMsgOrNull, true)}
+ */
+ public final long startForInfoLog(String traceMsgOrNull) {
+ if (canExitEarly(true)) {
+ return -1;
+ }
+ return start(traceMsgOrNull, true);
}
/**
* Returns quickly if log level is not DEBUG or TRACE - if it is DEBUG,
then
* just returns the current time in millis, if it is TRACE, then log the
* given message and also return the current time in millis.
- *
+ *
* @param traceMsgOrNull
* the message to log if log level is TRACE - or null if no
* message should be logged (even on TRACE level)
* @return the current time if level is DEBUG or TRACE, -1 otherwise
*/
- public final long start(String traceMsgOrNull) {
- if (!delegate.isDebugEnabled()) {
- // if log level is not at least DEBUG, then return fast, no-op
+ private long start(String traceMsgOrNull, boolean logAtInfoToo) {
+ if (canExitEarly(logAtInfoToo)) {
return -1;
}
if (traceMsgOrNull != null && delegate.isTraceEnabled()) {
@@ -94,70 +119,89 @@ public final class PerfLogger {
}
/**
- * Returns quickly if log level is not DEBUG or TRACE - if it is DEBUG
- * and the difference between now and the provided 'start' is bigger
(slower)
- * than 'logAtDebugIfSlowerThanMs', then a log.debug is emitted, if at
- * TRACE then a log.trace is always emitted (independent of time measured).
- * <p>
+ * See {@link #end(long, long, long, String, Object...)}
* Note that this method exists for performance optimization only (compared
* to the other end() method with a vararg.
- * @param start the start time with which 'now' should be compared
- * @param logAtDebugIfSlowerThanMs the number of milliseconds that must
- * be surpassed to issue a log.debug (if log level is DEBUG)
- * @param logMessagePrefix the log message 'prefix' - to which the given
- * argument will be passed, plus the measured time difference in the format
- * '[took x ms']
- * @param arg1 the argument which is to be passed to the log statement
*/
public final void end(long start, long logAtDebugIfSlowerThanMs,
String logMessagePrefix, Object arg1) {
if (start < 0) {
return;
}
- end(start, logAtDebugIfSlowerThanMs, logMessagePrefix,
+ end(start, logAtDebugIfSlowerThanMs, Long.MAX_VALUE, logMessagePrefix,
new Object[] { arg1 });
}
/**
- * Returns quickly if log level is not DEBUG or TRACE - if it is DEBUG
- * and the difference between now and the provided 'start' is bigger
(slower)
- * than 'logAtDebugIfSlowerThanMs', then a log.debug is emitted, if at
- * TRACE then a log.trace is always emitted (independent of time measured).
- * <p>
+ * See {@link #end(long, long, long, String, Object...)}
* Note that this method exists for performance optimization only (compared
* to the other end() method with a vararg.
- * @param start the start time with which 'now' should be compared
- * @param logAtDebugIfSlowerThanMs the number of milliseconds that must
- * be surpassed to issue a log.debug (if log level is DEBUG)
- * @param logMessagePrefix the log message 'prefix' - to which the given
- * arguments will be passed, plus the measured time difference in the
format
- * '[took x ms']
- * @param arg1 the first argument which is to be passed to the log
statement
- * @param arg2 the second argument which is to be passed to the log
statement
*/
public final void end(long start, long logAtDebugIfSlowerThanMs,
String logMessagePrefix, Object arg1, Object arg2) {
if (start < 0) {
return;
}
- end(start, logAtDebugIfSlowerThanMs, logMessagePrefix, new Object[] {
- arg1, arg2 });
+ end(start, logAtDebugIfSlowerThanMs, Long.MAX_VALUE, logMessagePrefix,
+ new Object[] { arg1, arg2 });
}
/**
- * Returns quickly if log level is not DEBUG or TRACE - if it is DEBUG
- * and the difference between now and the provided 'start' is bigger
(slower)
- * than 'logAtDebugIfSlowerThanMs', then a log.debug is emitted, if at
- * TRACE then a log.trace is always emitted (independent of time measured).
+ * Shortcut to {@link #end(long, long, long, String, Object...)} for
+ * {@code logMessagePrefix} = {@link Long#MAX_VALUE}
+ */
+ public void end(long start, long logAtDebugIfSlowerThanMs,
+ String logMessagePrefix, Object... arguments) {
+ end(start, logAtDebugIfSlowerThanMs, Long.MAX_VALUE, logMessagePrefix,
arguments);
+ }
+
+ /**
+ * See {@link #end(long, long, long, String, Object...)}
+ * Note that this method exists for performance optimization only (compared
+ * to the other end() method with a vararg.
+ */
+ public final void end(long start, long logAtDebugIfSlowerThanMs, long
logAtInfoIfSlowerThanMs,
+ String logMessagePrefix, Object arg1) {
+ if (start < 0) {
+ return;
+ }
+ end(start, logAtDebugIfSlowerThanMs, logAtInfoIfSlowerThanMs,
logMessagePrefix,
+ new Object[] { arg1 });
+ }
+
+ /**
+ * See {@link #end(long, long, long, String, Object...)}
+ * Note that this method exists for performance optimization only (compared
+ * to the other end() method with a vararg.
+ */
+ public final void end(long start, long logAtDebugIfSlowerThanMs, long
logAtInfoIfSlowerThanMs,
+ String logMessagePrefix, Object arg1, Object arg2) {
+ if (start < 0) {
+ return;
+ }
+ end(start, logAtDebugIfSlowerThanMs, logAtInfoIfSlowerThanMs,
logMessagePrefix,
+ new Object[] { arg1, arg2 });
+ }
+
+ /**
+ * Returns quickly if start is negative (which is the case according to
log level
+ * at the time of {@link #start()} or {@link #startForInfoLog()}).
+ * If log level is set to TRACE, log.trace is always emitted.
+ * If log level is set to DEBUG, then log.debug is emitted if 'now' is
bigger (slower)
+ * than {@code start} by at least {@code logAtDebugIfSlowerThanMs}.
+ * If log level is set to INFO, then long.info is emitted if 'now' is
bigger (slower)
+ * than {@code start} by at least {@code logAtInfoIfSlowerThanMs}.
* @param start the start time with which 'now' should be compared
* @param logAtDebugIfSlowerThanMs the number of milliseconds that must
* be surpassed to issue a log.debug (if log level is DEBUG)
+ * @param logAtInfoIfSlowerThanMs the number of milliseconds that must
+ * be surpassed to issue a log.info (if log level is DEBUG)
* @param logMessagePrefix the log message 'prefix' - to which the given
* arguments will be passed, plus the measured time difference in the
format
* '[took x ms']
* @param arguments the arguments which is to be passed to the log
statement
*/
- public void end(long start, long logAtDebugIfSlowerThanMs,
+ public void end(long start, long logAtDebugIfSlowerThanMs, long
logAtInfoIfSlowerThanMs,
String logMessagePrefix, Object... arguments) {
if (start < 0) {
// if start is negative, we assume that start() returned -1
because the log level is above DEBUG
@@ -165,22 +209,57 @@ public final class PerfLogger {
}
final long diff = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() -
start);
- if (delegate.isTraceEnabled()) {
+ if (isTraceEnabled()) {
// if log level is TRACE, then always log - and do that on TRACE
// then:
delegate.trace(logMessagePrefix + " [took " + diff + "ms]",
(Object[]) arguments);
- } else if ((logAtDebugIfSlowerThanMs < 0)
- || (diff > logAtDebugIfSlowerThanMs)) {
+ } else if ( ( logAtDebugIfSlowerThanMs < 0 || diff >
logAtDebugIfSlowerThanMs )
+ && isDebugEnabled()) {
// otherwise (log level is DEBUG) only log if
// logDebugIfSlowerThanMs is set to -1 (or negative)
// OR the measured diff is larger than logDebugIfSlowerThanMs -
// and then do that on DEBUG:
delegate.debug(logMessagePrefix + " [took " + diff + "ms]",
(Object[]) arguments);
+ } else if ( logAtInfoIfSlowerThanMs < 0 || diff >
logAtInfoIfSlowerThanMs ) {
+ // otherwise (log level is INFO) only log if
+ // logAtInfoIfSlowerThanMs is set to -1 (or negative)
+ // OR the measured diff is larger than logAtInfoIfSlowerThanMs -
+ // and then do that on INFO:
+ delegate.info(logMessagePrefix + " [took " + diff + "ms]",
+ (Object[]) arguments);
}
}
+ /**
+ * @return same as {@code canExitEarly(false)}
+ */
+ private boolean canExitEarly() {
+ return canExitEarly(false);
+ }
+
+ /**
+ * Whether early exit is OK?
+ *
+ * @param logAtInfoToo We want to log at INFO level too
+ * @return {@code true} if log level not even at INFO
+ * or log level is not at least DEBUG as well as
{@code logAtInfoToo} is false too
+ * ; false otherwise
+ */
+ private boolean canExitEarly(boolean logAtInfoToo) {
+ if (!logAtInfoToo) {
+ return !isDebugEnabled();
+ } else {
+ return !isInfoEnabled();
+ }
+ }
+
+ /** Whether or not the delegate has log level INFO configured **/
+ public final boolean isInfoEnabled() {
+ return delegate.isInfoEnabled();
+ }
+
/** Whether or not the delegate has log level DEBUG configured **/
public final boolean isDebugEnabled() {
return delegate.isDebugEnabled();
Copied:
jackrabbit/oak/branches/1.4/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerIT.java
(from r1752273,
jackrabbit/oak/trunk/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerIT.java)
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/branches/1.4/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerIT.java?p2=jackrabbit/oak/branches/1.4/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerIT.java&p1=jackrabbit/oak/trunk/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerIT.java&r1=1752273&r2=1752282&rev=1752282&view=diff
==============================================================================
---
jackrabbit/oak/trunk/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerIT.java
(original)
+++
jackrabbit/oak/branches/1.4/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerIT.java
Tue Jul 12 11:53:45 2016
@@ -1,116 +1,156 @@
-/*
- * 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.jackrabbit.oak.util;
-
-import org.junit.Before;
-import org.junit.Test;
-import org.mockito.Mock;
-import org.mockito.MockitoAnnotations;
-import org.slf4j.Logger;
-
-import static org.mockito.Matchers.any;
-import static org.mockito.Matchers.anyString;
-import static org.mockito.Mockito.times;
-import static org.mockito.Mockito.verify;
-import static org.mockito.Mockito.verifyNoMoreInteractions;
-import static org.mockito.Mockito.when;
-
-public class PerfLoggerIT {
- @Mock
- Logger logger;
-
- private PerfLogger perfLogger;
-
- @Before
- public void setup() {
- MockitoAnnotations.initMocks(this);
- when(logger.isTraceEnabled()).thenReturn(false);
- when(logger.isDebugEnabled()).thenReturn(false);
- when(logger.isInfoEnabled()).thenReturn(false);
-
- perfLogger = new PerfLogger(logger);
- }
-
- //test for logger set at DEBUG
- @Test
- public void logAtDebugTimeoutNotHit() {
- setupDebugLogger();
-
- long start = perfLogger.start();
- perfLogger.end(start, 100, "message", "argument");
-
- verifyTraceInteractions(1, false, false);
- verifyDebugInteractions(2, false);
- verifyNoMoreInteractions(logger);
- }
-
- @Test
- public void logAtDebugTimeoutHit() throws InterruptedException {
- setupDebugLogger();
-
- long start = perfLogger.start();
- Thread.sleep(100);
- perfLogger.end(start, 20, "message", "argument");
-
- verifyTraceInteractions(1, false, false);
- verifyDebugInteractions(2, true);
- verifyNoMoreInteractions(logger);
- }
- //end DEBUG tests
-
-
- //test for logger set at INFO
- @Test
- public void logAtInfoDebugTimeoutHit() throws InterruptedException {
- setupInfoLogger();
-
- long start = perfLogger.start();
- Thread.sleep(100);
- perfLogger.end(start, 20, "message", "argument");
-
- verifyDebugInteractions(1, false);
- verifyNoMoreInteractions(logger);
- }
- //end INFO tests
-
- private void setupDebugLogger() {
- when(logger.isDebugEnabled()).thenReturn(true);
- setupInfoLogger();
- }
- private void setupInfoLogger() {
- when(logger.isInfoEnabled()).thenReturn(true);
- }
-
- private void verifyTraceInteractions(int enabled, boolean shouldLogStart,
boolean shouldLogEnd) {
- verify(logger, times(enabled)).isTraceEnabled();
-
- if (shouldLogStart) {
- verify(logger, times(1)).trace(anyString());
- }
- if (shouldLogEnd) {
- verify(logger, times(1)).trace(anyString(), any(Object[].class));
- }
- }
-
- private void verifyDebugInteractions(int enabled, boolean shouldLog) {
- verify(logger, times(enabled)).isDebugEnabled();
-
- if (shouldLog) {
- verify(logger, times(1)).debug(anyString(), any(Object[].class));
- }
- }
-}
+/*
+ * 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.jackrabbit.oak.util;
+
+import org.junit.Before;
+import org.junit.Test;
+import org.mockito.Mock;
+import org.mockito.MockitoAnnotations;
+import org.slf4j.Logger;
+
+import static org.mockito.Matchers.any;
+import static org.mockito.Matchers.anyString;
+import static org.mockito.Mockito.times;
+import static org.mockito.Mockito.verify;
+import static org.mockito.Mockito.verifyNoMoreInteractions;
+import static org.mockito.Mockito.when;
+
+/**
+ * Timing tests for {@link PerfLogger} using {@code Thread.sleep} because
+ * virtual clock requires currentTimeMillis (OAK-3877)
+ */
+public class PerfLoggerIT {
+ @Mock
+ Logger logger;
+
+ private PerfLogger perfLogger;
+
+ @Before
+ public void setup() {
+ MockitoAnnotations.initMocks(this);
+ when(logger.isTraceEnabled()).thenReturn(false);
+ when(logger.isDebugEnabled()).thenReturn(false);
+ when(logger.isInfoEnabled()).thenReturn(false);
+
+ perfLogger = new PerfLogger(logger);
+ }
+
+ //test for logger set at DEBUG
+ @Test
+ public void logAtDebugTimeoutNotHit() {
+ setupDebugLogger();
+
+ long start = perfLogger.start();
+ perfLogger.end(start, 100, "message", "argument");
+
+ verifyTraceInteractions(1, false, false);
+ verifyDebugInteractions(2, false);
+ verifyNoMoreInteractions(logger);
+ }
+
+ @Test
+ public void logAtDebugTimeoutHit() throws InterruptedException {
+ setupDebugLogger();
+
+ long start = perfLogger.start();
+ Thread.sleep(100);
+ perfLogger.end(start, 20, "message", "argument");
+
+ verifyTraceInteractions(1, false, false);
+ verifyDebugInteractions(3, true);
+ verifyNoMoreInteractions(logger);
+ }
+ //end DEBUG tests
+
+
+ //test for logger set at INFO
+ @Test
+ public void logAtInfoDebugTimeoutHit() throws InterruptedException {
+ setupInfoLogger();
+
+ long start = perfLogger.start();
+ Thread.sleep(100);
+ perfLogger.end(start, 20, "message", "argument");
+
+ verifyDebugInteractions(1, false);
+ verifyNoMoreInteractions(logger);
+ }
+
+ @Test
+ public void logAtInfoInfoTimeoutNotHit() throws InterruptedException {
+ setupInfoLogger();
+
+ long start = perfLogger.startForInfoLog();
+ Thread.sleep(100);
+ perfLogger.end(start, 20, 500, "message", "argument");
+
+ verifyTraceInteractions(1, false, false);
+ verifyDebugInteractions(1, false);
+ verifyInfoInteractions(2, false);
+ verifyNoMoreInteractions(logger);
+ }
+
+ @Test
+ public void logAtInfoInfoTimeoutHit() throws InterruptedException {
+ setupInfoLogger();
+
+ long start = perfLogger.startForInfoLog();
+ Thread.sleep(100);
+ perfLogger.end(start, 20, 50, "message", "argument");
+
+ verifyTraceInteractions(1, false, false);
+ verifyDebugInteractions(1, false);
+ verifyInfoInteractions(2, true);
+ verifyNoMoreInteractions(logger);
+ }
+ //end INFO tests
+
+ private void setupDebugLogger() {
+ when(logger.isDebugEnabled()).thenReturn(true);
+ setupInfoLogger();
+ }
+ private void setupInfoLogger() {
+ when(logger.isInfoEnabled()).thenReturn(true);
+ }
+
+ private void verifyTraceInteractions(int enabled, boolean shouldLogStart,
boolean shouldLogEnd) {
+ verify(logger, times(enabled)).isTraceEnabled();
+
+ if (shouldLogStart) {
+ verify(logger, times(1)).trace(anyString());
+ }
+ if (shouldLogEnd) {
+ verify(logger, times(1)).trace(anyString(), any(Object[].class));
+ }
+ }
+
+ private void verifyDebugInteractions(int enabled, boolean shouldLog) {
+ verify(logger, times(enabled)).isDebugEnabled();
+
+ if (shouldLog) {
+ verify(logger, times(1)).debug(anyString(), any(Object[].class));
+ }
+ }
+
+ private void verifyInfoInteractions(int enabled, boolean shouldLog) {
+ verify(logger, times(enabled)).isInfoEnabled();
+
+ if (shouldLog) {
+ verify(logger, times(1)).info(anyString(), any(Object[].class));
+ }
+ }
+}
Modified:
jackrabbit/oak/branches/1.4/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerTest.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/branches/1.4/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerTest.java?rev=1752282&r1=1752281&r2=1752282&view=diff
==============================================================================
---
jackrabbit/oak/branches/1.4/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerTest.java
(original)
+++
jackrabbit/oak/branches/1.4/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerTest.java
Tue Jul 12 11:53:45 2016
@@ -16,50 +16,224 @@
*/
package org.apache.jackrabbit.oak.util;
+import org.junit.Before;
import org.junit.Test;
-import org.mockito.Mockito;
+import org.mockito.Mock;
+import org.mockito.MockitoAnnotations;
import org.slf4j.Logger;
import static org.mockito.Matchers.any;
import static org.mockito.Matchers.anyString;
-import static org.mockito.Mockito.atLeastOnce;
-import static org.mockito.Mockito.never;
import static org.mockito.Mockito.times;
import static org.mockito.Mockito.verify;
import static org.mockito.Mockito.verifyNoMoreInteractions;
import static org.mockito.Mockito.when;
public class PerfLoggerTest {
+ @Mock
+ Logger logger;
- @Test
- public void testEndDebug() {
- Logger logger = Mockito.mock(Logger.class);
+ private PerfLogger perfLogger;
+
+ @Before
+ public void setup() {
+ MockitoAnnotations.initMocks(this);
when(logger.isTraceEnabled()).thenReturn(false);
- when(logger.isDebugEnabled()).thenReturn(true);
+ when(logger.isDebugEnabled()).thenReturn(false);
+ when(logger.isInfoEnabled()).thenReturn(false);
+
+ perfLogger = new PerfLogger(logger);
+ }
+
+ //test for logger set at TRACE
+ @Test
+ public void logAtTraceSimpleStart() {
+ setupTraceLogger();
- PerfLogger perfLogger = new PerfLogger(logger);
long start = perfLogger.start();
perfLogger.end(start, -1, "message", "argument");
- verify(logger, atLeastOnce()).isTraceEnabled();
- verify(logger, atLeastOnce()).isDebugEnabled();
- verify(logger, times(1)).debug(anyString(), any(Object[].class));
+ verifyTraceInteractions(1, false, true);
+ verifyDebugInteractions(2, false);
verifyNoMoreInteractions(logger);
}
@Test
- public void testEndSkipsIsDebugEnabled() {
- Logger logger = Mockito.mock(Logger.class);
- when(logger.isTraceEnabled()).thenReturn(false);
- when(logger.isDebugEnabled()).thenReturn(false);
+ public void logAtTraceMessageStart() {
+ setupTraceLogger();
+
+ long start = perfLogger.start("Start message");
+ perfLogger.end(start, -1, "message", "argument");
+
+ verifyTraceInteractions(2, true, true);
+ verifyDebugInteractions(2, false);
+ verifyNoMoreInteractions(logger);
+ }
+
+ @Test
+ public void logAtTraceSimpleStartWithInfoLog() {
+ setupTraceLogger();
+
+ long start = perfLogger.startForInfoLog();
+ perfLogger.end(start, -1, "message", "argument");
+
+ verifyTraceInteractions(1, false, true);
+ verifyInfoInteractions(2, false);
+ verifyNoMoreInteractions(logger);
+ }
+
+ @Test
+ public void logAtTraceMessageStartWithInfoLog() {
+ setupTraceLogger();
+
+ long start = perfLogger.startForInfoLog("Start message");
+ perfLogger.end(start, -1, "message", "argument");
+
+ verifyTraceInteractions(2, true, true);
+ verifyInfoInteractions(2, false);
+ verifyNoMoreInteractions(logger);
+ }
+ //end TRACE tests
+
+ //test for logger set at DEBUG
+ @Test
+ public void logAtDebugSimpleStart() {
+ setupDebugLogger();
- PerfLogger perfLogger = new PerfLogger(logger);
long start = perfLogger.start();
perfLogger.end(start, -1, "message", "argument");
- verify(logger, never()).isTraceEnabled();
- verify(logger, times(1)).isDebugEnabled();
+ verifyTraceInteractions(1, false, false);
+ verifyDebugInteractions(3, true);
+ verifyNoMoreInteractions(logger);
+ }
+
+ @Test
+ public void logAtDebugMessageStart() {
+ setupDebugLogger();
+
+ long start = perfLogger.start("Start message");
+ perfLogger.end(start, -1, "message", "argument");
+
+ verifyTraceInteractions(2, false, false);
+ verifyDebugInteractions(3, true);
+ verifyNoMoreInteractions(logger);
+ }
+
+ @Test
+ public void logAtDebugSimpleStartWithInfoLog() {
+ setupDebugLogger();
+
+ long start = perfLogger.startForInfoLog();
+ perfLogger.end(start, -1, "message", "argument");
+
+ verifyTraceInteractions(1, false, false);
+ verifyDebugInteractions(1, true);
+ verifyInfoInteractions(2, false);
verifyNoMoreInteractions(logger);
}
+ @Test
+ public void logAtDebugMessageStartWithInfoLog() {
+ setupDebugLogger();
+
+ long start = perfLogger.startForInfoLog("Start message");
+ perfLogger.end(start, -1, "message", "argument");
+
+ verifyTraceInteractions(2, false, false);
+ verifyDebugInteractions(1, true);
+ verifyInfoInteractions(2, false);
+ verifyNoMoreInteractions(logger);
+ }
+ //end DEBUG tests
+
+ //test for logger set at INFO
+ @Test
+ public void logAtInfoSimpleStart() {
+ setupInfoLogger();
+
+ long start = perfLogger.start();
+ perfLogger.end(start, -1, "message", "argument");
+
+ verifyDebugInteractions(1, false);
+ verifyNoMoreInteractions(logger);
+ }
+
+ @Test
+ public void logAtInfoMessageStart() {
+ setupInfoLogger();
+
+ long start = perfLogger.start("Start message");
+ perfLogger.end(start, -1, "message", "argument");
+
+ verifyDebugInteractions(1, false);
+ verifyNoMoreInteractions(logger);
+ }
+
+ @Test
+ public void logAtInfoSimpleStartWithInfoLog() {
+ setupInfoLogger();
+
+ long start = perfLogger.startForInfoLog();
+ perfLogger.end(start, -1, "message", "argument");
+
+ verifyTraceInteractions(1, false, false);
+ verifyDebugInteractions(1, false);
+ verifyInfoInteractions(2, false);
+ verifyNoMoreInteractions(logger);
+ }
+
+ @Test
+ public void logAtInfoMessageStartWithInfoLog() {
+ setupInfoLogger();
+
+ long start = perfLogger.startForInfoLog("Start message");
+ perfLogger.end(start, -1, "message", "argument");
+
+ verifyTraceInteractions(2, false, false);
+ verifyDebugInteractions(1, false);
+ verifyInfoInteractions(2, false);
+ verifyNoMoreInteractions(logger);
+ }
+ //end INFO tests
+
+ private void setupTraceLogger() {
+ when(logger.isTraceEnabled()).thenReturn(true);
+ setupDebugLogger();
+ }
+ private void setupDebugLogger() {
+ when(logger.isDebugEnabled()).thenReturn(true);
+ setupInfoLogger();
+ }
+ private void setupInfoLogger() {
+ when(logger.isInfoEnabled()).thenReturn(true);
+ }
+
+ private void verifyTraceInteractions(int enabled, boolean shouldLogStart,
boolean shouldLogEnd) {
+ verify(logger, times(enabled)).isTraceEnabled();
+
+ if (shouldLogStart) {
+ verify(logger, times(1)).trace(anyString());
+ }
+ if (shouldLogEnd) {
+ verify(logger, times(1)).trace(anyString(), any(Object[].class));
+ }
+ }
+
+ private void verifyDebugInteractions(int enabled, boolean shouldLog) {
+ verify(logger, times(enabled)).isDebugEnabled();
+
+ if (shouldLog) {
+ verify(logger, times(1)).debug(anyString(), any(Object[].class));
+ }
+ }
+
+ private void verifyInfoInteractions(int enabled, boolean shouldLog) {
+ verify(logger, times(enabled)).isInfoEnabled();
+
+ if (shouldLog) {
+ verify(logger, times(1)).info(anyString(), any(Object[].class));
+ }
+ }
+
}
