hide serialization stats recording behind flag (off by default) (#70)

* hide serialization stats recording behind flag (off by default)

* use nanos in both serializer and deserializer

* refactor: extract common stats code to BookKeeper

* System.nanoTime is relatively expensive - only call if necessary

Author: mpollmeier

tinkerpop3/src/main/java/io/shiftleft/overflowdb/OdbConfig.java

@@ -6,6 +6,7 @@ public class OdbConfig {
   private boolean overflowEnabled = true;
   private int heapPercentageThreshold = 80;
   private Optional<String> storageLocation = Optional.empty();
+  private boolean serializationStatsEnabled = false;
 
   public static OdbConfig withDefaults() {
     return new OdbConfig();
@@ -37,6 +38,12 @@ public OdbConfig withStorageLocation(String path) {
     return this;
   }
 
+  /* If specified, OdbGraph will measure and report serialization / deserialization timing averages. */
+  public OdbConfig withSerializationStatsEnabled() {
+    this.serializationStatsEnabled = true;
+    return this;
+  }
+
   public boolean isOverflowEnabled() {
     return overflowEnabled;
   }
@@ -48,4 +55,8 @@ public int getHeapPercentageThreshold() {
   public Optional<String> getStorageLocation() {
     return storageLocation;
   }
+
+  public boolean isSerializationStatsEnabled() {
+    return serializationStatsEnabled;
+  }
 }

tinkerpop3/src/main/java/io/shiftleft/overflowdb/OdbGraph.java

@@ -95,12 +95,17 @@ private OdbGraph(OdbConfig config,
         Optional.of(new HeapUsageMonitor(config.getHeapPercentageThreshold(), referenceManager)) :
         Optional.empty();
 
-    NodeDeserializer nodeDeserializer = new NodeDeserializer(this, nodeFactoryByLabelId);
+    NodeDeserializer nodeDeserializer = new NodeDeserializer(
+        this, nodeFactoryByLabelId, config.isSerializationStatsEnabled());
     if (config.getStorageLocation().isPresent()) {
-      storage = OdbStorage.createWithSpecificLocation(nodeDeserializer, new File(config.getStorageLocation().get()));
+      storage = OdbStorage.createWithSpecificLocation(
+          nodeDeserializer,
+          new File(config.getStorageLocation().get()),
+          config.isSerializationStatsEnabled()
+      );
       initElementCollections(storage);
     } else {
-      storage = OdbStorage.createWithTempFile(nodeDeserializer);
+      storage = OdbStorage.createWithTempFile(nodeDeserializer, config.isSerializationStatsEnabled());
       initEmptyElementCollections();
     }
   }

tinkerpop3/src/main/java/io/shiftleft/overflowdb/storage/BookKeeper.java

@@ -0,0 +1,34 @@
+package io.shiftleft.overflowdb.storage;
+
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+public abstract class BookKeeper {
+  protected final Logger logger = LoggerFactory.getLogger(getClass());
+  public final boolean statsEnabled;
+  private int totalCount = 0;
+  private long totalTimeSpentNanos = 0;
+
+  protected BookKeeper(boolean statsEnabled) {
+    this.statsEnabled = statsEnabled;
+  }
+
+  protected final long getStartTimeNanos() {
+    // System.nanoTime is relatively expensive - only  go there if we're actually recording stats
+    return statsEnabled ? System.nanoTime() : 0;
+  }
+
+  protected void recordStatistics(long startTimeNanos) {
+    totalCount++;
+    totalTimeSpentNanos += System.nanoTime() - startTimeNanos;
+    if (0 == (totalCount & 0x0001ffff)) {
+      float avgSerializationTime = 1.0f-6 * totalTimeSpentNanos / (float) totalCount;
+      logger.debug("stats: handled " + totalCount + " nodes in total (avg time: " + avgSerializationTime + "ms)");
+    }
+  }
+
+  public final int getSerializedCount() {
+    if (statsEnabled) return totalCount;
+    else throw new RuntimeException("serialization statistics not enabled");
+  }
+}

tinkerpop3/src/main/java/io/shiftleft/overflowdb/storage/NodeDeserializer.java

@@ -22,31 +22,25 @@
 import java.util.Map;
 import java.util.concurrent.ConcurrentHashMap;
 
-public class NodeDeserializer {
-  private final Logger logger = LoggerFactory.getLogger(getClass());
+public class NodeDeserializer extends BookKeeper {
   protected final OdbGraph graph;
   private final Map<Integer, NodeFactory> nodeFactoryByLabelId;
-  private int deserializedCount = 0;
-  private long deserializationTimeSpentNanos = 0;
   private ConcurrentHashMap<String, String> interner;
 
-
-  public NodeDeserializer(OdbGraph graph, Map<Integer, NodeFactory> nodeFactoryByLabelId) {
+  public NodeDeserializer(OdbGraph graph, Map<Integer, NodeFactory> nodeFactoryByLabelId, boolean statsEnabled) {
+    super(statsEnabled);
     this.graph = graph;
     this.nodeFactoryByLabelId = nodeFactoryByLabelId;
-    this.interner = new ConcurrentHashMap<String, String>();
+    this.interner = new ConcurrentHashMap<>();
   }
 
   private final String intern(String s){
     String interned = interner.putIfAbsent(s, s);
     return interned == null ? s : interned;
   }
 
-
   public final OdbNode deserialize(byte[] bytes) throws IOException {
-    // todo: only time when some config is set
-
-    long start = System.nanoTime();
+    long startTimeNanos = getStartTimeNanos();
     if (null == bytes)
       return null;
 
@@ -59,12 +53,7 @@ public final OdbNode deserialize(byte[] bytes) throws IOException {
 
     OdbNode node = createNode(id, labelId, properties, edgeOffsets, adjacentNodesWithProperties);
 
-    deserializedCount++;
-    deserializationTimeSpentNanos += System.nanoTime() - start;
-    if (0 == (deserializedCount & 0x0001ffff)) {
-      float avgDeserializationTime = 1.0f-6 * deserializationTimeSpentNanos / (float) deserializedCount;
-      logger.debug("stats: deserialized " + deserializedCount + " nodes in total (avg time: " + avgDeserializationTime + "ms)");
-    }
+    if (statsEnabled) recordStatistics(startTimeNanos);
     return node;
   }
 

tinkerpop3/src/main/java/io/shiftleft/overflowdb/storage/NodeSerializer.java

@@ -6,22 +6,19 @@
 import org.apache.commons.lang3.NotImplementedException;
 import org.msgpack.core.MessageBufferPacker;
 import org.msgpack.core.MessagePack;
-import org.slf4j.Logger;
-import org.slf4j.LoggerFactory;
 
 import java.io.IOException;
 import java.util.Iterator;
 import java.util.List;
 import java.util.Map;
 
-public class NodeSerializer {
-
-  private final Logger logger = LoggerFactory.getLogger(getClass());
-  private int serializedCount = 0;
-  private long serializationTimeSpentMillis = 0;
+public class NodeSerializer extends BookKeeper {
+  public NodeSerializer(boolean statsEnabled) {
+    super(statsEnabled);
+  }
 
   public byte[] serialize(OdbNode node) throws IOException {
-    long start = System.currentTimeMillis();
+    long startTimeNanos = getStartTimeNanos();
     try (MessageBufferPacker packer = MessagePack.newDefaultBufferPacker()) {
       /* marking as clean *before* we start serializing - if node is modified any time afterwards it'll be marked as dirty */
       node.markAsClean();
@@ -33,12 +30,7 @@ public byte[] serialize(OdbNode node) throws IOException {
       packEdgeOffsets(packer, node.getEdgeOffsetsPackedArray());
       packAdjacentNodesWithProperties(packer, node.getAdjacentNodesWithProperties());
 
-      serializedCount++;
-      serializationTimeSpentMillis += System.currentTimeMillis() - start;
-      if (serializedCount % 131072 == 0) { //2^17
-        float avgSerializationTime = serializationTimeSpentMillis / (float) serializedCount;
-        logger.debug("stats: serialized " + serializedCount + " instances in total (avg time: " + avgSerializationTime + "ms)");
-      }
+      if (statsEnabled) recordStatistics(startTimeNanos);
       return packer.toByteArray();
     }
   }
@@ -120,7 +112,4 @@ private void packTypedValue(final MessageBufferPacker packer, final Object value
     }
   }
 
-  public final int getSerializedCount() {
-    return serializedCount;
-  }
 }

tinkerpop3/src/main/java/io/shiftleft/overflowdb/storage/OdbStorage.java

@@ -17,38 +17,41 @@
 public class OdbStorage implements AutoCloseable {
   private static final String INDEX_PREFIX = "index_";
   private final Logger logger = LoggerFactory.getLogger(getClass());
-  protected final NodeSerializer nodeSerializer = new NodeSerializer();
+  protected final NodeSerializer nodeSerializer;
   protected final Optional<NodeDeserializer> nodeDeserializer;
 
   private final File mvstoreFile;
   private MVStore mvstore; // initialized in `getNodesMVMap`
   private MVMap<Long, byte[]> nodesMVMap;
   private boolean closed;
 
-  public static OdbStorage createWithTempFile(final NodeDeserializer nodeDeserializer) {
-    return new OdbStorage(Optional.empty(), Optional.ofNullable(nodeDeserializer));
+  public static OdbStorage createWithTempFile(
+      final NodeDeserializer nodeDeserializer, final boolean enableSerializationStats) {
+    return new OdbStorage(Optional.empty(), Optional.ofNullable(nodeDeserializer), enableSerializationStats);
   }
 
   /**
    * create with specific mvstore file - which may or may not yet exist.
    * mvstoreFile won't be deleted at the end (unlike temp file constructors above)
    */
   public static OdbStorage createWithSpecificLocation(
-      final NodeDeserializer nodeDeserializer, final File mvstoreFile) {
-    return new OdbStorage(Optional.ofNullable(mvstoreFile), Optional.ofNullable(nodeDeserializer));
+      final NodeDeserializer nodeDeserializer, final File mvstoreFile, final boolean enableSerializationStats) {
+    return new OdbStorage(Optional.ofNullable(mvstoreFile), Optional.ofNullable(nodeDeserializer), enableSerializationStats);
   }
 
   /**
    * create with specific mvstore file - which may or may not yet exist.
    * mvstoreFile won't be deleted at the end (unlike temp file constructors above)
    */
-  public static OdbStorage createWithSpecificLocation(final File mvstoreFile) {
-    return new OdbStorage(Optional.ofNullable(mvstoreFile), Optional.empty());
+  public static OdbStorage createWithSpecificLocation(final File mvstoreFile, final boolean enableSerializationStats) {
+    return new OdbStorage(Optional.ofNullable(mvstoreFile), Optional.empty(), enableSerializationStats);
   }
 
   private OdbStorage(
       final Optional<File> mvstoreFileMaybe,
-      final Optional<NodeDeserializer> nodeDeserializer) {
+      final Optional<NodeDeserializer> nodeDeserializer,
+      final boolean enableSerializationStats) {
+    this.nodeSerializer = new NodeSerializer(enableSerializationStats);
     this.nodeDeserializer = nodeDeserializer;
 
     if (mvstoreFileMaybe.isPresent()) {

tinkerpop3/src/test/java/io/shiftleft/overflowdb/storage/GraphSaveRestoreTest.java

@@ -169,6 +169,7 @@ private void modifyAndCloseGraph(File storageFile, Function<OdbGraph, Integer> g
 
   private OdbGraph newGratefulDeadGraph(File overflowDb, boolean enableOverflow) {
     OdbConfig config = enableOverflow ? OdbConfig.withDefaults() : OdbConfig.withoutOverflow();
+    config = config.withSerializationStatsEnabled();
     return GratefulDead.newGraph(config.withStorageLocation(overflowDb.getAbsolutePath()));
   }
 

tinkerpop3/src/test/java/io/shiftleft/overflowdb/storage/SerializerTest.java

@@ -25,7 +25,7 @@ public class SerializerTest {
   @Test
   public void serializeVertex() throws IOException {
     try (OdbGraph graph = SimpleDomain.newGraph()) {
-      NodeSerializer serializer = new NodeSerializer();
+      NodeSerializer serializer = new NodeSerializer(false);
       NodeDeserializer deserializer = newDeserializer(graph);
       TestNode testNode = (TestNode) graph.addVertex(
           T.label, TestNode.LABEL,
@@ -52,7 +52,7 @@ public void serializeVertex() throws IOException {
   @Test
   public void serializeWithEdge() throws IOException {
     try (OdbGraph graph = SimpleDomain.newGraph()) {
-      NodeSerializer serializer = new NodeSerializer();
+      NodeSerializer serializer = new NodeSerializer(true);
       NodeDeserializer deserializer = newDeserializer(graph);
 
       TestNode testNode1 = (TestNode) graph.addVertex(T.label, TestNode.LABEL);
@@ -84,7 +84,7 @@ public void serializeWithEdge() throws IOException {
   private NodeDeserializer newDeserializer(OdbGraph graph) {
     Map<Integer, NodeFactory> vertexFactories = new HashMap();
     vertexFactories.put(TestNodeDb.layoutInformation.labelId, TestNode.factory);
-    return new NodeDeserializer(graph, vertexFactories);
+    return new NodeDeserializer(graph, vertexFactories, true);
   }
 
 }