jackrabbit-oak-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Vikas Saurabh (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (OAK-4543) Add PerfLogger around observation event generation and event consumption by observer
Date Wed, 13 Jul 2016 10:39:20 GMT

    [ 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)

Mime
View raw message