[onionoo/master] Add performance metrics to the servlet. - tor-commits

12 Aug 2014

commit 4ac8773be3c5d2296fd3ae293427a33f42d9fe7d
Author: Karsten Loesing karsten.loesing@gmx.net
Date:   Tue Aug 12 09:41:47 2014 +0200
Add performance metrics to the servlet.
Implements #12655.
---
 .../onionoo/server/PerformanceMetrics.java         |  198 +++++++++++++++++++
 .../torproject/onionoo/server/ResourceServlet.java |   12 ++
 .../torproject/onionoo/server/ResponseBuilder.java |   27 ++-
 .../onionoo/server/PerformanceMetricsTest.java     |  199 ++++++++++++++++++++
 4 files changed, 430 insertions(+), 6 deletions(-)

diff --git a/src/main/java/org/torproject/onionoo/server/PerformanceMetrics.java b/src/main/java/org/torproject/onionoo/server/PerformanceMetrics.java
new file mode 100644
index 0000000..5f780d9
--- /dev/null
+++ b/src/main/java/org/torproject/onionoo/server/PerformanceMetrics.java
@@ -0,0 +1,198 @@
+/* Copyright 2014 The Tor Project
+ * See LICENSE for licensing information */
+package org.torproject.onionoo.server;
+
+import java.util.Arrays;
+import java.util.Collection;
+import java.util.Collections;
+import java.util.HashMap;
+import java.util.Map;
+import java.util.SortedMap;
+import java.util.SortedSet;
+import java.util.TreeMap;
+import java.util.TreeSet;
+
+import org.torproject.onionoo.util.ApplicationFactory;
+import org.torproject.onionoo.util.DateTimeHelper;
+import org.torproject.onionoo.util.Time;
+
+class Counter {
+  int value = 0;
+  void increment() {
+    this.value++;
+  }
+  public String toString() {
+    return String.valueOf(this.value);
+  }
+  void clear() {
+    this.value = 0;
+  }
+}
+
+class MostFrequentString {
+  Map<String, Integer> stringFrequencies = new HashMap<String, Integer>();
+  void addString(String string) {
+    if (!this.stringFrequencies.containsKey(string)) {
+      this.stringFrequencies.put(string, 1);
+    } else {
+      this.stringFrequencies.put(string,
+          this.stringFrequencies.get(string) + 1);
+    }
+  }
+  public String toString() {
+    SortedMap<Integer, SortedSet<String>> sortedFrequencies =
+        new TreeMap<Integer, SortedSet<String>>(
+        Collections.reverseOrder());
+    if (this.stringFrequencies.isEmpty()) {
+      return "null (0)";
+    }
+    for (Map.Entry<String, Integer> e : stringFrequencies.entrySet()) {
+      if (!sortedFrequencies.containsKey(e.getValue())) {
+        sortedFrequencies.put(e.getValue(), new TreeSet<String>(
+            Arrays.asList(new String[] { e.getKey() } )));
+      } else {
+        sortedFrequencies.get(e.getValue()).add(e.getKey());
+      }
+    }
+    StringBuilder sb = new StringBuilder();
+    int stringsToAdd = 3, written = 0;
+    for (Map.Entry<Integer, SortedSet<String>> e :
+        sortedFrequencies.entrySet()) {
+      for (String string : e.getValue()) {
+        if (stringsToAdd-- > 0) {
+          sb.append((written++ > 0 ? ", " : "") + string + " ("
+              + e.getKey() + ")");
+        }
+      }
+      if (stringsToAdd == 0) {
+        break;
+      }
+    }
+    return sb.toString();
+  }
+  void clear() {
+    this.stringFrequencies.clear();
+  }
+}
+
+class IntegerDistribution {
+  int[] logValues = new int[64];
+  void addLong(long value) {
+    logValues[64 - Long.numberOfLeadingZeros(value)]++;
+  }
+  public String toString() {
+    StringBuilder sb = new StringBuilder();
+    int totalValues = 0;
+    for (int i = 0; i < logValues.length; i++) {
+      totalValues += logValues[i];
+    }
+    int[] permilles = new int[] { 500, 900, 990, 999 };
+    if (totalValues > 0) {
+      int seenValues = 0;
+      for (int i = 0, j = 0; i < logValues.length; i++) {
+        seenValues += logValues[i];
+        while (j < permilles.length &&
+            (seenValues * 1000 > totalValues * permilles[j])) {
+          sb.append((j > 0 ? ", " : "") + "." + permilles[j]
+              + (i < logValues.length - 1 ? "<" + (1L << i)
+              : ">=" + (1L << i - 1)));
+          j++;
+        }
+        if (j == permilles.length) {
+          break;
+        }
+      }
+    } else {
+      for (int j = 0; j < permilles.length; j++) {
+        sb.append((j > 0 ? ", " : "") + "." + permilles[j] + "<null");
+      }
+    }
+    return sb.toString();
+  }
+  void clear() {
+    Arrays.fill(logValues, 0, logValues.length - 1, 0);
+  }
+}
+
+public class PerformanceMetrics {
+
+  private static final Object lock = new Object();
+
+  private static Time time;
+
+  private static long lastLoggedMillis = -1L;
+
+  private static final long LOG_INTERVAL = DateTimeHelper.ONE_HOUR;
+
+  private static Counter totalProcessedRequests = new Counter();
+
+  private static MostFrequentString
+      requestsByResourceType = new MostFrequentString(),
+      requestsByParameters = new MostFrequentString();
+
+  private static IntegerDistribution
+      matchingRelayDocuments = new IntegerDistribution(),
+      matchingBridgeDocuments = new IntegerDistribution(),
+      writtenChars = new IntegerDistribution(),
+      handleRequestMillis = new IntegerDistribution(),
+      buildResponseMillis = new IntegerDistribution();
+
+  public static void logStatistics(long receivedRequestMillis,
+      String resourceType, Collection<String> parameterKeys,
+      long parsedRequestMillis, int relayDocumentsWritten,
+      int bridgeDocumentsWritten, int charsWritten,
+      long writtenResponseMillis) {
+    synchronized (lock) {
+      if (time == null) {
+        time = ApplicationFactory.getTime();
+      }
+      if (lastLoggedMillis < 0L) {
+        lastLoggedMillis = time.currentTimeMillis();
+      } else if (receivedRequestMillis - lastLoggedMillis >
+          LOG_INTERVAL) {
+        System.err.println("Request statistics ("
+            + DateTimeHelper.format(lastLoggedMillis + LOG_INTERVAL)
+            + ", " + LOG_INTERVAL + " s):");
+        System.err.println("  Total processed requests: "
+            + totalProcessedRequests);
+        System.err.println("  Most frequently requested resource: "
+            + requestsByResourceType);
+        System.err.println("  Most frequently requested parameter "
+            + "combinations: " + requestsByParameters);
+        System.err.println("  Matching relays per request: "
+            + matchingRelayDocuments);
+        System.err.println("  Matching bridges per request: "
+            + matchingBridgeDocuments);
+        System.err.println("  Written characters per response: "
+            + writtenChars);
+        System.err.println("  Milliseconds to handle request: "
+            + handleRequestMillis);
+        System.err.println("  Milliseconds to build response: "
+            + buildResponseMillis);
+        totalProcessedRequests.clear();
+        requestsByResourceType.clear();
+        requestsByParameters.clear();
+        matchingRelayDocuments.clear();
+        matchingBridgeDocuments.clear();
+        writtenChars.clear();
+        handleRequestMillis.clear();
+        buildResponseMillis.clear();
+        do {
+          lastLoggedMillis += LOG_INTERVAL;
+        } while (receivedRequestMillis - lastLoggedMillis > LOG_INTERVAL);
+      }
+      totalProcessedRequests.increment();
+      handleRequestMillis.addLong(parsedRequestMillis
+          - receivedRequestMillis);
+      requestsByResourceType.addString(resourceType);
+      requestsByParameters.addString(parameterKeys.toString());
+      matchingRelayDocuments.addLong(relayDocumentsWritten);
+      matchingBridgeDocuments.addLong(bridgeDocumentsWritten);
+      writtenChars.addLong(charsWritten);
+      buildResponseMillis.addLong(writtenResponseMillis
+          - parsedRequestMillis);
+    }
+  }
+
+}
+
diff --git a/src/main/java/org/torproject/onionoo/server/ResourceServlet.java b/src/main/java/org/torproject/onionoo/server/ResourceServlet.java
index 6f01448..481462e 100644
--- a/src/main/java/org/torproject/onionoo/server/ResourceServlet.java
+++ b/src/main/java/org/torproject/onionoo/server/ResourceServlet.java
@@ -19,6 +19,7 @@ import javax.servlet.http.HttpServletResponse;
import org.torproject.onionoo.util.ApplicationFactory;
 import org.torproject.onionoo.util.DateTimeHelper;
