svn commit: r995064 - /jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/session/SessionState.java

[ju...@apache.org]

Author: jukka
Date: Wed Sep  8 14:23:37 2010
New Revision: 995064

URL: http://svn.apache.org/viewvc?rev=995064&view=rev
Log:
JCR-2741: Improved logging for session operations

Use nanosecond timing, but scale it back to milliseconds for more readable log messages.
(System.currentTimeMillis() is affected by system time changes, as pointed out by Thomas.)

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=995064&r1=995063&r2=995064&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 14:23:37 2010
@@ -50,6 +50,11 @@ public class SessionState {
         LoggerFactory.getLogger(SessionState.class);
 
     /**
+     * Number of nanoseconds in a millisecond.
+     */
+    private static final int NS_PER_MS = 1000000;
+
+    /**
      * Component context of this session.
      */
     private final SessionContext context;
@@ -161,13 +166,13 @@ public class SessionState {
                     // Perform the actual operation, optionally with debug logs
                     if (log.isDebugEnabled()) {
                         log.debug("Performing {}", operation);
-                        long start = System.currentTimeMillis();
+                        long start = System.nanoTime();
                         try {
                             return operation.perform(context);
                         } finally {
-                            log.debug("{} performed in {}ms",
-                                    operation,
-                                    System.currentTimeMillis() - start);
+                            log.debug("It took {}ms to perform {}",
+                                    (System.nanoTime() - start) / NS_PER_MS,
+                                    operation);
                         }
                     } else {
                         return operation.perform(context);