Patch for adding latency tracking to server

Add_latency_monitoring_to_server.patch

Index: src/main/java/com/aitusoftware/workshop/usvc/svc/e4/TcpBinaryCalculatorServer.java
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- src/main/java/com/aitusoftware/workshop/usvc/svc/e4/TcpBinaryCalculatorServer.java	(revision 75e465ad33a90511fadce2b94593704cc9bb8463)
+++ src/main/java/com/aitusoftware/workshop/usvc/svc/e4/TcpBinaryCalculatorServer.java	(date 1539109413000)
@@ -11,10 +11,14 @@
  */
 package com.aitusoftware.workshop.usvc.svc.e4;
 
-import com.aitusoftware.workshop.usvc.common.Calculator;
-import com.aitusoftware.workshop.usvc.common.Operation;
+import static java.lang.String.format;
 
+import java.io.File;
+import java.io.FileNotFoundException;
+import java.io.FileOutputStream;
 import java.io.IOException;
+import java.io.PrintStream;
+import java.io.PrintWriter;
 import java.net.InetSocketAddress;
 import java.net.StandardSocketOptions;
 import java.nio.ByteBuffer;
@@ -22,12 +26,31 @@
 import java.nio.channels.SocketChannel;
 import java.util.concurrent.ExecutorService;
 import java.util.concurrent.Executors;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicLong;
+import java.util.concurrent.atomic.AtomicReference;
+import java.util.concurrent.locks.LockSupport;
+
+import com.aitusoftware.workshop.usvc.common.Calculator;
+import com.aitusoftware.workshop.usvc.common.Operation;
+
+import org.HdrHistogram.Histogram;
 
 public final class TcpBinaryCalculatorServer
 {
+    private static final long REPORT_INTERVAL = TimeUnit.SECONDS.toNanos(5L);
     private static final Operation[] VALUES = Operation.values();
     private final ServerSocketChannel serverSocketChannel;
     private final ExecutorService executorService = Executors.newCachedThreadPool();
+
+    private final AtomicReference<Histogram> writableHistogram = new AtomicReference<>();
+    private final Histogram even = new Histogram(TimeUnit.SECONDS.toNanos(1L), 5);
+    private final Histogram odd = new Histogram(TimeUnit.SECONDS.toNanos(1L), 5);
+    private final Histogram sum = new Histogram(TimeUnit.SECONDS.toNanos(1L), 5);
+    private final AtomicLong startEpoch = new AtomicLong();
+    private final AtomicLong endEpoch = new AtomicLong();
+    private final AtomicLong requestCount = new AtomicLong();
+
     private volatile boolean running = true;
 
     public static void main(String[] args) throws IOException
@@ -46,6 +69,8 @@
     public void start()
     {
         executorService.submit(this::receiveLoop);
+        writableHistogram.set(even);
+        executorService.submit(this::reportLoop);
     }
 
     public void stop()
@@ -95,6 +120,7 @@
                         return;
                     }
 
+                    final long startNanos = System.nanoTime();
                     buffer.flip();
                     final Operation operation = VALUES[buffer.getInt()];
                     final long operand0 = buffer.getLong();
@@ -103,6 +129,14 @@
                     buffer.clear();
                     buffer.putLong(calculator.calculate(operand0, operand1, operation).getResult());
                     buffer.flip();
+                    requestCount.incrementAndGet();
+                    final long requestDuration = System.nanoTime() - startNanos;
+
+                    final long epoch = startEpoch.incrementAndGet();
+                    writableHistogram.get().
+                      recordValue(
+                        Math.min(requestDuration, TimeUnit.SECONDS.toNanos(1L)));
+                    endEpoch.lazySet(epoch);
                     socketChannel.write(buffer);
                 }
                 catch (Exception e)
@@ -112,4 +146,86 @@
             }
         }
     }
+
+
+
+    private void reportLoop()
+    {
+        long lastSumReportNanos = System.nanoTime();
+        System.out.println("Latency (ns)");
+        printColumnHeaders();
+
+
+        while(!Thread.currentThread().isInterrupted())
+        {
+            final long startNanos = System.nanoTime();
+            LockSupport.parkNanos(REPORT_INTERVAL);
+            final long intervalRequestCount = requestCount.getAndSet(0L);
+            final long endNanos = System.nanoTime();
+
+            final Histogram expectedWritable = writableHistogram.get() == even ? even : odd;
+            final Histogram nextWritable = writableHistogram.get() == even ? odd : even;
+
+            if(!writableHistogram.compareAndSet(expectedWritable, nextWritable))
+            {
+                System.out.println("Unexpected histogram. Exiting :(");
+                return;
+            }
+            final long lastStartedEpoch = startEpoch.get();
+            while(endEpoch.get() < lastStartedEpoch)
+            {
+                LockSupport.parkNanos(1L);
+            }
+
+            final double seconds = (endNanos - startNanos) / TimeUnit.SECONDS.toNanos(1L);
+            final double throughput = intervalRequestCount / seconds;
+
+            shortReport(expectedWritable, throughput, System.out);
+
+            sum.add(expectedWritable);
+            expectedWritable.reset();
+
+            if(lastSumReportNanos + TimeUnit.SECONDS.toNanos(20L) < endNanos)
+            {
+                try
+                {
+                    final String filename = getHistogramFilename();
+                    sum.outputPercentileDistribution(new PrintStream(new FileOutputStream(new File(System.getProperty("java.io.tmpdir"), filename))), 1d);
+                }
+                catch (FileNotFoundException e)
+                {
+                    System.err.println("Failed to write histogram summary: " + e.getMessage());
+                }
+                sum.reset();
+                lastSumReportNanos = endNanos;
+                printColumnHeaders();
+            }
+        }
+    }
+
+    private void printColumnHeaders()
+    {
+        System.out.println("\n        min       mean        50%        90%        99%      99.9%     99.99%        max    req/sec");
+    }
+
+    private void shortReport(final Histogram histogram, final double throughput, final PrintStream out)
+    {
+        final PrintWriter printWriter = new PrintWriter(out);
+        printWriter.append(format("%11d", histogram.getMinValue()));
+        printWriter.append(format("%11d", (long) histogram.getMean()));
+        printWriter.append(format("%11d", histogram.getValueAtPercentile(50.0d)));
+        printWriter.append(format("%11d", histogram.getValueAtPercentile(90.0d)));
+        printWriter.append(format("%11d", histogram.getValueAtPercentile(99.0d)));
+        printWriter.append(format("%11d", histogram.getValueAtPercentile(99.9d)));
+        printWriter.append(format("%11d", histogram.getValueAtPercentile(99.99d)));
+        printWriter.append(format("%11d", histogram.getMaxValue()));
+        printWriter.append(format("%11d", (long) throughput));
+        printWriter.append("\n");
+        printWriter.flush();
+    }
+
+    private static String getHistogramFilename()
+    {
+        return "binary_server.hgram";
+    }
 }