You are viewing a plain text version of this content. The canonical link for it is here.
Posted to oak-commits@jackrabbit.apache.org by th...@apache.org on 2013/10/01 10:51:53 UTC
svn commit: r1527974 -
/jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/mongomk/util/TimingDocumentStoreWrapper.java
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("------");
+
}
}