Author: mreutegg
Date: Mon Feb 23 09:53:58 2015
New Revision: 1661630
URL: http://svn.apache.org/r1661630
Log:
OAK-2501: add more trace-logging to mongoMk to debug performance issues
Apply patch from Stefan Egli
Added:
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/util/PerfLogger.java
(with props)
Modified:
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeState.java
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/mongo/MongoDocumentStore.java
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/observation/EventGenerator.java
Modified:
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeState.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeState.java?rev=1661630&r1=1661629&r2=1661630&view=diff
==============================================================================
---
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeState.java
(original)
+++
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeState.java
Mon Feb 23 09:53:58 2015
@@ -48,6 +48,8 @@ import org.apache.jackrabbit.oak.spi.sta
import org.apache.jackrabbit.oak.spi.state.NodeBuilder;
import org.apache.jackrabbit.oak.spi.state.NodeState;
import org.apache.jackrabbit.oak.spi.state.NodeStateDiff;
+import org.apache.jackrabbit.oak.util.PerfLogger;
+import org.slf4j.LoggerFactory;
import com.google.common.base.Function;
import com.google.common.collect.Iterables;
@@ -63,6 +65,10 @@ import static org.apache.jackrabbit.oak.
*/
public class DocumentNodeState extends AbstractNodeState implements CacheValue
{
+ private static final PerfLogger perfLogger = new PerfLogger(
+ LoggerFactory.getLogger(DocumentNodeState.class.getName()
+ + ".perf"));
+
public static final Children NO_CHILDREN = new Children();
/**
@@ -257,7 +263,19 @@ public class DocumentNodeState extends A
return true;
} else {
// use DocumentNodeStore compare
- return dispatch(store.diffChildren(this, mBase),
mBase, diff);
+ final long start = perfLogger.start();
+ try {
+ return dispatch(store.diffChildren(this, mBase),
+ mBase, diff);
+ } finally {
+ perfLogger
+ .end(start,
+ 1,
+ "compareAgainstBaseState, path={},
rev={}, lastRevision={}, base.path={}, base.rev={}, base.lastRevision={}",
+ path, rev, lastRevision,
+ mBase.path, mBase.rev,
+ mBase.lastRevision);
+ }
}
}
}
Modified:
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java?rev=1661630&r1=1661629&r2=1661630&view=diff
==============================================================================
---
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java
(original)
+++
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java
Mon Feb 23 09:53:58 2015
@@ -98,6 +98,7 @@ import org.apache.jackrabbit.oak.spi.sta
import org.apache.jackrabbit.oak.spi.state.NodeState;
import org.apache.jackrabbit.oak.spi.state.NodeStore;
import org.apache.jackrabbit.oak.stats.Clock;
+import org.apache.jackrabbit.oak.util.PerfLogger;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
@@ -109,6 +110,9 @@ public final class DocumentNodeStore
private static final Logger LOG =
LoggerFactory.getLogger(DocumentNodeStore.class);
+ private static final PerfLogger PERFLOG = new PerfLogger(
+ LoggerFactory.getLogger(DocumentNodeStore.class.getName() +
".perf"));
+
/**
* Do not cache more than this number of children for a document.
*/
@@ -698,6 +702,7 @@ public final class DocumentNodeStore
@CheckForNull
DocumentNodeState getNode(@Nonnull final String path, @Nonnull final
Revision rev) {
checkRevisionAge(checkNotNull(rev), checkNotNull(path));
+ final long start = PERFLOG.start();
try {
PathRev key = new PathRev(path, rev);
DocumentNodeState node = nodeCache.get(key, new
Callable<DocumentNodeState>() {
@@ -714,7 +719,10 @@ public final class DocumentNodeStore
return n;
}
});
- return node == missing || node.equals(missing) ? null : node;
+ final DocumentNodeState result = node == missing
+ || node.equals(missing) ? null : node;
+ PERFLOG.end(start, 1, "getNode: path={}, rev={}", path, rev);
+ return result;
} catch (UncheckedExecutionException e) {
throw DocumentStoreException.convert(e.getCause());
} catch (ExecutionException e) {
@@ -936,13 +944,21 @@ public final class DocumentNodeStore
@CheckForNull
DocumentNodeState readNode(String path, Revision readRevision) {
+ final long start = PERFLOG.start();
String id = Utils.getIdFromPath(path);
Revision lastRevision = getPendingModifications().get(path);
NodeDocument doc = store.find(Collection.NODES, id);
if (doc == null) {
+ PERFLOG.end(start, 1,
+ "readNode: (document not found) path={}, readRevision={}",
+ path, readRevision);
return null;
}
- return doc.getNodeAtRevision(this, readRevision, lastRevision);
+ final DocumentNodeState result = doc.getNodeAtRevision(this,
+ readRevision, lastRevision);
+ PERFLOG.end(start, 1, "readNode: path={}, readRevision={}", path,
+ readRevision);
+ return result;
}
/**
Modified:
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/mongo/MongoDocumentStore.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/mongo/MongoDocumentStore.java?rev=1661630&r1=1661629&r2=1661630&view=diff
==============================================================================
---
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/mongo/MongoDocumentStore.java
(original)
+++
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/mongo/MongoDocumentStore.java
Mon Feb 23 09:53:58 2015
@@ -63,6 +63,7 @@ import org.apache.jackrabbit.oak.plugins
import org.apache.jackrabbit.oak.plugins.document.util.StringValue;
import org.apache.jackrabbit.oak.plugins.document.util.Utils;
import org.apache.jackrabbit.oak.stats.Clock;
+import org.apache.jackrabbit.oak.util.PerfLogger;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
@@ -91,8 +92,9 @@ import static com.google.common.base.Pre
public class MongoDocumentStore implements DocumentStore {
private static final Logger LOG =
LoggerFactory.getLogger(MongoDocumentStore.class);
-
- private static final boolean LOG_TIME = false;
+ private static final PerfLogger PERFLOG = new PerfLogger(
+ LoggerFactory.getLogger(MongoDocumentStore.class.getName()
+ + ".perf"));
private static final DBObject BY_ID_ASC = new BasicDBObject(Document.ID,
1);
@@ -239,20 +241,6 @@ public class MongoDocumentStore implemen
return new NodeDocOffHeapCache(primaryCache, listener, builder, this);
}
- private static long start() {
- return LOG_TIME ? System.currentTimeMillis() : 0;
- }
-
- private void end(String message, long start) {
- if (LOG_TIME) {
- long t = System.currentTimeMillis() - start;
- if (t > 0) {
- LOG.debug(message + ": " + t);
- }
- timeSum += t;
- }
- }
-
@Override
public void finalize() throws Throwable {
super.finalize();
@@ -289,14 +277,20 @@ public class MongoDocumentStore implemen
@Override
public <T extends Document> T find(Collection<T> collection, String key) {
- return find(collection, key, true, -1);
+ final long start = PERFLOG.start();
+ final T result = find(collection, key, true, -1);
+ PERFLOG.end(start, 1, "find: preferCached=true, key={}", key);
+ return result;
}
@Override
public <T extends Document> T find(final Collection<T> collection,
final String key,
int maxCacheAge) {
- return find(collection, key, false, maxCacheAge);
+ final long start = PERFLOG.start();
+ final T result = find(collection, key, false, maxCacheAge);
+ PERFLOG.end(start, 1, "find: preferCached=false, key={}", key);
+ return result;
}
@SuppressWarnings("unchecked")
@@ -409,12 +403,14 @@ public class MongoDocumentStore implemen
protected <T extends Document> T findUncached(Collection<T> collection,
String key, DocumentReadPreference docReadPref) {
log("findUncached", key, docReadPref);
DBCollection dbCollection = getDBCollection(collection);
- long start = start();
+ final long start = PERFLOG.start();
+ boolean isSlaveOk = false;
try {
ReadPreference readPreference = getMongoReadPreference(collection,
Utils.getParentId(key), docReadPref);
if(readPreference.isSlaveOk()){
LOG.trace("Routing call to secondary for fetching [{}]", key);
+ isSlaveOk = true;
}
DBObject obj = dbCollection.findOne(getByKeyQuery(key).get(),
null, null, readPreference);
@@ -439,7 +435,8 @@ public class MongoDocumentStore implemen
}
return doc;
} finally {
- end("findUncached", start);
+ PERFLOG.end(start, 1, "findUncached on key={}, isSlaveOk={}", key,
+ isSlaveOk);
}
}
@@ -490,7 +487,7 @@ public class MongoDocumentStore implemen
DBObject query = queryBuilder.get();
String parentId = Utils.getParentIdFromLowerLimit(fromKey);
TreeLock lock = acquireExclusive(parentId != null ? parentId : "");
- long start = start();
+ final long start = PERFLOG.start();
try {
DBCursor cursor =
dbCollection.find(query).sort(BY_ID_ASC).hint(hint);
ReadPreference readPreference =
@@ -538,7 +535,7 @@ public class MongoDocumentStore implemen
return list;
} finally {
lock.unlock();
- end("query", start);
+ PERFLOG.end(start, 1, "query for children from [{}] to [{}]",
fromKey, toKey);
}
}
@@ -553,7 +550,7 @@ public class MongoDocumentStore implemen
public <T extends Document> void remove(Collection<T> collection, String
key) {
log("remove", key);
DBCollection dbCollection = getDBCollection(collection);
- long start = start();
+ long start = PERFLOG.start();
try {
WriteResult writeResult =
dbCollection.remove(getByKeyQuery(key).get());
invalidateCache(collection, key);
@@ -561,7 +558,7 @@ public class MongoDocumentStore implemen
throw new DocumentStoreException("Remove failed: " +
writeResult.getError());
}
} finally {
- end("remove", start);
+ PERFLOG.end(start, 1, "remove key={}", key);
}
}
@@ -591,7 +588,7 @@ public class MongoDocumentStore implemen
DBObject update = createUpdate(updateOp);
TreeLock lock = acquire(updateOp.getId());
- long start = start();
+ final long start = PERFLOG.start();
try {
// get modCount of cached document
Number modCount = null;
@@ -644,7 +641,7 @@ public class MongoDocumentStore implemen
throw DocumentStoreException.convert(e);
} finally {
lock.unlock();
- end("findAndModify", start);
+ PERFLOG.end(start, 1, "findAndModify [{}]", updateOp.getId());
}
}
@@ -714,7 +711,7 @@ public class MongoDocumentStore implemen
}
DBCollection dbCollection = getDBCollection(collection);
- long start = start();
+ final long start = PERFLOG.start();
try {
try {
WriteResult writeResult = dbCollection.insert(inserts);
@@ -736,7 +733,7 @@ public class MongoDocumentStore implemen
return false;
}
} finally {
- end("create", start);
+ PERFLOG.end(start, 1, "create");
}
}
@@ -750,7 +747,7 @@ public class MongoDocumentStore implemen
// make sure we don't modify the original updateOp
updateOp = updateOp.copy();
DBObject update = createUpdate(updateOp);
- long start = start();
+ final long start = PERFLOG.start();
try {
Map<String, NodeDocument> cachedDocs = Collections.emptyMap();
if (collection == Collection.NODES) {
@@ -786,7 +783,7 @@ public class MongoDocumentStore implemen
throw DocumentStoreException.convert(e);
}
} finally {
- end("update", start);
+ PERFLOG.end(start, 1, "update");
}
}
Modified:
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/observation/EventGenerator.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/observation/EventGenerator.java?rev=1661630&r1=1661629&r2=1661630&view=diff
==============================================================================
---
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/observation/EventGenerator.java
(original)
+++
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/observation/EventGenerator.java
Mon Feb 23 09:53:58 2015
@@ -36,7 +36,7 @@ import javax.annotation.Nonnull;
import org.apache.jackrabbit.oak.api.PropertyState;
import org.apache.jackrabbit.oak.spi.state.NodeState;
import org.apache.jackrabbit.oak.spi.state.NodeStateDiff;
-import org.slf4j.Logger;
+import org.apache.jackrabbit.oak.util.PerfLogger;
import org.slf4j.LoggerFactory;
/**
@@ -55,7 +55,10 @@ import org.slf4j.LoggerFactory;
* </pre>
*/
public class EventGenerator {
- private static final Logger log =
LoggerFactory.getLogger(EventGenerator.class);
+
+ private static final PerfLogger perfLogger = new PerfLogger(
+ LoggerFactory.getLogger(EventGenerator.class.getName()
+ + ".perf"));
/**
* Maximum number of content changes to process during the
@@ -109,14 +112,11 @@ public class EventGenerator {
public void generate() {
if (!continuations.isEmpty()) {
final Continuation c = continuations.removeFirst();
- if (log.isDebugEnabled()) {
- log.debug("Starting event generation ...");
- long start = System.currentTimeMillis();
- c.run();
- log.debug("Generated {} events in {} ms", c.counter,
(System.currentTimeMillis() - start));
- } else {
- c.run();
- }
+ final long start = perfLogger
+ .start("generate: Starting event generation");
+ c.run();
+ perfLogger.end(start, 1, "generate: Generated {} events in {} ms",
+ c.counter);
}
}
Added:
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/util/PerfLogger.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/util/PerfLogger.java?rev=1661630&view=auto
==============================================================================
---
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/util/PerfLogger.java
(added)
+++
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/util/PerfLogger.java
Mon Feb 23 09:53:58 2015
@@ -0,0 +1,199 @@
+/*
+ * 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.slf4j.Logger;
+
+/**
+ * PerfLogger is a simpler wrapper around a slf4j Logger which
+ * comes with the capability to issue log statements containing
+ * the measurement between start() and end() methods.
+ * <p>
+ * Usage:
+ * <ul>
+ * <li>final long start = perflogger.start();</li>
+ * <li>.. some code ..
+ * <li>perflogger.end(start, 1, "myMethodName: param1={}", param1);</li>
+ * </ul>
+ * <p>
+ * The above will do nothing if the log level for the logger passed
+ * to PerfLogger at construction time is not DEBUG or TRACE - otherwise
+ * start() will return the current time in milliseconds and end will
+ * issue a log statement if the time between start and end was bigger
+ * than 1 ms, and it will pass the parameters to the log statement.
+ * The idea is to keep up performance at max possible if the log
+ * level is INFO or higher - but to allow some meaningful logging
+ * if at DEBUG or TRACe. The difference between DEBUG and TRACE is
+ * that TRACE will log start too (if a log message is passed to start)
+ * and it will always log the end - whereas in case of DEBUG the start
+ * will never be logged and the end will only be logged if the time
+ * is bigger than what's passed to end.
+ */
+public final class PerfLogger {
+
+ /** The logger to which the log statements are emitted **/
+ private final Logger delegate;
+
+ /** Create a new PerfLogger that shall use the given Logger object for
logging **/
+ public PerfLogger(Logger delegate) {
+ if (delegate == null) {
+ throw new IllegalArgumentException("delegate must not be null");
+ }
+ this.delegate = delegate;
+ }
+
+ /**
+ * 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
+ */
+ public final long start() {
+ if (!delegate.isDebugEnabled()) {
+ // if log level is not at least DEBUG, then return fast, no-op
+ return -1;
+ }
+ return start(null);
+ }
+
+ /**
+ * 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
+ return -1;
+ }
+ if (traceMsgOrNull != null && delegate.isTraceEnabled()) {
+ delegate.trace(traceMsgOrNull);
+ }
+ return System.currentTimeMillis();
+ }
+
+ /**
+ * 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>
+ * 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 (!delegate.isTraceEnabled()) {
+ return;
+ }
+ end(start, logAtDebugIfSlowerThanMs, 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>
+ * 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 (!delegate.isTraceEnabled()) {
+ return;
+ }
+ end(start, logAtDebugIfSlowerThanMs, 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).
+ * @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 arguments the arguments which is to be passed to the log
statement
+ */
+ public void end(long start, long logAtDebugIfSlowerThanMs,
+ String logMessagePrefix, Object... arguments) {
+ if (!delegate.isDebugEnabled()) {
+ // if log level is not at least DEBUG, then return fast, no-op
+ return;
+ }
+
+ if (start == -1) {
+ // start was never set
+ // -> then log at trace as we have no diff available
+ delegate.trace(logMessagePrefix + " [start not set]",
+ (Object[]) arguments);
+ } else {
+ final long diff = System.currentTimeMillis() - start;
+ if (delegate.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)) {
+ // 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);
+ }
+ }
+ }
+
+ /** Whether or not the delegate has log level DEBUG configured **/
+ public final boolean isDebugEnabled() {
+ return delegate.isDebugEnabled();
+ }
+
+ /** Whether or not the delegate has log level TRACE configured **/
+ public final boolean isTraceEnabled() {
+ return delegate.isTraceEnabled();
+ }
+
+}
Propchange:
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/util/PerfLogger.java
------------------------------------------------------------------------------
svn:eol-style = native
