You are viewing a plain text version of this content. The canonical link for it is here.
Posted to oak-issues@jackrabbit.apache.org by "Vikas Saurabh (JIRA)" <ji...@apache.org> on 2016/07/13 10:39:20 UTC
[jira] [Commented] (OAK-4543) Add PerfLogger around observation
event generation and event consumption by observer
[ https://issues.apache.org/jira/browse/OAK-4543?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15374816#comment-15374816 ]
Vikas Saurabh commented on OAK-4543:
------------------------------------
While in ideal case, I'd probably have liked to have single numbers for a pair of revision comparison. But, I couldn't find a way to do it (yet??? or impossible??). Here's something we might want to start with:
{code}
diff --git a/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/AbstractDocumentNodeState.java b/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/AbstractDocumentNodeState.java
index 5757711..333b3ea 100644
--- a/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/AbstractDocumentNodeState.java
+++ b/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/AbstractDocumentNodeState.java
@@ -111,14 +111,14 @@ public abstract class AbstractDocumentNodeState extends AbstractNodeState {
return true;
} else {
// use DocumentNodeStore compare
- final long start = perfLogger.start();
+ final long start = perfLogger.startForInfoLog();
try {
return getNodeStateDiffer().compare(this, mBase, diff);
} finally {
if (start > 0) {
perfLogger
.end(start,
- 1,
+ 1, 100,
"compareAgainstBaseState, path={}, readRevision={}, lastRevision={}, base.path={}, base.readRevision={}, base.lastRevision={}",
getPath(), getRevision(), getLastRevision(),
mBase.getPath(), mBase.getRevision(),
diff --git a/oak-core/src/main/java/org/apache/jackrabbit/oak/spi/commit/CompositeObserver.java b/oak-core/src/main/java/org/apache/jackrabbit/oak/spi/commit/CompositeObserver.java
index 5724f51..ceaaffe 100644
--- a/oak-core/src/main/java/org/apache/jackrabbit/oak/spi/commit/CompositeObserver.java
+++ b/oak-core/src/main/java/org/apache/jackrabbit/oak/spi/commit/CompositeObserver.java
@@ -26,6 +26,8 @@ import javax.annotation.Nonnull;
import javax.annotation.Nullable;
import org.apache.jackrabbit.oak.spi.state.NodeState;
+import org.apache.jackrabbit.oak.util.PerfLogger;
+import org.slf4j.LoggerFactory;
/**
* Composite observer that delegates all content changes to the set of
@@ -35,6 +37,9 @@ public class CompositeObserver implements Observer {
private final Set<Observer> observers = newIdentityHashSet();
+ private static final PerfLogger PERF_LOGGER = new PerfLogger(
+ LoggerFactory.getLogger(CompositeObserver.class.getName() + ".perf"));
+
public synchronized void addObserver(@Nonnull Observer observer) {
checkState(observers.add(checkNotNull(observer)));
}
@@ -50,7 +55,14 @@ public class CompositeObserver implements Observer {
@Nonnull NodeState root, @Nullable CommitInfo info) {
checkNotNull(root);
for (Observer observer : observers) {
+ long start = PERF_LOGGER.startForInfoLog();
observer.contentChanged(root, info);
+ PERF_LOGGER.end(
+ start,
+ 100, 2000,
+ "Dispatched contentChanged to {} for {}",
+ observer, root
+ );
}
}
diff --git a/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/observation/ChangeProcessor.java b/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/observation/ChangeProcessor.java
index 43267ed..20a72ed 100644
--- a/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/observation/ChangeProcessor.java
+++ b/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/observation/ChangeProcessor.java
@@ -329,7 +329,7 @@ class ChangeProcessor implements Observer {
public void contentChanged(@Nonnull NodeState root, @Nullable CommitInfo info) {
if (previousRoot != null) {
try {
- long start = PERF_LOGGER.start();
+ long start = PERF_LOGGER.startForInfoLog();
FilterProvider provider = filterProvider.get();
// FIXME don't rely on toString for session id
if (provider.includeCommit(contentSession.toString(), info)) {
@@ -347,7 +347,7 @@ class ChangeProcessor implements Observer {
}
}
}
- PERF_LOGGER.end(start, 100,
+ PERF_LOGGER.end(start, 100, 2000,
"Generated events (before: {}, after: {})",
previousRoot, root);
} catch (Exception e) {
{code}
For now, I think diff per path logging at 1ms at DEBUG and 100 ms for INFO is ok.
For composite timings of jcr listeners ({{ChangeProcessor}}), I think logging at 100ms/2000ms would capture diff+event timings. Not sure about this though... needs validation? Btw, I'd like to also log {{eventListener}} to better capture the slow ones. Is that a good idea?
Similarly, for direct oak observers ({{ChangeDispather}}->{{CompositeObserver}}), I think 100ms/2000ms around each observer.contentChanged would capture diff+event timings. BUT, as it seems to me (disclaimer: I'm not sure of code flow here), the call is just to initiate a diff and actual diff calls are probably made by observer internally. If that's the case, I'm not sure how to collect composite information for this case.
[~chetanm], [~egli], [~mreutegg] please share your inputs :).
> Add PerfLogger around observation event generation and event consumption by observer
> ------------------------------------------------------------------------------------
>
> Key: OAK-4543
> URL: https://issues.apache.org/jira/browse/OAK-4543
> Project: Jackrabbit Oak
> Issue Type: Improvement
> Reporter: Vikas Saurabh
> Assignee: Vikas Saurabh
> Priority: Minor
> Labels: candidate_oak_1_0, candidate_oak_1_2, candidate_oak_1_4, monitoring, observation, performance
>
> I'm not sure if it's possible in the current scheme of things (implementation), but it'd useful to be able to easily differentiate between slow diff calculation or slow observer as a reason to see why observation queue might fill up.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)