jackrabbit-oak-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From thom...@apache.org
Subject svn commit: r1489729 - in /jackrabbit/oak/trunk/oak-mongomk/src/main/java/org/apache/jackrabbit/mongomk/util: LogWrapper.java TimingWrapper.java Utils.java
Date Wed, 05 Jun 2013 07:28:33 GMT
Author: thomasm
Date: Wed Jun  5 07:28:31 2013
New Revision: 1489729

URL: http://svn.apache.org/r1489729
Log:
OAK-836 Improved Timing Wrapper (also log "%" of time and count)

Modified:
    jackrabbit/oak/trunk/oak-mongomk/src/main/java/org/apache/jackrabbit/mongomk/util/LogWrapper.java
    jackrabbit/oak/trunk/oak-mongomk/src/main/java/org/apache/jackrabbit/mongomk/util/TimingWrapper.java
    jackrabbit/oak/trunk/oak-mongomk/src/main/java/org/apache/jackrabbit/mongomk/util/Utils.java

Modified: jackrabbit/oak/trunk/oak-mongomk/src/main/java/org/apache/jackrabbit/mongomk/util/LogWrapper.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-mongomk/src/main/java/org/apache/jackrabbit/mongomk/util/LogWrapper.java?rev=1489729&r1=1489728&r2=1489729&view=diff
==============================================================================
--- jackrabbit/oak/trunk/oak-mongomk/src/main/java/org/apache/jackrabbit/mongomk/util/LogWrapper.java
(original)
+++ jackrabbit/oak/trunk/oak-mongomk/src/main/java/org/apache/jackrabbit/mongomk/util/LogWrapper.java
Wed Jun  5 07:28:31 2013
@@ -27,6 +27,8 @@ import org.slf4j.LoggerFactory;
 
 /**
  * A logging microkernel implementation.
+ * 
+ * @param <T> the wrapped microkernel
  */
 public class LogWrapper<T extends MicroKernel> implements MicroKernel {
     

Modified: jackrabbit/oak/trunk/oak-mongomk/src/main/java/org/apache/jackrabbit/mongomk/util/TimingWrapper.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-mongomk/src/main/java/org/apache/jackrabbit/mongomk/util/TimingWrapper.java?rev=1489729&r1=1489728&r2=1489729&view=diff
==============================================================================
--- jackrabbit/oak/trunk/oak-mongomk/src/main/java/org/apache/jackrabbit/mongomk/util/TimingWrapper.java
(original)
+++ jackrabbit/oak/trunk/oak-mongomk/src/main/java/org/apache/jackrabbit/mongomk/util/TimingWrapper.java
Wed Jun  5 07:28:31 2013
@@ -26,7 +26,6 @@ import javax.annotation.Nonnull;
 
 import org.apache.jackrabbit.mk.api.MicroKernel;
 import org.apache.jackrabbit.mk.api.MicroKernelException;
-import org.apache.jackrabbit.mk.json.JsopBuilder;
 
 /**
  * A MicroKernel wrapper that can be used to log and also time MicroKernel
@@ -43,6 +42,7 @@ public class TimingWrapper implements Mi
     private long startTime;
     private final Map<String, Count> counts = new HashMap<String, Count>();
     private long lastLogTime;
+    private long totalLogTime;
 
     /**
      * A class that keeps track of timing data and call counts.
@@ -51,43 +51,34 @@ public class TimingWrapper implements Mi
         public long count;
         public long max;
         public long total;
+        public long paramSize;
+        public long resultSize;
 
-        void update(long time) {
+        void update(long time, int paramSize, int resultSize) {
             count++;
             if (time > max) {
                 max = time;
             }
             total += time;
+            this.paramSize += paramSize;
+            this.resultSize += resultSize;
         }
     }
 
     public TimingWrapper(MicroKernel mk) {
         this.mk = mk;
-        counts.put("commit", new Count());
-        counts.put("getHeadRevision", new Count());
-        counts.put("getJournal", new Count());
-        counts.put("diff", new Count());
-        counts.put("getLength", new Count());
-        counts.put("getNodes", new Count());
-        counts.put("getRevisionHistory", new Count());
-        counts.put("nodeExists", new Count());
-        counts.put("getChildNodeCount", new Count());
-        counts.put("read", new Count());
-        counts.put("waitForCommit", new Count());
-        counts.put("write", new Count());
-        counts.put("branch", new Count());
-        counts.put("merge", new Count());
+        lastLogTime = now();
     }
 
     @Override
     public String commit(String path, String jsonDiff, String revisionId, String message)
{
         try {
-            long start = System.currentTimeMillis();
+            long start = now();
             String result = mk.commit(path, jsonDiff, revisionId, message);
-            updateAndLogTimes("commit", start);
+            updateAndLogTimes("commit", start, 
+                    size(path) + size(jsonDiff) + size(message), 0);
             return result;
         } catch (Exception e) {
-            logException(e);
             throw convert(e);
         }
     }
@@ -95,12 +86,11 @@ public class TimingWrapper implements Mi
     @Override
     public String getHeadRevision() {
         try {
-            long start = System.currentTimeMillis();
+            long start = now();
             String result = mk.getHeadRevision();
-            updateAndLogTimes("getHeadRevision", start);
+            updateAndLogTimes("getHeadRevision", start, 0, 0);
             return result;
         } catch (Exception e) {
-            logException(e);
             throw convert(e);
         }
     }
@@ -108,12 +98,12 @@ public class TimingWrapper implements Mi
     @Override
     public String getJournal(String fromRevisionId, String toRevisionId, String path) {
         try {
-            long start = System.currentTimeMillis();
+            long start = now();
             String result = mk.getJournal(fromRevisionId, toRevisionId, path);
-            updateAndLogTimes("getJournal", start);
+            updateAndLogTimes("getJournal", start,
+                    size(path), size(result));
             return result;
         } catch (Exception e) {
-            logException(e);
             throw convert(e);
         }
     }
@@ -121,12 +111,11 @@ public class TimingWrapper implements Mi
     @Override
     public String diff(String fromRevisionId, String toRevisionId, String path, int depth)
{
         try {
-            long start = System.currentTimeMillis();
+            long start = now();
             String result = mk.diff(fromRevisionId, toRevisionId, path, depth);
-            updateAndLogTimes("diff", start);
+            updateAndLogTimes("diff", start, size(path), size(result));
             return result;
         } catch (Exception e) {
-            logException(e);
             throw convert(e);
         }
     }
@@ -134,12 +123,11 @@ public class TimingWrapper implements Mi
     @Override
     public long getLength(String blobId) {
         try {
-            long start = System.currentTimeMillis();
+            long start = now();
             long result = mk.getLength(blobId);
-            updateAndLogTimes("getLength", start);
+            updateAndLogTimes("getLength", start, size(blobId), 0);
             return result;
         } catch (Exception e) {
-            logException(e);
             throw convert(e);
         }
     }
@@ -147,12 +135,11 @@ public class TimingWrapper implements Mi
     @Override
     public String getNodes(String path, String revisionId, int depth, long offset, int maxChildNodes,
String filter) {
         try {
-            long start = System.currentTimeMillis();
+            long start = now();
             String result = mk.getNodes(path, revisionId, depth, offset, maxChildNodes, filter);
-            updateAndLogTimes("getNodes", start);
+            updateAndLogTimes("getNodes", start, size(path) + size(filter), size(result));
             return result;
         } catch (Exception e) {
-            logException(e);
             throw convert(e);
         }
     }
@@ -160,12 +147,11 @@ public class TimingWrapper implements Mi
     @Override
     public String getRevisionHistory(long since, int maxEntries, String path) {
         try {
-            long start = System.currentTimeMillis();
+            long start = now();
             String result = mk.getRevisionHistory(since, maxEntries, path);
-            updateAndLogTimes("getRevisionHistory", start);
+            updateAndLogTimes("getRevisionHistory", start, size(path), size(result));
             return result;
         } catch (Exception e) {
-            logException(e);
             throw convert(e);
         }
     }
@@ -173,12 +159,11 @@ public class TimingWrapper implements Mi
     @Override
     public boolean nodeExists(String path, String revisionId) {
         try {
-            long start = System.currentTimeMillis();
+            long start = now();
             boolean result = mk.nodeExists(path, revisionId);
-            updateAndLogTimes("nodeExists", start);
+            updateAndLogTimes("nodeExists", start, size(path), 0);
             return result;
         } catch (Exception e) {
-            logException(e);
             throw convert(e);
         }
     }
@@ -186,12 +171,11 @@ public class TimingWrapper implements Mi
     @Override
     public long getChildNodeCount(String path, String revisionId) {
         try {
-            long start = System.currentTimeMillis();
+            long start = now();
             long result = mk.getChildNodeCount(path, revisionId);
-            updateAndLogTimes("getChildNodeCount", start);
+            updateAndLogTimes("getChildNodeCount", start, size(path), 0);
             return result;
         } catch (Exception e) {
-            logException(e);
             throw convert(e);
         }
     }
@@ -199,12 +183,11 @@ public class TimingWrapper implements Mi
     @Override
     public int read(String blobId, long pos, byte[] buff, int off, int length) {
         try {
-            long start = System.currentTimeMillis();
+            long start = now();
             int result = mk.read(blobId, pos, buff, off, length);
-            updateAndLogTimes("read", start);
+            updateAndLogTimes("read", start, size(blobId) + length, 0);
             return result;
         } catch (Exception e) {
-            logException(e);
             throw convert(e);
         }
     }
@@ -212,15 +195,13 @@ public class TimingWrapper implements Mi
     @Override
     public String waitForCommit(String oldHeadRevisionId, long maxWaitMillis) throws InterruptedException
{
         try {
-            long start = System.currentTimeMillis();
+            long start = now();
             String result = mk.waitForCommit(oldHeadRevisionId, maxWaitMillis);
-            updateAndLogTimes("waitForCommit", start);
+            updateAndLogTimes("waitForCommit", start, 0, 0);
             return result;
         } catch (InterruptedException e) {
-            logException(e);
             throw e;
         } catch (Exception e) {
-            logException(e);
             throw convert(e);
         }
     }
@@ -228,12 +209,11 @@ public class TimingWrapper implements Mi
     @Override
     public String write(InputStream in) {
         try {
-            long start = System.currentTimeMillis();
+            long start = now();
             String result = mk.write(in);
-            updateAndLogTimes("write", start);
+            updateAndLogTimes("write", start, 0, size(result));
             return result;
         } catch (Exception e) {
-            logException(e);
             throw convert(e);
         }
     }
@@ -241,12 +221,11 @@ public class TimingWrapper implements Mi
     @Override
     public String branch(String trunkRevisionId) {
         try {
-            long start = System.currentTimeMillis();
+            long start = now();
             String result = mk.branch(trunkRevisionId);
-            updateAndLogTimes("branch", start);
+            updateAndLogTimes("branch", start, 0, 0);
             return result;
         } catch (Exception e) {
-            logException(e);
             throw convert(e);
         }
     }
@@ -254,12 +233,11 @@ public class TimingWrapper implements Mi
     @Override
     public String merge(String branchRevisionId, String message) {
         try {
-            long start = System.currentTimeMillis();
+            long start = now();
             String result = mk.merge(branchRevisionId, message);
-            updateAndLogTimes("merge", start);
+            updateAndLogTimes("merge", start, size(message), 0);
             return result;
         } catch (Exception e) {
-            logException(e);
             throw convert(e);
         }
     }
@@ -268,63 +246,76 @@ public class TimingWrapper implements Mi
     @Override
     public String rebase(@Nonnull String branchRevisionId, String newBaseRevisionId) {
         try {
-            long start = System.currentTimeMillis();
+            long start = now();
             String result = mk.rebase(branchRevisionId, newBaseRevisionId);
-            updateAndLogTimes("rebase", start);
+            updateAndLogTimes("rebase", start, 0, 0);
             return result;
         } catch (Exception e) {
-            logException(e);
             throw convert(e);
         }
     }
 
-    public static String quote(Object o) {
-        if (o == null) {
-            return "null";
-        } else if (o instanceof String) {
-            return JsopBuilder.encode((String) o);
-        }
-        return o.toString();
-    }
-
-    private RuntimeException convert(Exception e) {
+    private static RuntimeException convert(Exception e) {
         if (e instanceof RuntimeException) {
             return (RuntimeException) e;
         }
-        log("// unexpected exception type: " + e.getClass().getName());
         return new MicroKernelException("Unexpected exception: " + e.toString(), e);
     }
 
-    private void logException(Exception e) {
-        log("// exception: " + e.toString());
-    }
-    
     private void log(String message) {
         if (DEBUG) {
-            System.out.println(id + " " + message);
+            System.out.println("[" + id + "] " + message);
         }
     }
+    
+    private static int size(String s) {
+        return s == null ? 0 : s.length();
+    }
+    
+    private static long now() {
+        return System.currentTimeMillis();
+    }
 
-    private void updateAndLogTimes(String operation, long start) {
+    private void updateAndLogTimes(String operation, long start, int paramSize, int resultSize)
{
+        long now = now();
         if (startTime == 0) {
-            startTime = System.currentTimeMillis();
+            startTime = now;
         }
-        counts.get(operation).update(System.currentTimeMillis() - start);
-        long now = System.currentTimeMillis();
-        if (now - lastLogTime >= 2000) {
+        Count c = counts.get(operation);
+        if (c == null) {
+            c = new Count();
+            counts.put(operation, c);
+        }
+        c.update(now - start, paramSize, resultSize);
+        long t = now - lastLogTime;
+        if (t >= 2000) {
+            totalLogTime += t;
             lastLogTime = now;
-            for (Entry<String, Count> count : counts.entrySet()) {
-                double c = count.getValue().count;
-                double max = count.getValue().max;
-                double total = count.getValue().total;
-                double avg = total / c;
-                if (c > 0) {
-                    log(count.getKey() + " --> count:" + c + " avg: " + avg
-                            + " max: " + max + " total: " + total);
+            long totalCount = 0, totalTime = 0;
+            for (Count count : counts.values()) {
+                totalCount += count.count;
+                totalTime += count.total;
+            }
+            totalCount = Math.max(1, totalCount);
+            totalTime = Math.max(1, totalTime);
+            for (Entry<String, Count> e : counts.entrySet()) {
+                c = e.getValue();
+                long count = c.count;
+                long total = c.total;
+                long in = c.paramSize / 1024 / 1024;
+                long out = c.resultSize / 1024 / 1024;
+                if (count > 0) {
+                    log(e.getKey() + 
+                            " count " + count + 
+                            " " + (100 * count / totalCount) + "%" +
+                            " in " + in + " out " + out +
+                            " time " + total +
+                            " " + (100 * total / totalTime) + "%");
                 }
             }
-            System.out.println("Time: " + ((now - startTime) / 1000L));
-            System.out.println("------");
+            log("all count " + totalCount + " time " + totalTime + " " + 
+                    (100 * totalTime / totalLogTime) + "%");
+            log("------");
         }
     }
 }

Modified: jackrabbit/oak/trunk/oak-mongomk/src/main/java/org/apache/jackrabbit/mongomk/util/Utils.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-mongomk/src/main/java/org/apache/jackrabbit/mongomk/util/Utils.java?rev=1489729&r1=1489728&r2=1489729&view=diff
==============================================================================
--- jackrabbit/oak/trunk/oak-mongomk/src/main/java/org/apache/jackrabbit/mongomk/util/Utils.java
(original)
+++ jackrabbit/oak/trunk/oak-mongomk/src/main/java/org/apache/jackrabbit/mongomk/util/Utils.java
Wed Jun  5 07:28:31 2013
@@ -186,10 +186,10 @@ public class Utils {
      * Formats a MongoDB document for use in a log message.
      * 
      * @param document the MongoDB document.
-     * @return
+     * @return the formatted string
      */
     public static String formatDocument(Map<String, Object> document) {
-    	return document.toString().replaceAll(", _", ",\n_").replaceAll("}, ", "},\n");
+        return document.toString().replaceAll(", _", ",\n_").replaceAll("}, ", "},\n");
     }
 
 }



Mime
View raw message