This closes #1605

artemis-cli/pom.xml

@@ -82,6 +82,10 @@
          <artifactId>commons-lang3</artifactId>
          <version>${commons.lang.version}</version>
       </dependency>
+      <dependency>
+         <groupId>org.hdrhistogram</groupId>
+         <artifactId>HdrHistogram</artifactId>
+      </dependency>
       <dependency>
         <groupId>com.sun.winsw</groupId>
         <artifactId>winsw</artifactId>

artemis-cli/src/main/java/org/apache/activemq/artemis/cli/commands/util/SyncCalculation.java

@@ -21,8 +21,10 @@ import java.io.File;
 import java.io.IOException;
 import java.nio.ByteBuffer;
 import java.text.DecimalFormat;
+import java.util.Arrays;
 import java.util.concurrent.TimeUnit;
 
+import org.HdrHistogram.Histogram;
 import org.apache.activemq.artemis.core.io.IOCallback;
 import org.apache.activemq.artemis.core.io.SequentialFile;
 import org.apache.activemq.artemis.core.io.SequentialFileFactory;
@@ -40,9 +42,30 @@ import org.apache.activemq.artemis.utils.ReusableLatch;
  */
 public class SyncCalculation {
 
+   //uses nanoseconds to avoid any conversion cost: useful when performing operation on mapped journal without fsync or with RAM-like devices
+   private static final long MAX_FLUSH_NANOS = TimeUnit.SECONDS.toNanos(5);
+
    /**
-    * It will perform a write test of blockSize * bocks, sinc on each write, for N tries.
+    * It will perform {@code tries} write tests of {@code blockSize * blocks} bytes and returning the lowest elapsed time to perform a try.
-    * It will return the lowest spent time from the tries.
+    *
+    * <p>
+    * Please configure {@code blocks >= -XX:CompileThreshold} (ie by default on most JVMs is 10000) to favour the best JIT/OSR compilation (ie: Just In Time/On Stack Replacement)
+    * if the test is running on a temporary file-system (eg: tmpfs on Linux) or without {@code fsync}.
+    * <p>
+    * NOTE: The write latencies are provided only if {@code verbose && !(journalType == JournalType.ASYNCIO && !syncWrites)} (ie are used effective synchronous writes).
+    *
+    * @param datafolder  the folder where the journal files will be stored
+    * @param blockSize   the size in bytes of each write on the journal
+    * @param blocks      the number of {@code blockSize} writes performed on each try
+    * @param tries       the number of tests
+    * @param verbose     {@code true} to make the output verbose, {@code false} otherwise
+    * @param fsync       if {@code true} the test is performing full durable writes, {@code false} otherwise
+    * @param syncWrites  if {@code true} each write is performed only if the previous one is completed, {@code false} otherwise (ie each try will wait only the last write)
+    * @param fileName    the name of the journal file used for the test
+    * @param maxAIO      the max number of in-flight IO requests (if {@code journalType} will support it)
+    * @param journalType the {@link JournalType} used for the tests
+    * @return the lowest elapsed time (in {@link TimeUnit#MILLISECONDS}) to perform a try
+    * @throws Exception
     */
    public static long syncTest(File datafolder,
                                int blockSize,
@@ -55,13 +78,35 @@ public class SyncCalculation {
                                int maxAIO,
                                JournalType journalType) throws Exception {
       SequentialFileFactory factory = newFactory(datafolder, fsync, journalType, blockSize * blocks, maxAIO);
+      final boolean asyncWrites = journalType == JournalType.ASYNCIO && !syncWrites;
+      //the write latencies could be taken only when writes are effectively synchronous
+      final Histogram writeLatencies = (verbose && !asyncWrites) ? new Histogram(MAX_FLUSH_NANOS, 2) : null;
+
+      if (journalType == JournalType.ASYNCIO && syncWrites) {
+         System.out.println();
+         System.out.println("*******************************************************************************************");
+         System.out.println("*** Notice: The recommendation for AsyncIO journal is to not use --sync-writes          ***");
+         System.out.println("***         The measures here will be useful to understand your device                  ***");
+         System.out.println("***         however the result here won't represent the best configuration option       ***");
+         System.out.println("*******************************************************************************************");
+         System.out.println();
+      }
 
       if (verbose) {
          System.out.println("Using " + factory.getClass().getName() + " to calculate sync times, alignment=" + factory.getAlignment());
+         if (writeLatencies == null) {
+            System.out.println("*** Use --sync-writes if you want to see a histogram for each write performed ***");
+         }
       }
       SequentialFile file = factory.createSequentialFile(fileName);
-
+      //to be sure that a process/thread crash won't leave the dataFolder with garbage files
+      file.getJavaFile().deleteOnExit();
       try {
+         final ByteBuffer bufferBlock = allocateAlignedBlock(blockSize, factory);
+
+         // making sure the blockSize matches the device
+         blockSize = bufferBlock.remaining();
+
          file.delete();
          file.open();
 
@@ -71,16 +116,6 @@ public class SyncCalculation {
 
          long[] result = new long[tries];
 
-         byte[] block = new byte[blockSize];
-
-         for (int i = 0; i < block.length; i++) {
-            block[i] = (byte) 't';
-         }
-
-         ByteBuffer bufferBlock = factory.newBuffer(blockSize);
-         bufferBlock.put(block);
-         bufferBlock.position(0);
-
          final ReusableLatch latch = new ReusableLatch(0);
 
          IOCallback callback = new IOCallback() {
@@ -108,11 +143,19 @@ public class SyncCalculation {
             for (int i = 0; i < blocks; i++) {
                bufferBlock.position(0);
                latch.countUp();
+               long startWrite = 0;
+               if (writeLatencies != null) {
+                  startWrite = System.nanoTime();
+               }
                file.writeDirect(bufferBlock, true, callback);
 
                if (syncWrites) {
                   flushLatch(latch);
                }
+               if (writeLatencies != null) {
+                  final long elapsedWriteNanos = System.nanoTime() - startWrite;
+                  writeLatencies.recordValue(elapsedWriteNanos);
+               }
             }
 
             if (!syncWrites) flushLatch(latch);
@@ -129,10 +172,30 @@ public class SyncCalculation {
                System.out.println("**************************************************");
             }
             file.close();
+
+            if (ntry == 0 && writeLatencies != null) {
+               writeLatencies.reset(); // discarding the first one.. some warmup time
+            }
          }
 
          factory.releaseDirectBuffer(bufferBlock);
 
+         if (writeLatencies != null) {
+            System.out.println("Write Latencies Percentile Distribution in microseconds");
+            //print latencies in us -> (ns * 1000d)
+
+            System.out.println("*****************************************************************");
+            writeLatencies.outputPercentileDistribution(System.out, 1000d);
+            System.out.println();
+            System.out.println("*****************************************************************");
+            System.out.println("*** this may be useful to generate charts if you like charts: ***");
+            System.out.println("*** http://hdrhistogram.github.io/HdrHistogram/plotFiles.html ***");
+            System.out.println("*****************************************************************");
+            System.out.println();
+
+            writeLatencies.reset();
+         }
+
          long totalTime = Long.MAX_VALUE;
          for (int i = 0; i < tries; i++) {
             if (result[i] < totalTime) {
@@ -157,8 +220,17 @@ public class SyncCalculation {
       }
    }
 
+   private static ByteBuffer allocateAlignedBlock(int blockSize, SequentialFileFactory factory) {
+      final ByteBuffer bufferBlock = factory.newBuffer(blockSize);
+      final byte[] block = new byte[bufferBlock.remaining()];
+      Arrays.fill(block, (byte) 't');
+      bufferBlock.put(block);
+      bufferBlock.position(0);
+      return bufferBlock;
+   }
+
    private static void flushLatch(ReusableLatch latch) throws InterruptedException, IOException {
-      if (!latch.await(5, TimeUnit.SECONDS)) {
+      if (!latch.await(MAX_FLUSH_NANOS, TimeUnit.NANOSECONDS)) {
          throw new IOException("Timed out on receiving IO callback");
       }
    }

artemis-distribution/src/main/assembly/dep.xml

@@ -97,6 +97,7 @@
             <include>org.jgroups:jgroups</include>
             <include>org.apache.geronimo.specs:geronimo-json_1.0_spec</include>
             <include>org.apache.johnzon:johnzon-core</include>
+            <include>org.hdrhistogram:HdrHistogram</include>
          </includes>
          <!--excludes>
             <exclude>org.apache.activemq:artemis-website</exclude>

pom.xml

@@ -78,6 +78,7 @@
       <activemq5-version>5.14.5</activemq5-version>
       <apache.derby.version>10.11.1.1</apache.derby.version>
       <commons.beanutils.version>1.9.2</commons.beanutils.version>
+      <org.hdrhistogram.version>2.1.10</org.hdrhistogram.version>
       <commons.collections.version>3.2.2</commons.collections.version>
       <fuse.mqtt.client.version>1.14</fuse.mqtt.client.version>
       <guava.version>19.0</guava.version>
@@ -666,6 +667,15 @@
             <!-- License: Apache 2.0 -->
          </dependency>
 
+         <!-- needed by SyncCalculation -->
+         <!-- https://mvnrepository.com/artifact/org.hdrhistogram/HdrHistogram -->
+         <dependency>
+            <groupId>org.hdrhistogram</groupId>
+            <artifactId>HdrHistogram</artifactId>
+            <version>${org.hdrhistogram.version}</version>
+            <!-- License: Public Domain -->
+         </dependency>
+
          <dependency>
             <groupId>org.apache.openwebbeans</groupId>
             <artifactId>openwebbeans-impl</artifactId>