jackrabbit-oak-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From thom...@apache.org
Subject svn commit: r1527974 - /jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/mongomk/util/TimingDocumentStoreWrapper.java
Date Tue, 01 Oct 2013 08:51:53 GMT
Author: thomasm
Date: Tue Oct  1 08:51:53 2013
New Revision: 1527974

URL: http://svn.apache.org/r1527974
Log:
OAK-641: Improved benchmark tooling - Log common slow calls in TimingDocumentWrappers

Modified:
    jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/mongomk/util/TimingDocumentStoreWrapper.java

Modified: jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/mongomk/util/TimingDocumentStoreWrapper.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/mongomk/util/TimingDocumentStoreWrapper.java?rev=1527974&r1=1527973&r2=1527974&view=diff
==============================================================================
--- jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/mongomk/util/TimingDocumentStoreWrapper.java
(original)
+++ jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/mongomk/util/TimingDocumentStoreWrapper.java
Tue Oct  1 08:51:53 2013
@@ -17,6 +17,7 @@
 package org.apache.jackrabbit.oak.plugins.mongomk.util;
 
 import java.util.HashMap;
+import java.util.Iterator;
 import java.util.List;
 import java.util.Map;
 import java.util.Map.Entry;
@@ -48,6 +49,9 @@ public class TimingDocumentStoreWrapper 
     private final Map<String, Count> counts = new HashMap<String, Count>();
     private long lastLogTime;
     private long totalLogTime;
+    private final HashMap<String, Integer> commonCalls = new HashMap<String, Integer>();
+    
+    private int callCount;
 
     /**
      * A class that keeps track of timing data and call counts.
@@ -75,6 +79,10 @@ public class TimingDocumentStoreWrapper 
         lastLogTime = now();
     }
     
+    private boolean logCommonCall() {
+        return callCount % 10 == 0;
+    }
+    
     @Override
     @CheckForNull
     public <T extends Document> T find(Collection<T> collection, String key)
{
@@ -82,6 +90,9 @@ public class TimingDocumentStoreWrapper 
             long start = now();
             T result = base.find(collection, key);
             updateAndLogTimes("find", start, 0, size(result));
+            if (logCommonCall()) {
+                logCommonCall(start, "find " + collection + " " + key);
+            }
             return result;
         } catch (Exception e) {
             throw convert(e);
@@ -95,6 +106,9 @@ public class TimingDocumentStoreWrapper 
             long start = now();
             T result = base.find(collection, key, maxCacheAge);
             updateAndLogTimes("find2", start, 0, size(result));
+            if (logCommonCall()) {
+                logCommonCall(start, "find2 " + collection + " " + key);
+            }
             return result;
         } catch (Exception e) {
             throw convert(e);
@@ -111,6 +125,9 @@ public class TimingDocumentStoreWrapper 
             long start = now();
             List<T> result = base.query(collection, fromKey, toKey, limit);
             updateAndLogTimes("query", start, 0, size(result));
+            if (logCommonCall()) {
+                logCommonCall(start, "query " + collection + " " + fromKey + " " + toKey
+ " " + limit);
+            }
             return result;
         } catch (Exception e) {
             throw convert(e);
@@ -129,6 +146,9 @@ public class TimingDocumentStoreWrapper 
             long start = now();
             List<T> result = base.query(collection, fromKey, toKey, indexedProperty,
startValue, limit);
             updateAndLogTimes("query2", start, 0, size(result));
+            if (logCommonCall()) {
+                logCommonCall(start, "query2 " + collection + " " + fromKey + " " + toKey
+ " " + indexedProperty + " " + startValue + " " + limit);
+            }
             return result;
         } catch (Exception e) {
             throw convert(e);
@@ -141,6 +161,9 @@ public class TimingDocumentStoreWrapper 
             long start = now();
             base.remove(collection, key);
             updateAndLogTimes("remove", start, 0, 0);
+            if (logCommonCall()) {
+                logCommonCall(start, "remove " + collection + " " + key);
+            }
         } catch (Exception e) {
             throw convert(e);
         }
@@ -152,6 +175,9 @@ public class TimingDocumentStoreWrapper 
             long start = now();
             boolean result = base.create(collection, updateOps);
             updateAndLogTimes("create", start, 0, 0);
+            if (logCommonCall()) {
+                logCommonCall(start, "create " + collection);
+            }
             return result;
         } catch (Exception e) {
             throw convert(e);
@@ -166,6 +192,9 @@ public class TimingDocumentStoreWrapper 
             long start = now();
             T result = base.createOrUpdate(collection, update);
             updateAndLogTimes("createOrUpdate", start, 0, size(result));
+            if (logCommonCall()) {
+                logCommonCall(start, "createOrUpdate " + collection + " " + update.getId());
+            }
             return result;
         } catch (Exception e) {
             throw convert(e);
@@ -180,6 +209,9 @@ public class TimingDocumentStoreWrapper 
             long start = now();
             T result = base.findAndUpdate(collection, update);
             updateAndLogTimes("findAndUpdate", start, 0, size(result));
+            if (logCommonCall()) {
+                logCommonCall(start, "findAndUpdate " + collection + " " + update.getId());
+            }
             return result;
         } catch (Exception e) {
             throw convert(e);
@@ -230,6 +262,33 @@ public class TimingDocumentStoreWrapper 
             throw convert(e);
         }
     }
+    
+    private synchronized void logCommonCall(long start, String key) {
+        int time = (int) (System.currentTimeMillis() - start);
+        if (time <= 0) {
+            return;
+        }
+        HashMap<String, Integer> map = commonCalls;
+        Integer oldCount = map.get(key);
+        if (oldCount == null) {
+            map.put(key, time);
+        } else {
+            map.put(key, oldCount + time);
+        }
+        int maxElements = 1000;
+        int minCount = 1;
+        while (map.size() > maxElements) {
+            for (Iterator<Map.Entry<String, Integer>> ei = map.entrySet().iterator();
ei.hasNext();) {
+                Map.Entry<String, Integer> e = ei.next();
+                if (e.getValue() <= minCount) {
+                    ei.remove();
+                }
+            }
+            if (map.size() > maxElements) {
+                minCount++;
+            }
+        }
+    }
 
     private static RuntimeException convert(Exception e) {
         if (e instanceof RuntimeException) {
@@ -276,7 +335,7 @@ public class TimingDocumentStoreWrapper 
         }
         c.update(now - start, paramSize, resultSize);
         long t = now - lastLogTime;
-        if (t >= 2000) {
+        if (t >= 10000) {
             totalLogTime += t;
             lastLogTime = now;
             long totalCount = 0, totalTime = 0;
@@ -303,7 +362,32 @@ public class TimingDocumentStoreWrapper 
             }
             log("all count " + totalCount + " time " + totalTime + " " + 
                     (100 * totalTime / totalLogTime) + "%");
+
+            HashMap<String, Integer> map = commonCalls;
+            int top = 10;
+            int max = Integer.MAX_VALUE;
+            for (int i = 0; i < top;) {
+                int best = 0;
+                for (int x : map.values()) {
+                    if (x < max && x > best) {
+                        best = x;
+                    }
+                }
+                for (Entry<String, Integer> e : map.entrySet()) {
+                    if (e.getValue() >= best && e.getValue() < max) {
+                        log("common call " + e.getValue() + " " + e.getKey());
+                        i++;
+                        if (i >= top) {
+                            break;
+                        }
+                    }
+                }
+                max = best;
+            }
+            commonCalls.clear();
+            
             log("------");
+            
         }
     }
     



Mime
View raw message