QPID-4515: improved broker logging, particularly when receiving/sending AMQP 0-8/0-9 frames and when committing transactions.

Work done by Keith (kwall) and myself.

git-svn-id: https://svn.apache.org/repos/asf/qpid/trunk@1424382 13f79535-47bb-0310-9956-ffa450edef68

2 files changed, 38 insertions, 9 deletions

diff --git a/qpid/java/bdbstore/src/main/java/org/apache/qpid/server/store/berkeleydb/AbstractBDBMessageStore.java b/qpid/java/bdbstore/src/main/java/org/apache/qpid/server/store/berkeleydb/AbstractBDBMessageStore.java
index 851038c6de..eb8723461e 100644
--- a/qpid/java/bdbstore/src/main/java/org/apache/qpid/server/store/berkeleydb/AbstractBDBMessageStore.java
+++ b/qpid/java/bdbstore/src/main/java/org/apache/qpid/server/store/berkeleydb/AbstractBDBMessageStore.java
@@ -902,7 +902,7 @@ public abstract class AbstractBDBMessageStore implements MessageStore
             {
                 LOGGER.debug("Enqueuing message " + messageId + " on queue "
                         + (queue instanceof AMQQueue ? ((AMQQueue) queue).getName() + " with id " : "") + queue.getId()
-                        + " [Transaction" + tx + "]");
+                        + " in transaction " + tx);
             }
             _deliveryDb.put(tx, key, value);
         }
@@ -1056,7 +1056,8 @@ public abstract class AbstractBDBMessageStore implements MessageStore
 
             if (LOGGER.isDebugEnabled())
             {
-                LOGGER.debug("commitTranImpl completed for [Transaction:" + tx + "]");
+                String transactionType = syncCommit ? "synchronous" : "asynchronous";
+                LOGGER.debug("commitTranImpl completed " + transactionType + " transaction " + tx);
             }
         }
         catch (DatabaseException e)
@@ -1078,7 +1079,7 @@ public abstract class AbstractBDBMessageStore implements MessageStore
     {
         if (LOGGER.isDebugEnabled())
         {
-            LOGGER.debug("abortTran called for [Transaction:" + tx + "]");
+            LOGGER.debug("abortTran called for transaction " + tx);
         }
 
         try
@@ -1190,7 +1191,7 @@ public abstract class AbstractBDBMessageStore implements MessageStore
 
             if (LOGGER.isDebugEnabled())
             {
-                LOGGER.debug("Storing content for message " + messageId + "[Transaction" + tx + "]");
+                LOGGER.debug("Storing content for message " + messageId + " in transaction " + tx);
 
             }
         }
@@ -1215,8 +1216,9 @@ public abstract class AbstractBDBMessageStore implements MessageStore
     {
         if (LOGGER.isDebugEnabled())
         {
-            LOGGER.debug("public void storeMetaData(Txn tx = " + tx + ", Long messageId = "
-                       + messageId + ", MessageMetaData messageMetaData = " + messageMetaData + "): called");
+            LOGGER.debug("storeMetaData called for transaction " + tx
+                    + ", messageId " + messageId
+                    + ", messageMetaData " + messageMetaData);
         }
 
         DatabaseEntry key = new DatabaseEntry();
@@ -1230,7 +1232,7 @@ public abstract class AbstractBDBMessageStore implements MessageStore
             _messageMetaDataDb.put(tx, key, value);
             if (LOGGER.isDebugEnabled())
             {
-                LOGGER.debug("Storing message metadata for message id " + messageId + "[Transaction" + tx + "]");
+                LOGGER.debug("Storing message metadata for message id " + messageId + " in transaction " + tx);
             }
         }
         catch (DatabaseException e)
diff --git a/qpid/java/bdbstore/src/main/java/org/apache/qpid/server/store/berkeleydb/CommitThreadWrapper.java b/qpid/java/bdbstore/src/main/java/org/apache/qpid/server/store/berkeleydb/CommitThreadWrapper.java
index fe1556b5a6..598d20146c 100644
--- a/qpid/java/bdbstore/src/main/java/org/apache/qpid/server/store/berkeleydb/CommitThreadWrapper.java
+++ b/qpid/java/bdbstore/src/main/java/org/apache/qpid/server/store/berkeleydb/CommitThreadWrapper.java
@@ -80,7 +80,7 @@ public class CommitThreadWrapper
         {
             if (LOGGER.isDebugEnabled())
             {
-                LOGGER.debug("public synchronized void complete(): called (Transaction = " + _tx + ")");
+                LOGGER.debug("complete() called for transaction " + _tx);
             }
             _complete = true;
 
@@ -101,7 +101,10 @@ public class CommitThreadWrapper
 
             if(!_syncCommit)
             {
-                LOGGER.debug("CommitAsync was requested, returning immediately.");
+                if(LOGGER.isDebugEnabled())
+                {
+                    LOGGER.debug("CommitAsync was requested, returning immediately.");
+                }
                 return;
             }
 
@@ -121,6 +124,12 @@ public class CommitThreadWrapper
 
         public synchronized void waitForCompletion()
         {
+            long startTime = 0;
+            if(LOGGER.isDebugEnabled())
+            {
+                startTime = System.currentTimeMillis();
+            }
+
             while (!isComplete())
             {
                 _commitThread.explicitNotify();
@@ -133,6 +142,12 @@ public class CommitThreadWrapper
                     throw new RuntimeException(e);
                 }
             }
+
+            if(LOGGER.isDebugEnabled())
+            {
+                long duration = System.currentTimeMillis() - startTime;
+                LOGGER.debug("waitForCompletion returning after " + duration + " ms for transaction " + _tx);
+            }
         }
     }
 
@@ -198,8 +213,20 @@ public class CommitThreadWrapper
 
             try
             {
+                long startTime = 0;
+                if(LOGGER.isDebugEnabled())
+                {
+                    startTime = System.currentTimeMillis();
+                }
+
                 _environment.flushLog(true);
 
+                if(LOGGER.isDebugEnabled())
+                {
+                    long duration = System.currentTimeMillis() - startTime;
+                    LOGGER.debug("flushLog completed in " + duration  + " ms");
+                }
+
                 for(int i = 0; i < size; i++)
                 {
                     BDBCommitFuture commit = _jobQueue.poll();