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:27 UTC
[jackrabbit-oak] 01/01: OAK-10054 Improved trace level logging of JCR method calls
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);
}
});
}