+import org.torproject.onionoo.util.Time;
public class ResourceServlet extends HttpServlet {
@@ -74,6 +75,9 @@ public class ResourceServlet extends HttpServlet {
       return;
     }
+    Time time = ApplicationFactory.getTime();
+    long receivedRequestMillis = time.currentTimeMillis();
+
     String uri = request.getRequestURI();
     if (uri.startsWith("/onionoo/")) {
       uri = uri.substring("/onionoo".length());
@@ -279,6 +283,7 @@ public class ResourceServlet extends HttpServlet {
       rh.setFamily(family);
     }
     rh.handleRequest();
+    long parsedRequestMillis = time.currentTimeMillis();
ResponseBuilder rb = new ResponseBuilder();
     rb.setResourceType(resourceType);
@@ -301,8 +306,15 @@ public class ResourceServlet extends HttpServlet {
     response.setCharacterEncoding("utf-8");
     PrintWriter pw = response.getWriter();
     rb.buildResponse(pw);
+    int relayDocumentsWritten = rh.getOrderedRelays().size();
+    int bridgeDocumentsWritten = rh.getOrderedBridges().size();
+    int charsWritten = rb.getCharsWritten();
     pw.flush();
     pw.close();
+    long writtenResponseMillis = time.currentTimeMillis();
+    PerformanceMetrics.logStatistics(receivedRequestMillis, resourceType,
+        parameterMap.keySet(), parsedRequestMillis, relayDocumentsWritten,
+        bridgeDocumentsWritten, charsWritten, writtenResponseMillis);
   }
private static Pattern searchParameterPattern =
diff --git a/src/main/java/org/torproject/onionoo/server/ResponseBuilder.java b/src/main/java/org/torproject/onionoo/server/ResponseBuilder.java
index 161692c..458f7db 100644
--- a/src/main/java/org/torproject/onionoo/server/ResponseBuilder.java
+++ b/src/main/java/org/torproject/onionoo/server/ResponseBuilder.java
@@ -64,31 +64,46 @@ public class ResponseBuilder {
     writeBridges(orderedBridges, pw);
   }
+  private int charsWritten = 0;
+  public int getCharsWritten() {
+    return this.charsWritten;
+  }
+
   private void writeRelays(List<SummaryDocument> relays, PrintWriter pw) {
-    pw.write("{"relays_published":"" + relaysPublishedString
-        + "",\n"relays":[");
+    String header = "{"relays_published":"" + relaysPublishedString
+        + "",\n"relays":[";
+    this.charsWritten += header.length();
+    pw.write(header);
     int written = 0;
     for (SummaryDocument entry : relays) {
       String lines = this.formatNodeStatus(entry);
       if (lines.length() > 0) {
+        this.charsWritten += (written > 0 ? 2 : 1) + lines.length();
         pw.print((written++ > 0 ? ",\n" : "\n") + lines);
       }
     }
-    pw.print("\n],\n");
+    String footer = "\n],\n";
+    this.charsWritten += footer.length();
+    pw.print(footer);
   }
private void writeBridges(List<SummaryDocument> bridges,
       PrintWriter pw) {
-    pw.write(""bridges_published":"" + bridgesPublishedString
-        + "",\n"bridges":[");
+    String header = ""bridges_published":"" + bridgesPublishedString
+        + "",\n"bridges":[";
+    this.charsWritten += header.length();
+    pw.write(header);
     int written = 0;
     for (SummaryDocument entry : bridges) {
       String lines = this.formatNodeStatus(entry);
       if (lines.length() > 0) {
+        this.charsWritten += (written > 0 ? 2 : 1) + lines.length();
         pw.print((written++ > 0 ? ",\n" : "\n") + lines);
       }
     }
-    pw.print("\n]}\n");
+    String footer = "\n]}\n";
+    this.charsWritten += footer.length();
+    pw.print(footer);
   }
private String formatNodeStatus(SummaryDocument entry) {
diff --git a/src/test/java/org/torproject/onionoo/server/PerformanceMetricsTest.java b/src/test/java/org/torproject/onionoo/server/PerformanceMetricsTest.java
new file mode 100644
index 0000000..7a6614e
--- /dev/null
+++ b/src/test/java/org/torproject/onionoo/server/PerformanceMetricsTest.java
@@ -0,0 +1,199 @@
+/* Copyright 2014 The Tor Project
+ * See LICENSE for licensing information */
+package org.torproject.onionoo.server;
+
+import static org.junit.Assert.assertEquals;
+
+import org.junit.Test;
+
+public class PerformanceMetricsTest {
+
+  @Test
+  public void testCounterZero() {
+    Counter c = new Counter();
+    assertEquals("0", c.toString());
+  }
+
+  @Test
+  public void testCounterClear() {
+    Counter c = new Counter();
+    c.increment();
+    c.clear();
+    assertEquals("0", c.toString());
+  }
+
+  @Test
+  public void testCounterOne() {
+    Counter c = new Counter();
+    c.increment();
+    assertEquals("1", c.toString());
+  }
+
+  @Test
+  public void testCounterTwo() {
+    Counter c = new Counter();
+    c.increment();
+    c.increment();
+    assertEquals("2", c.toString());
+  }
+
+  @Test
+  public void testCounterOverflow() {
+    Counter c = new Counter();
+    c.value = Integer.MAX_VALUE;
+    c.increment();
+    assertEquals(String.valueOf(Integer.MIN_VALUE), c.toString());
+  }
+
+  @Test
+  public void testMostFrequentStringNothing() {
+    MostFrequentString mfs = new MostFrequentString();
+    assertEquals("null (0)", mfs.toString());
+  }
+
+  @Test
+  public void testMostFrequentStringClear() {
+    MostFrequentString mfs = new MostFrequentString();
+    mfs.addString("foo");
+    mfs.clear();
+    assertEquals("null (0)", mfs.toString());
+  }
+
+  @Test
+  public void testMostFrequentStringOneFoo() {
+    MostFrequentString mfs = new MostFrequentString();
+    mfs.addString("foo");
+    assertEquals("foo (1)", mfs.toString());
+  }
+
+  @Test
+  public void testMostFrequentStringTwoFoos() {
+    MostFrequentString mfs = new MostFrequentString();
+    mfs.addString("foo");
+    mfs.addString("foo");
+    assertEquals("foo (2)", mfs.toString());
+  }
+
+  @Test
+  public void testMostFrequentStringTwoFoosOneBar() {
+    MostFrequentString mfs = new MostFrequentString();
+    mfs.addString("foo");
+    mfs.addString("foo");
+    mfs.addString("bar");
+    assertEquals("foo (2), bar (1)", mfs.toString());
+  }
+
+  @Test
+  public void testMostFrequentStringABCD() {
+    MostFrequentString mfs = new MostFrequentString();
+    mfs.addString("A");
+    mfs.addString("B");
+    mfs.addString("C");
+    mfs.addString("D");
+    assertEquals("A (1), B (1), C (1)", mfs.toString());
+  }
+
+  @Test
+  public void testIntegerDistributionNothing() {
+    IntegerDistribution id = new IntegerDistribution();
+    assertEquals(".500<null, .900<null, .990<null, .999<null",
+        id.toString());
+  }
+
+  @Test
+  public void testIntegerDistributionClear() {
+    IntegerDistribution id = new IntegerDistribution();
+    id.addLong(1);
+    id.clear();
+    assertEquals(".500<null, .900<null, .990<null, .999<null",
+        id.toString());
+  }
+
+  @Test
+  public void testIntegerDistributionZero() {
+    IntegerDistribution id = new IntegerDistribution();
+    id.addLong(0);
+    assertEquals(".500<1, .900<1, .990<1, .999<1", id.toString());
+  }
+
+  @Test
+  public void testIntegerDistributionOne() {
+    IntegerDistribution id = new IntegerDistribution();
+    id.addLong(1);
+    assertEquals(".500<2, .900<2, .990<2, .999<2", id.toString());
+  }
+
+  @Test
+  public void testIntegerDistributionTwo() {
+    IntegerDistribution id = new IntegerDistribution();
+    id.addLong(2);
+    assertEquals(".500<4, .900<4, .990<4, .999<4", id.toString());
+  }
+
+  @Test
+  public void testIntegerDistributionThree() {
+    IntegerDistribution id = new IntegerDistribution();
+    id.addLong(3);
+    assertEquals(".500<4, .900<4, .990<4, .999<4", id.toString());
+  }
+
+  @Test
+  public void testIntegerDistributionFour() {
+    IntegerDistribution id = new IntegerDistribution();
+    id.addLong(4);
+    assertEquals(".500<8, .900<8, .990<8, .999<8", id.toString());
+  }
+
+  @Test
+  public void testIntegerDistributionFive() {
+    IntegerDistribution id = new IntegerDistribution();
+    id.addLong(5);
+    assertEquals(".500<8, .900<8, .990<8, .999<8", id.toString());
+  }
+
+  @Test
+  public void testIntegerDistributionFifteen() {
+    IntegerDistribution id = new IntegerDistribution();
+    id.addLong(15);
+    assertEquals(".500<16, .900<16, .990<16, .999<16", id.toString());
+  }
+
+  @Test
+  public void testIntegerDistributionSixteen() {
+    IntegerDistribution id = new IntegerDistribution();
+    id.addLong(16);
+    assertEquals(".500<32, .900<32, .990<32, .999<32", id.toString());
+  }
+
+  @Test
+  public void testIntegerDistributionSeventeen() {
+    IntegerDistribution id = new IntegerDistribution();
+    id.addLong(17);
+    assertEquals(".500<32, .900<32, .990<32, .999<32", id.toString());
+  }
+
+  @Test
+  public void testIntegerDistributionMaxLong() {
+    IntegerDistribution id = new IntegerDistribution();
+    id.addLong(Long.MAX_VALUE);
+    long val = Long.highestOneBit(Long.MAX_VALUE);
+    assertEquals(".500>=" + val + ", .900>=" + val + ", .990>=" + val
+        + ", .999>=" + val, id.toString());
+  }
+
+  @Test
+  public void testIntegerDistributionToThirtyTwo() {
+    IntegerDistribution id = new IntegerDistribution();
+    for (int i = 13; i <= 32; i++) id.addLong(i);
+    assertEquals(".500<32, .900<32, .990<64, .999<64", id.toString());
+  }
+
+  @Test
+  public void testIntegerDistributionToOneHundredTwentyEight() {
+    IntegerDistribution id = new IntegerDistribution();
+    for (int i = 27; i <= 128; i++) id.addLong(i);
+    assertEquals(".500<128, .900<128, .990<128, .999<256",
+        id.toString());
+  }
+}
+

    