You are viewing a plain text version of this content. The canonical link for it is here.
Posted to oak-commits@jackrabbit.apache.org by th...@apache.org on 2023/01/06 08:42:26 UTC
[jackrabbit-oak] branch OAK-10054 created (now cdc854cb9e)
This is an automated email from the ASF dual-hosted git repository.
thomasm pushed a change to branch OAK-10054
in repository https://gitbox.apache.org/repos/asf/jackrabbit-oak.git
at cdc854cb9e OAK-10054 Improved trace level logging of JCR method calls
This branch includes the following new commits:
new cdc854cb9e OAK-10054 Improved trace level logging of JCR method calls
The 1 revisions listed above as "new" are entirely new to this
repository and will be described in separate emails. The revisions
listed as "add" were already present in the repository and have only
been added to this reference.
[jackrabbit-oak] 01/01: OAK-10054 Improved trace level logging of JCR method calls
Posted by th...@apache.org.
This is an automated email from the ASF dual-hosted git repository.
thomasm pushed a commit to branch OAK-10054
in repository https://gitbox.apache.org/repos/asf/jackrabbit-oak.git
commit cdc854cb9e409a88df49ce9ff76635b71f103351
Author: Thomas Mueller <th...@apache.org>
AuthorDate: Fri Jan 6 09:42:13 2023 +0100
OAK-10054 Improved trace level logging of JCR method calls
---
.../oak/jcr/delegate/SessionDelegate.java | 29 ++++++++++++++++--
.../jackrabbit/oak/jcr/session/ItemImpl.java | 5 ++++
.../jackrabbit/oak/jcr/session/NodeImpl.java | 34 ++++++++++++++++++----
3 files changed, 61 insertions(+), 7 deletions(-)
diff --git a/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/delegate/SessionDelegate.java b/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/delegate/SessionDelegate.java
index b757d40bfa..6799fa3873 100644
--- a/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/delegate/SessionDelegate.java
+++ b/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/delegate/SessionDelegate.java
@@ -29,6 +29,7 @@ import static org.apache.jackrabbit.oak.commons.PathUtils.denotesRoot;
import java.io.IOException;
import java.util.Iterator;
import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicLong;
import java.util.concurrent.locks.Condition;
import java.util.concurrent.locks.Lock;
import java.util.concurrent.locks.ReentrantLock;
@@ -78,6 +79,20 @@ public class SessionDelegate {
static final Logger readOperationLogger = LoggerFactory.getLogger("org.apache.jackrabbit.oak.jcr.operations.reads");
static final Logger writeOperationLogger = LoggerFactory.getLogger("org.apache.jackrabbit.oak.jcr.operations.writes");
+ // the bitmask used for trace level logging
+ // we use a bitmask instead of a counter to avoid the slow modulo operation:
+ // https://stackoverflow.com/questions/27977834/why-is-modulus-operator-slow
+ // we use "if ((counter & LOG_TRACE_BIT_MASK) == 0) log(...)"
+ // instead of the slower "if ((counter % LOG_TRACE) == 0) log(...)"
+ private static final String LOG_TRACE_BIT_MASK_NAME = "org.apache.jackrabbit.oak.jcr.operations.bitMask";
+ // log every 128th call by default
+ private static long LOG_TRACE_BIT_MASK = Long.getLong(LOG_TRACE_BIT_MASK_NAME, 128 - 1);
+ private static final String LOG_TRACE_STACK_BIT_MASK_NAME = "org.apache.jackrabbit.oak.jcr.operations.stack.bitMask";
+ // log a stack trace every ~1 million calls by default
+ private static long LOG_TRACE_STACK_BIT_MASK = Long.getLong(LOG_TRACE_BIT_MASK_NAME, 1024 * 1024 - 1);
+ // the counter used for logging
+ private static AtomicLong LOG_COUNTER = new AtomicLong();
+
private final ContentSession contentSession;
private final SecurityProvider securityProvider;
private final RefreshAtNextAccess refreshAtNextAccess = new RefreshAtNextAccess();
@@ -689,8 +704,18 @@ public class SessionDelegate {
|| writeOperationLogger.isTraceEnabled()
|| auditLogger.isDebugEnabled()) {
Logger log = ops.isUpdate() ? writeOperationLogger : readOperationLogger;
- log.trace("[{}] {}", session, ops);
-
+ long logId = LOG_COUNTER.incrementAndGet();
+ if ((logId & LOG_TRACE_BIT_MASK) == 0) {
+ // update, to allow changes at runtime
+ LOG_TRACE_BIT_MASK = Long.getLong(LOG_TRACE_BIT_MASK_NAME, LOG_TRACE_BIT_MASK);
+ LOG_TRACE_STACK_BIT_MASK = Long.getLong(LOG_TRACE_BIT_MASK_NAME, LOG_TRACE_STACK_BIT_MASK);
+ if ((logId & LOG_TRACE_STACK_BIT_MASK) == 0) {
+ Exception e = new Exception("count: " + LOG_COUNTER);
+ log.trace("[{}] {}", session, ops, e);
+ } else {
+ log.trace("[{}] {}", session, ops);
+ }
+ }
//For a logout operation the auth info is not accessible
if (!ops.isLogout() && !ops.isRefresh() && !ops.isSave() && ops.isUpdate()) {
auditLogger.debug("[{}] [{}] {}", session.getAuthInfo().getUserID(), session, ops);
diff --git a/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/session/ItemImpl.java b/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/session/ItemImpl.java
index 5340383580..68a8b873b9 100644
--- a/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/session/ItemImpl.java
+++ b/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/session/ItemImpl.java
@@ -17,6 +17,7 @@
package org.apache.jackrabbit.oak.jcr.session;
import static com.google.common.collect.Lists.newArrayListWithCapacity;
+import static java.lang.String.format;
import static org.apache.jackrabbit.oak.api.Type.NAME;
import static org.apache.jackrabbit.oak.api.Type.NAMES;
import static org.apache.jackrabbit.oak.api.Type.PATH;
@@ -126,6 +127,10 @@ abstract class ItemImpl<T extends ItemDelegate> implements Item {
public String perform() {
return item.getName();
}
+ @Override
+ public String toString() {
+ return format("getName [%s]", dlg.getPath());
+ }
});
// special case name of root node
return oakName.isEmpty() ? "" : toJcrPath(dlg.getName());
diff --git a/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/session/NodeImpl.java b/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/session/NodeImpl.java
index 9d9dcede20..1bf61963e8 100644
--- a/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/session/NodeImpl.java
+++ b/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/session/NodeImpl.java
@@ -246,7 +246,7 @@ public class NodeImpl<T extends NodeDelegate> extends ItemImpl<T> implements Jac
@Override
public String toString() {
- return format("Removing node [%s]", dlg.getPath());
+ return format("removeNode [%s]", dlg.getPath());
}
});
}
@@ -329,7 +329,7 @@ public class NodeImpl<T extends NodeDelegate> extends ItemImpl<T> implements Jac
@Override
public String toString() {
- return format("Adding node [%s/%s]", dlg.getPath(), relPath);
+ return format("addNode [%s/%s]", dlg.getPath(), relPath);
}
});
}
@@ -599,6 +599,10 @@ public class NodeImpl<T extends NodeDelegate> extends ItemImpl<T> implements Jac
}
};
}
+ @Override
+ public String toString() {
+ return format("getNodes [%s]", dlg.getPath());
+ }
});
}
@@ -621,6 +625,10 @@ public class NodeImpl<T extends NodeDelegate> extends ItemImpl<T> implements Jac
});
return new NodeIteratorAdapter(nodeIterator(children));
}
+ @Override
+ public String toString() {
+ return format("getNodes [%s]", dlg.getPath());
+ }
});
}
@@ -642,6 +650,10 @@ public class NodeImpl<T extends NodeDelegate> extends ItemImpl<T> implements Jac
});
return new NodeIteratorAdapter(nodeIterator(children));
}
+ @Override
+ public String toString() {
+ return format("getNodes [%s]", dlg.getPath());
+ }
});
}
@@ -661,6 +673,10 @@ public class NodeImpl<T extends NodeDelegate> extends ItemImpl<T> implements Jac
return new PropertyImpl(pd, sessionContext);
}
}
+ @Override
+ public String toString() {
+ return format("getProperty [%s]", dlg.getPath());
+ }
});
}
@@ -676,6 +692,10 @@ public class NodeImpl<T extends NodeDelegate> extends ItemImpl<T> implements Jac
return new PropertyIteratorAdapter(
propertyIterator(properties), size);
}
+ @Override
+ public String toString() {
+ return format("getProperties [%s]", dlg.getPath());
+ }
});
}
@@ -874,6 +894,10 @@ public class NodeImpl<T extends NodeDelegate> extends ItemImpl<T> implements Jac
public Boolean perform() throws RepositoryException {
return node.getPropertyOrNull(oakPath) != null;
}
+ @Override
+ public String toString() {
+ return format("hasProperty [%s]", dlg.getPath());
+ }
});
} catch (PathNotFoundException e) {
return false;
@@ -1428,7 +1452,7 @@ public class NodeImpl<T extends NodeDelegate> extends ItemImpl<T> implements Jac
@Override
public String toString() {
- return format("Setting property [%s/%s]", dlg.getPath(), jcrName);
+ return format("setProperty [%s/%s]", dlg.getPath(), jcrName);
}
});
}
@@ -1474,7 +1498,7 @@ public class NodeImpl<T extends NodeDelegate> extends ItemImpl<T> implements Jac
@Override
public String toString() {
- return format("Setting property [%s/%s]", dlg.getPath(), jcrName);
+ return format("setProperty [%s/%s]", dlg.getPath(), jcrName);
}
});
}
@@ -1526,7 +1550,7 @@ public class NodeImpl<T extends NodeDelegate> extends ItemImpl<T> implements Jac
@Override
public String toString() {
- return format("Removing property [%s]", jcrName);
+ return format("removeProperty [%s]", jcrName);
}
});
}