svn commit: r656991 - in /myfaces/orchestra/trunk/core/src/main/java/org/apache/myfaces/orchestra: conversation/ConversationContext.java lib/_ReentrantLock.java

[sk...@apache.org]

Author: skitching
Date: Fri May 16 02:56:11 2008
New Revision: 656991

URL: http://svn.apache.org/viewvc?rev=656991&view=rev
Log:
Add debugging for resolving context-locking issues.

Modified:
    myfaces/orchestra/trunk/core/src/main/java/org/apache/myfaces/orchestra/conversation/ConversationContext.java
    myfaces/orchestra/trunk/core/src/main/java/org/apache/myfaces/orchestra/lib/_ReentrantLock.java

Modified: myfaces/orchestra/trunk/core/src/main/java/org/apache/myfaces/orchestra/conversation/ConversationContext.java
URL: http://svn.apache.org/viewvc/myfaces/orchestra/trunk/core/src/main/java/org/apache/myfaces/orchestra/conversation/ConversationContext.java?rev=656991&r1=656990&r2=656991&view=diff
==============================================================================
--- myfaces/orchestra/trunk/core/src/main/java/org/apache/myfaces/orchestra/conversation/ConversationContext.java (original)
+++ myfaces/orchestra/trunk/core/src/main/java/org/apache/myfaces/orchestra/conversation/ConversationContext.java Fri May 16 02:56:11 2008
@@ -369,22 +369,36 @@
      * If this method is called, then an equal number of calls to
      * unlockForCurrentThread <b>MUST</b> made, or this context object
      * will remain locked until the http session times out.
+     * <p>
+     * Note that this method may be called very early in the request processing
+     * lifecycle, eg before a FacesContext exists for a JSF request.
      *
      * @since 1.1
      */
     public void lockInterruptablyForCurrentThread() throws InterruptedException
     {
+        if (log.isDebugEnabled())
+        {
+            log.debug("Locking context " + this.id);
+        }
         lock.lockInterruptibly();
     }
 
     /**
      * Block until no other thread has this instance marked as reserved, then
      * mark the object as reserved for this thread.
+     * <p>
+     * Note that this method may be called very late in the request processing
+     * lifecycle, eg after a FacesContext has been destroyed for a JSF request.
      *
      * @since 1.1
      */
     public void unlockForCurrentThread()
     {
+        if (log.isDebugEnabled())
+        {
+            log.debug("Unlocking context " + this.id);
+        }
         lock.unlock();
     }
 

Modified: myfaces/orchestra/trunk/core/src/main/java/org/apache/myfaces/orchestra/lib/_ReentrantLock.java
URL: http://svn.apache.org/viewvc/myfaces/orchestra/trunk/core/src/main/java/org/apache/myfaces/orchestra/lib/_ReentrantLock.java?rev=656991&r1=656990&r2=656991&view=diff
==============================================================================
--- myfaces/orchestra/trunk/core/src/main/java/org/apache/myfaces/orchestra/lib/_ReentrantLock.java (original)
+++ myfaces/orchestra/trunk/core/src/main/java/org/apache/myfaces/orchestra/lib/_ReentrantLock.java Fri May 16 02:56:11 2008
@@ -18,6 +18,9 @@
  */
 package org.apache.myfaces.orchestra.lib;
 
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
+
 
 /**
  * A reentrant mutual exclusion with the same basic
@@ -37,12 +40,15 @@
  */
 public class _ReentrantLock implements java.io.Serializable {
     private static final long serialVersionUID = 7373984872572414699L;
+    private static final long WAIT_WARN_MILLIS = 30L * 1000L; // 30 seconds
 
+    private final Log log = LogFactory.getLog(_ReentrantLock.class);
     private transient Thread lockedBy;
     private int lockCount;
     
     public void lockInterruptibly() throws InterruptedException
     {
+        long beganAt = System.currentTimeMillis();
         Thread caller = Thread.currentThread();
         for(;;)
         {
@@ -63,12 +69,29 @@
     
                 try
                 {
-                    this.wait();
+                    if (log.isDebugEnabled())
+                    {
+                        log.debug("Waiting for lock " + this.toString()
+                                + " which is owned by thread "
+                                + lockedBy.getName());
+                    }
+                    this.wait(WAIT_WARN_MILLIS);
                 }
                 catch(InterruptedException e)
                 {
                     throw e;
                 }
+                
+                if (System.currentTimeMillis() >= beganAt + WAIT_WARN_MILLIS)
+                {
+                    // Hopefully this will not get invoked very often!
+                    if (log.isWarnEnabled())
+                    {
+                        log.warn("Waited for longer than " + WAIT_WARN_MILLIS 
+                            + " milliseconds for access to lock " + this.toString()
+                            + " which is locked by thread " + lockedBy.getName());
+                    }
+                }
             }
         }
     }