From commits-return-10290-apmail-jackrabbit-commits-archive=jackrabbit.apache.org@jackrabbit.apache.org Wed Sep 08 12:08:09 2010 Return-Path: Delivered-To: apmail-jackrabbit-commits-archive@www.apache.org Received: (qmail 57062 invoked from network); 8 Sep 2010 12:08:09 -0000 Received: from unknown (HELO mail.apache.org) (140.211.11.3) by 140.211.11.9 with SMTP; 8 Sep 2010 12:08:09 -0000 Received: (qmail 69449 invoked by uid 500); 8 Sep 2010 12:08:09 -0000 Delivered-To: apmail-jackrabbit-commits-archive@jackrabbit.apache.org Received: (qmail 69359 invoked by uid 500); 8 Sep 2010 12:08:07 -0000 Mailing-List: contact commits-help@jackrabbit.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@jackrabbit.apache.org Delivered-To: mailing list commits@jackrabbit.apache.org Received: (qmail 69352 invoked by uid 99); 8 Sep 2010 12:08:07 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 08 Sep 2010 12:08:07 +0000 X-ASF-Spam-Status: No, hits=-2000.0 required=10.0 tests=ALL_TRUSTED X-Spam-Check-By: apache.org Received: from [140.211.11.4] (HELO eris.apache.org) (140.211.11.4) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 08 Sep 2010 12:08:06 +0000 Received: by eris.apache.org (Postfix, from userid 65534) id 98D1A23889E9; Wed, 8 Sep 2010 12:07:46 +0000 (UTC) Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit Subject: svn commit: r995004 - /jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/session/SessionState.java Date: Wed, 08 Sep 2010 12:07:46 -0000 To: commits@jackrabbit.apache.org From: jukka@apache.org X-Mailer: svnmailer-1.0.8 Message-Id: <20100908120746.98D1A23889E9@eris.apache.org> Author: jukka Date: Wed Sep 8 12:07:46 2010 New Revision: 995004 URL: http://svn.apache.org/viewvc?rev=995004&view=rev Log: JCR-2741: Improved logging for session operations Restructure the SessionState code for more consistent handling and logging of operations. Modified: jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/session/SessionState.java 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=995004&r1=995003&r2=995004&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 Wed Sep 8 12:07:46 2010 @@ -109,7 +109,7 @@ public class SessionState { if (!isAlive()) { throw new RepositoryException( "This session has been closed. See the chained exception" - + " for a trace of where the session was closed", closed); + + " for a trace of where the session was closed.", closed); } } @@ -123,23 +123,99 @@ public class SessionState { */ public T perform(SessionOperation operation) throws RepositoryException { - LogState state = new LogState( + // Set MDC variables to reflect the current session and this operation + LogState logState = new LogState( "jcr.session", context.toString(), "jcr.operation", operation.toString()); try { - if (log.isDebugEnabled()) { - long start = System.nanoTime(); + // 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) { + log.warn("Attempt to perform {} while another thread" + + " is concurrently modifying the session." + + " Blocking until the other thread is finished" + + " using this session.", operation); + } else { + log.debug("Attempt to perform {} while another thread" + + " is concurrently accessing the session." + + " Blocking until the other thread is finished" + + " using this session.", operation); + } + lock.lock(); + } + + 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 { - return internalPerform(operation); + // 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 { + log.debug("{} performed in {}ns", + operation, System.nanoTime() - start); + } + } else { + return operation.perform(context); + } } finally { - log.debug("{} performed in {}ns", - operation, System.nanoTime() - start); + isWriteOperation = wasWriteOperation; } - } else { - return internalPerform(operation); + } finally { + lock.unlock(); } } finally { - state.reset(); + logState.reset(); + } + } + + /** + * Closes this session. + * + * @return true if the session was closed, or + * false if the session had already been closed + */ + public boolean close() { + LogState logState = new LogState( + "jcr.session", context.toString(), + "jcr.operation", "close()"); + try { + if (!lock.tryLock()) { + log.warn("Attempt to close a session while another thread is" + + " concurrently accessing the session. Blocking until" + + " the other thread is finished using this session."); + lock.lock(); + } + try { + if (isAlive()) { + closed = new Exception( + "Stack trace of where " + context + " was closed"); + return true; + } else { + log.warn("This session has already been closed. See the" + + " chained exception for a trace of where the " + + " session was closed.", closed); + return false; + } + } finally { + lock.unlock(); + } + } finally { + logState.reset(); } } @@ -172,70 +248,4 @@ public class SessionState { } - /** - * The actual implementation of the {@link #perform(SessionOperation)} - * method, extracted since the public method is already filled with - * somewhat complex logging and timing logic. - * - * @param operation session operation - * @return the return value of the executed operation - * @throws RepositoryException if the operation fails or - * if the session has already been closed - */ - private T internalPerform(SessionOperation operation) - throws RepositoryException { - if (!lock.tryLock()) { - if (isWriteOperation && operation instanceof SessionWriteOperation) { - log.warn("Attempt to perform {} while another thread is" - + " concurrently modifying the session. Blocking until" - + " the other thread is finished using this session.", - operation); - } else { - log.debug("Attempt to perform {} while another thread is" - + " concurrently accessing the session. Blocking until" - + " the other thread is finished using this session.", - operation); - } - lock.lock(); - } - boolean wasWriteOperation = isWriteOperation; - if (!wasWriteOperation && operation instanceof SessionWriteOperation) { - isWriteOperation = true; - } - try { - checkAlive(); - log.debug("Performing {}", operation); - return operation.perform(context); - } finally { - isWriteOperation = wasWriteOperation; - lock.unlock(); - } - } - - /** - * Closes this session. - * - * @return true if the session was closed, or - * false if the session had already been closed - */ - public boolean close() { - if (!lock.tryLock()) { - log.warn("Attempt to close a session while another thread is" - + " concurrently accessing the session. Blocking until" - + " the other thread is finished using this session."); - lock.lock(); - } - try { - if (isAlive()) { - closed = new Exception(); - return true; - } else { - log.warn("This session has already been closed", closed); - return false; - } - } finally { - lock.unlock(); - } - } - }