ENH: Better Benchmark output.

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()
+        + "]";
+  }
 }

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);
   }