You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@jackrabbit.apache.org by ju...@apache.org on 2010/09/16 12:39:49 UTC
svn commit: r997685 - in /jackrabbit/trunk/jackrabbit-core/src:
main/java/org/apache/jackrabbit/core/session/SessionState.java
test/resources/logback-test.xml
Author: jukka
Date: Thu Sep 16 10:39:48 2010
New Revision: 997685
URL: http://svn.apache.org/viewvc?rev=997685&view=rev
Log:
JCR-2741: Improved logging for session operations
Remove MDC variables from SessionState as MDC.put is too expensive for at least small read operations. Instead of JCR API calls, we should instead look at using MDC at the level of HTTP requests, etc.
Modified:
jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/session/SessionState.java
jackrabbit/trunk/jackrabbit-core/src/test/resources/logback-test.xml
Modified: jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/session/SessionState.java
URL: http://svn.apache.org/viewvc/jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/session/SessionState.java?rev=997685&r1=997684&r2=997685&view=diff
==============================================================================
--- jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/session/SessionState.java (original)
+++ jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/session/SessionState.java Thu Sep 16 10:39:48 2010
@@ -24,7 +24,6 @@ import javax.jcr.Session;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
-import org.slf4j.MDC;
/**
* Internal session state. This class keeps track of the lifecycle of
@@ -135,76 +134,69 @@ public class SessionState {
*/
public <T> T perform(SessionOperation<T> operation)
throws RepositoryException {
- // Set MDC variables to reflect the current session and this operation
- LogState logState =
- new LogState("jcr.session", context, "jcr.operation", operation);
- try {
- // Acquire the exclusive lock for accessing session internals.
- // No other session should be holding the lock, so we log a
- // message to let the user know of such cases.
- if (!lock.tryLock()) {
- if (isWriteOperation
- && operation instanceof SessionWriteOperation) {
- Exception trace = new Exception(
- "Stack trace of concurrent access to " + context);
- log.warn("Attempt to perform " + operation
- + " while another thread is concurrently writing"
- + " to " + context + ". Blocking until the other"
- + " thread is finished using this session. Please"
- + " review your code to avoid concurrent use of"
- + " a session.", trace);
- } else if (log.isDebugEnabled()) {
- Exception trace = new Exception(
- "Stack trace of concurrent access to " + context);
- log.debug("Attempt to perform " + operation + " while"
- + " another thread is concurrently reading from "
- + context + ". Blocking until the other thread"
- + " is finished using this session. Please"
- + " review your code to avoid concurrent use of"
- + " a session.", trace);
- }
- lock.lock();
+ // Acquire the exclusive lock for accessing session internals.
+ // No other session should be holding the lock, so we log a
+ // message to let the user know of such cases.
+ if (!lock.tryLock()) {
+ if (isWriteOperation
+ && operation instanceof SessionWriteOperation) {
+ Exception trace = new Exception(
+ "Stack trace of concurrent access to " + context);
+ log.warn("Attempt to perform " + operation
+ + " while another thread is concurrently writing"
+ + " to " + context + ". Blocking until the other"
+ + " thread is finished using this session. Please"
+ + " review your code to avoid concurrent use of"
+ + " a session.", trace);
+ } else if (log.isDebugEnabled()) {
+ Exception trace = new Exception(
+ "Stack trace of concurrent access to " + context);
+ log.debug("Attempt to perform " + operation + " while"
+ + " another thread is concurrently reading from "
+ + context + ". Blocking until the other thread"
+ + " is finished using this session. Please"
+ + " review your code to avoid concurrent use of"
+ + " a session.", trace);
}
+ lock.lock();
+ }
- try {
- // Check that the session is still alive
- checkAlive();
+ try {
+ // Check that the session is still alive
+ checkAlive();
- // Raise the isWriteOperation flag for write operations.
- // The flag is used to set the appropriate log level above.
- boolean wasWriteOperation = isWriteOperation;
- if (!wasWriteOperation
- && operation instanceof SessionWriteOperation) {
- isWriteOperation = true;
- }
- try {
- // Perform the actual operation, optionally with debug logs
- if (log.isDebugEnabled()) {
- log.debug("Performing {}", operation);
- long start = System.nanoTime();
- try {
- return operation.perform(context);
- } finally {
- long time = System.nanoTime() - start;
- if (time > NS_PER_MS) {
- log.debug("Performed {} in {}ms",
- operation, time / NS_PER_MS);
- } else {
- log.debug("Performed {} in {}us",
- operation, time / NS_PER_US);
- }
- }
- } else {
+ // Raise the isWriteOperation flag for write operations.
+ // The flag is used to set the appropriate log level above.
+ boolean wasWriteOperation = isWriteOperation;
+ if (!wasWriteOperation
+ && operation instanceof SessionWriteOperation) {
+ isWriteOperation = true;
+ }
+ try {
+ // Perform the actual operation, optionally with debug logs
+ if (log.isDebugEnabled()) {
+ log.debug("Performing {}", operation);
+ long start = System.nanoTime();
+ try {
return operation.perform(context);
+ } finally {
+ long time = System.nanoTime() - start;
+ if (time > NS_PER_MS) {
+ log.debug("Performed {} in {}ms",
+ operation, time / NS_PER_MS);
+ } else {
+ log.debug("Performed {} in {}us",
+ operation, time / NS_PER_US);
+ }
}
- } finally {
- isWriteOperation = wasWriteOperation;
+ } else {
+ return operation.perform(context);
}
} finally {
- lock.unlock();
+ isWriteOperation = wasWriteOperation;
}
} finally {
- logState.reset();
+ lock.unlock();
}
}
@@ -217,73 +209,37 @@ public class SessionState {
* <code>false</code> if the session had already been closed
*/
public boolean close() {
- LogState logState =
- new LogState("jcr.session", context, "jcr.operation", "close()");
+ if (!lock.tryLock()) {
+ Exception trace = new Exception(
+ "Stack trace of concurrent access to " + context);
+ log.warn("Attempt to close " + context + " while another"
+ + " thread is concurrently accessing this session."
+ + " Blocking until the other thread is finished"
+ + " using this session. Please review your code"
+ + " to avoid concurrent use of a session.", trace);
+ lock.lock();
+ }
try {
- if (!lock.tryLock()) {
+ if (isAlive()) {
+ closed = new Exception(
+ "Stack trace of where " + context
+ + " was originally closed");
+ return true;
+ } else {
Exception trace = new Exception(
- "Stack trace of concurrent access to " + context);
- log.warn("Attempt to close " + context + " while another"
- + " thread is concurrently accessing this session."
- + " Blocking until the other thread is finished"
- + " using this session. Please review your code"
- + " to avoid concurrent use of a session.", trace);
- lock.lock();
- }
- try {
- if (isAlive()) {
- closed = new Exception(
- "Stack trace of where " + context
- + " was originally closed");
- return true;
- } else {
- Exception trace = new Exception(
- "Stack trace of the duplicate attempt to close "
- + context);
- log.warn("Attempt to close " + context + " after it has"
- + " already been closed. Please review your code"
- + " for proper session management.", trace);
- log.warn(context + " has already been closed. See the"
- + " attached exception for a trace of where this"
- + " session was closed.", closed);
- return false;
- }
- } finally {
- lock.unlock();
+ "Stack trace of the duplicate attempt to close "
+ + context);
+ log.warn("Attempt to close " + context + " after it has"
+ + " already been closed. Please review your code"
+ + " for proper session management.", trace);
+ log.warn(context + " has already been closed. See the"
+ + " attached exception for a trace of where this"
+ + " session was closed.", closed);
+ return false;
}
} finally {
- logState.reset();
- }
- }
-
- /**
- * Internal utility class for setting MDC variables during the execution
- * of a session operation.
- */
- private static class LogState {
-
- private final Object[] keyValuePairs;
-
- public LogState(Object... keyValuePairs) {
- this.keyValuePairs = keyValuePairs;
- for (int i = 0; i + 1 < keyValuePairs.length; i += 2) {
- String key = keyValuePairs[i].toString();
- if (MDC.get(key) == null) {
- MDC.put(key, keyValuePairs[i + 1].toString());
- } else {
- keyValuePairs[i + 1] = null;
- }
- }
+ lock.unlock();
}
-
- public void reset() {
- for (int i = 0; i + 1 < keyValuePairs.length; i += 2) {
- if (keyValuePairs[i + 1] != null) {
- MDC.remove(keyValuePairs[i].toString());
- }
- }
- }
-
}
}
Modified: jackrabbit/trunk/jackrabbit-core/src/test/resources/logback-test.xml
URL: http://svn.apache.org/viewvc/jackrabbit/trunk/jackrabbit-core/src/test/resources/logback-test.xml?rev=997685&r1=997684&r2=997685&view=diff
==============================================================================
--- jackrabbit/trunk/jackrabbit-core/src/test/resources/logback-test.xml (original)
+++ jackrabbit/trunk/jackrabbit-core/src/test/resources/logback-test.xml Thu Sep 16 10:39:48 2010
@@ -20,7 +20,7 @@
<appender name="file" class="ch.qos.logback.core.FileAppender">
<file>target/jcr.log</file>
<encoder>
- <pattern>%date{HH:mm:ss.SSS} %-5level %-40([%thread] %F:%L) %msg [%X{jcr.session} %X{jcr.operation}]%n</pattern>
+ <pattern>%date{HH:mm:ss.SSS} %-5level %-40([%thread] %F:%L) %msg%n</pattern>
</encoder>
</appender>
@@ -33,7 +33,7 @@
<appender name="FILE-${testname}" class="ch.qos.logback.core.FileAppender">
<File>target/surefire-reports/${testclass}.log</File>
<layout class="ch.qos.logback.classic.PatternLayout">
- <Pattern>%date{HH:mm:ss.SSS} %-5level %-40([%thread] %F:%L) %msg [%X{jcr.session} %X{jcr.operation}]%n</Pattern>
+ <Pattern>%date{HH:mm:ss.SSS} %-5level %-40([%thread] %F:%L) %msg%n</Pattern>
</layout>
</appender>
</sift>