Added performance logging

.gitignore

@@ -1,3 +1,5 @@
 target
 .idea/
 *.iml
+*.log
+*.lck

src/main/java/com/stor/common/PerformanceLogHandler.java

@@ -0,0 +1,28 @@
+package com.stor.common;
+
+import java.io.IOException;
+import java.util.logging.FileHandler;
+
+/**
+ * Handler for capturing performance related log entries
+ */
+public class PerformanceLogHandler extends FileHandler {
+    public PerformanceLogHandler() throws IOException, SecurityException {
+    }
+
+    public PerformanceLogHandler(String s) throws IOException, SecurityException {
+        super(s);
+    }
+
+    public PerformanceLogHandler(String s, boolean b) throws IOException, SecurityException {
+        super(s, b);
+    }
+
+    public PerformanceLogHandler(String s, int i, int i2) throws IOException, SecurityException {
+        super(s, i, i2);
+    }
+
+    public PerformanceLogHandler(String s, int i, int i2, boolean b) throws IOException, SecurityException {
+        super(s, i, i2, b);
+    }
+}

src/main/java/com/stor/p2p/StorApplicationImpl.java

@@ -25,6 +25,9 @@
 
 public class StorApplicationImpl implements StorApplication {
     private static final Logger logger = Logger.getLogger(StorApplicationImpl.class.getName());
+    private static final Logger perfLogger = Logger.getLogger("performanceLog");
+
+    private final Environment environment;
 
     //replica count
     private static final int REPLICA_COUNT = 5;
@@ -38,9 +41,15 @@ public class StorApplicationImpl implements StorApplication {
     private Past pastApp;
     private PastryIdFactory messageIdFactory;
 
+    private long now() {
+        return this.environment.getTimeSource().currentTimeMillis();
+    }
 
     public StorApplicationImpl(int bindPort, InetSocketAddress bootAddress, final Environment environment) throws IOException, InterruptedException, JoinFailedException {
+        this.environment = environment;
+
         logger.info("StorApplicationImpl - begin initialization");
+        long begin = now();
 
         //generate a random node id
         PastryNodeFactory pastryNodeFactory = new SocketPastryNodeFactory(new RandomNodeIdFactory(environment), bindPort, environment);
@@ -59,6 +68,7 @@ public StorApplicationImpl(int bindPort, InetSocketAddress bootAddress, final En
 
         //boot node
         node.boot(bootAddress);
+        perfLogger.log(Level.INFO, "Boot Complete: {0} ms", now() - begin);
 
         // the node may require sending several messages to fully boot into the ring
         synchronized (node) {
@@ -74,6 +84,7 @@ public StorApplicationImpl(int bindPort, InetSocketAddress bootAddress, final En
         }
 
         logger.info("StorApplicationImpl - initialization complete");
+        perfLogger.log(Level.INFO, "Initialization completed: {0} ms", now() - begin);
     }
 
     public AppResponse put(String filePath) {
@@ -91,13 +102,18 @@ public AppResponse put(String filePath) {
             //save message
             StorMessage message = new StorMessage(id, fileContent);
 
+            long begin = now();
             Continuation.ExternalContinuation<Boolean[], Exception> putContinuation = new Continuation.ExternalContinuation<>();
 
             //trigger past insert
             pastApp.insert(message, putContinuation);
 
             putContinuation.sleep();
 
+            long duration = now() - begin;
+            perfLogger.log(Level.INFO, "Insert Complete: {0}", duration);
+            perfLogger.log(Level.INFO, "INSERT: Content: {0} bytes, Duration: {1} ms", new Object[]{fileContent.length, duration});
+
             if (putContinuation.exceptionThrown()) {
                 throw putContinuation.getException();
             }
@@ -126,12 +142,17 @@ public AppResponse get(String fileId) {
              */
             Continuation.ExternalContinuation<PastContent, Exception> getContinuation = new Continuation.ExternalContinuation<>();
 
+            long begin = now();
+
             //trigger past lookup
             pastApp.lookup(contentId, getContinuation);
 
             //wait for the content to be ready.
             getContinuation.sleep();
 
+            long duration = now() - begin;
+            perfLogger.log(Level.INFO, "Lookup Complete: {0} ms", duration);
+
             /**
              * getContinuation sleep ended. check if the content is available and report back
              *
@@ -157,6 +178,7 @@ public AppResponse get(String fileId) {
                     throw new StorException("Failed to save file");
                 } else {
                     logger.info("Located content store in: " + newFilePath.toString());
+                    perfLogger.log(Level.INFO, "LOOKUP: Content: {0} bytes, Duration: {1} ms", new Object[]{message.getFileContent().length, duration});
                     appResponse.setResponse(newFilePath.toString());
                 }
             } else {

src/main/resources/freepastry.params

@@ -384,18 +384,18 @@ log_rotate_filename = freepastry.log
 log_rotating_date_format = yyyyMMdd.HHmmss.SSS
 
 # true will tell the environment to ues the FileLogManager
-environment_logToFile = false
+environment_logToFile = true
 # the prefix for the log files (otherwise will be named after the nodeId)
-fileLogManager_filePrefix = 
+fileLogManager_filePrefix =
 # the suffix for the log files
 fileLogManager_fileSuffix = .log
 # wether to keep the line prefix (declaring the node id) for each line of the log
 fileLogManager_keepLinePrefix = false
-fileLogManager_multipleFiles = true
+fileLogManager_multipleFiles = false
 fileLogManager_defaultFileName = main
 
 # false = append true = overwrite
-fileLogManager_overwrite_existing_log_file = false
+fileLogManager_overwrite_existing_log_file = true
 
 # the amount of time the LookupService tutorial app will wait before timing out
 # in milliseconds, default is 30 seconds

src/main/resources/logging.properties

@@ -0,0 +1,14 @@
+handlers = java.util.logging.ConsoleHandler, java.util.logging.FileHandler
+.level = CONFIG
+
+performanceLog.handlers = com.stor.common.PerformanceLogHandler
+performanceLog.level = ALL
+
+java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
+java.util.logging.ConsoleHandler.level = WARNING
+
+java.util.logging.FileHandler.pattern = Stor.log
+java.util.logging.FileHandler.formatter = java.util.logging.SimpleFormatter
+
+com.stor.common.PerformanceLogHandler.pattern = Stor_Performance.log
+com.stor.common.PerformanceLogHandler.formatter = java.util.logging.SimpleFormatter