diff --git a/src/main/java/caosdb/server/database/misc/TransactionBenchmark.java b/src/main/java/caosdb/server/database/misc/TransactionBenchmark.java index f0a1fe0008a2f4a2f4552d2a080d1005f34813f6..91bf0acbcd8d8c2affdf0ba48aa7bdb756f34d81 100644 --- a/src/main/java/caosdb/server/database/misc/TransactionBenchmark.java +++ b/src/main/java/caosdb/server/database/misc/TransactionBenchmark.java @@ -28,8 +28,11 @@ import caosdb.server.utils.CronJob; import caosdb.server.utils.Info; import caosdb.server.utils.ServerStat; import java.io.Serializable; +import java.util.ArrayList; +import java.util.Collection; import java.util.Date; import java.util.HashMap; +import java.util.List; import java.util.Locale; import java.util.Map; import java.util.Map.Entry; @@ -71,6 +74,11 @@ class Timer implements Serializable { } } +/** + * The measurement of e.g. a certain action, possibly over multiple runs. A Measurement keeps track + * of how often the action was measured, and what the total and averaged spent time is. One + * Measurement object knows nothing about other Measurement objects. + */ class Measurement implements Serializable { private static final long serialVersionUID = -2429348657382168470L; private final Timer timer; @@ -227,6 +235,8 @@ class JdomConverter { public Element convert(TransactionBenchmark b) { Element ret = new Element(b.getName()); ret.setAttribute("since", new Date(b.since).toString()); + ret.setAttribute("since_ms", Long.toString(b.since)); + ret.setAttribute("called_from", b.called_from()); Iterable<Measurement> measurements = b.getMeasurements(); synchronized (measurements) { @@ -249,8 +259,8 @@ class JdomConverter { /** * The TransactionBenchmark object allows to store the time which some actions take. At its core, it * consists of: - * <li>A list of measurements. - * <li>A list of sub-benchmarks. + * <li>A list of named Measurements. + * <li>A list of named SubBenchmarks. * * <p>Each measurement may be recorded on multiple occasions, the stored Measurement objects * keep a statistic about the total and average recorded times. @@ -264,13 +274,16 @@ public abstract class TransactionBenchmark implements Serializable { Boolean.valueOf( CaosDBServer.getServerProperty(ServerProperties.KEY_TRANSACTION_BENCHMARK_ENABLED) .toLowerCase()); + protected StackTraceElement[] stackTraceElements; long since = System.currentTimeMillis(); protected final Map<String, Measurement> measurements = new HashMap<>(); protected final Map<String, SubBenchmark> subBenchmarks = new HashMap<>(); - protected TransactionBenchmark() {}; + protected TransactionBenchmark() { + stackTraceElements = Thread.currentThread().getStackTrace(); + }; public Iterable<SubBenchmark> getSubBenchmarks() { return this.subBenchmarks.values(); @@ -346,7 +359,8 @@ public abstract class TransactionBenchmark implements Serializable { public Element toElement() { if (isActive) { - return new JdomConverter().convert(this).setName("TransactionBenchmark"); + final Element el = new JdomConverter().convert(this); + return el.setName(el.getName() + ".TransactionBenchmark"); } else { final Element ret = new Element("TransactionBenchmark"); ret.setAttribute("info", "TransactionBenchmark is disabled."); @@ -402,4 +416,50 @@ public abstract class TransactionBenchmark implements Serializable { public TransactionBenchmark createBenchmark(Class<?> class1) { return this.createBenchmark(class1.getSimpleName()); } + + /** Return a String denoting where this TransactionBenchmark was created from. */ + public String called_from() { + final int stackSize = stackTraceElements.length; + if (stackSize <= 5) { + return null; + } + final String[] classComponents = stackTraceElements[0].getClassName().split("\\."); + if (classComponents.length == 0) { + return "unsplittable: " + stackTraceElements[0].getClassName(); + } + final Collection<String> blacklist = List.of("Thread", "Benchmark"); + for (int i = 0; i < stackSize; ++i) { + StackTraceElement ste = stackTraceElements[i]; + final String className = ste.getClassName(); + if (blacklist.stream().anyMatch((blacklistItem) -> className.contains(blacklistItem))) { + continue; + } + + Collection<String> elementStrings = new ArrayList<String>(); + List.of(i, i + 1, i + 2) + .forEach( + (j) -> { + if (j < stackTraceElements.length) { + elementStrings.add(prettifyStackTraceElement(stackTraceElements[j])); + } + }); + return String.join(" / ", elementStrings); + } + return null; + } + + /** + * Return a nice String for the StackTraceElement. + * + * <p>The String is composed like this: CLASS::METHOD [LINE_NUMBER], with "caosdb.server." removed + * from the class name. + */ + private static String prettifyStackTraceElement(final StackTraceElement ste) { + return ste.getClassName().replaceFirst("caosdb\\.server\\.", "") + + "::" + + ste.getMethodName().replaceAll("[<>]", "") + + " [" + + ste.getLineNumber() + + "]"; + } } diff --git a/src/main/java/caosdb/server/resource/transaction/EntityResource.java b/src/main/java/caosdb/server/resource/transaction/EntityResource.java index 0c853096c1af71dcacf2ef775c46f4dceecb1673..8dec9c00986fd3b27c050d39caf5705eb3dceaba 100644 --- a/src/main/java/caosdb/server/resource/transaction/EntityResource.java +++ b/src/main/java/caosdb/server/resource/transaction/EntityResource.java @@ -109,16 +109,30 @@ public class EntityResource extends AbstractCaosDBServerResource { getGetRequestHandler().handle(this, entityContainer); + final long t2 = System.currentTimeMillis(); + entityContainer + .getTransactionBenchmark() + .addMeasurement(getClass().getSimpleName() + ".httpGetInChildClass.handle", t2 - t1); + final Retrieve retrieve = new Retrieve(entityContainer); retrieve.execute(); - final long t2 = System.currentTimeMillis(); + final long t3 = System.currentTimeMillis(); entityContainer .getTransactionBenchmark() - .addMeasurement(getClass().getSimpleName() + ".httpGetInChildClass", t2 - t1); + .addMeasurement( + getClass().getSimpleName() + ".httpGetInChildClass.retrieve.execute", t3 - t2); + final Element rootElem = generateRootElement(); entityContainer.addToElement(rootElem); doc.setRootElement(rootElem); + + final long t4 = System.currentTimeMillis(); + entityContainer + .getTransactionBenchmark() + .addMeasurement( + getClass().getSimpleName() + ".httpGetInChildClass.element_handling", t4 - t3); + return ok(doc); }