Offer a getDurationInMillis() method in the Profiler utility class

- New implementation uses nanoseconds. Due to that, the places where the Profiler is used as a Monitor and/or
     a stopwatch will suffer with the difference in the return
   - Also added a getDuration(), which returns the time in nanoseconds in case someone wants to use it instead
   - Added an extra test to check if the getDuration() works fine with nanoseconds
   - Fixed the test that checks the time in milliseconds: I added an error margin to cover the test better

Signed-off-by: Daan Hoogland <daan@onecht.net>

engine/orchestration/src/com/cloud/agent/manager/SynchronousListener.java

@@ -116,7 +116,7 @@ public class SynchronousListener implements Listener {
         profiler.stop();
 
         if (s_logger.isTraceEnabled()) {
-            s_logger.trace("Synchronized command - sending completed, time: " + profiler.getDuration() + ", answer: " +
+            s_logger.trace("Synchronized command - sending completed, time: " + profiler.getDurationInMillis() + ", answer: " +
                 (_answers != null ? _answers[0].toString() : "null"));
         }
         return _answers;

framework/db/src/com/cloud/utils/db/GlobalLock.java

@@ -139,7 +139,7 @@ public class GlobalLock {
                         }
                         profiler.stop();
 
-                        remainingMilliSeconds -= profiler.getDuration();
+                        remainingMilliSeconds -= profiler.getDurationInMillis();
                         if (remainingMilliSeconds < 0)
                             return false;
 

framework/db/test/com/cloud/utils/db/GlobalLockTest.java

@@ -49,7 +49,7 @@ public class GlobalLockTest {
                 p.start();
                 locked = WorkLock.lock(timeoutSeconds);
                 p.stop();
-                System.out.println("Thread " + id + " waited " + p.getDuration() + " ms, locked=" + locked);
+                System.out.println("Thread " + id + " waited " + p.getDurationInMillis() + " ms, locked=" + locked);
                 if (locked) {
                     Thread.sleep(jobDuration * 1000);
                 }

server/src/com/cloud/network/security/SecurityGroupManagerImpl2.java

@@ -125,7 +125,7 @@ public class SecurityGroupManagerImpl2 extends SecurityGroupManagerImpl {
         p.stop();
         if (s_logger.isDebugEnabled()) {
             s_logger.debug("Security Group Mgr v2: done scheduling ruleset updates for " + workItems.size() + " vms: num new jobs=" + newJobs +
-                " num rows insert or updated=" + updated + " time taken=" + p.getDuration());
+                " num rows insert or updated=" + updated + " time taken=" + p.getDurationInMillis());
         }
     }
 

server/test/com/cloud/network/security/SecurityGroupManagerImpl2Test.java

@@ -61,7 +61,7 @@ public class SecurityGroupManagerImpl2Test extends TestCase {
         _sgMgr.scheduleRulesetUpdateToHosts(work, false, null);
         profiler.stop();
 
-        System.out.println("Done " + numVms + " in " + profiler.getDuration() + " ms");
+        System.out.println("Done " + numVms + " in " + profiler.getDurationInMillis() + " ms");
     }
 
     @Test

server/test/com/cloud/network/security/SecurityGroupQueueTest.java

@@ -131,7 +131,7 @@ public class SecurityGroupQueueTest extends TestCase {
             }
         }
         p.stop();
-        System.out.println("Num Vms= " + maxVmId + " Queue size = " + queue.size() + " time=" + p.getDuration() + " ms");
+        System.out.println("Num Vms= " + maxVmId + " Queue size = " + queue.size() + " time=" + p.getDurationInMillis() + " ms");
         assertEquals(maxVmId, queue.size());
     }
 

utils/src/com/cloud/utils/Profiler.java

@@ -20,45 +20,72 @@
 package com.cloud.utils;
 
 public class Profiler {
-    private Long startTickInMs;
-    private Long stopTickInMs;
+
+    private static final long MILLIS_FACTOR = 1000l;
+    private static final double EXPONENT = 2d;
+
+
+    private Long startTickNanoSeconds;
+    private Long stopTickNanoSeconds;
 
     public long start() {
-        startTickInMs = System.nanoTime();
-        return startTickInMs.longValue();
+        startTickNanoSeconds = System.nanoTime();
+        return startTickNanoSeconds;
     }
 
     public long stop() {
-        stopTickInMs = System.nanoTime();
-        return stopTickInMs.longValue();
+        stopTickNanoSeconds = System.nanoTime();
+        return stopTickNanoSeconds;
     }
 
+    /**
+     * 1 millisecond = 1e+6 nanoseconds
+     * 1 second = 1000 milliseconds = 1e+9 nanoseconds
+     *
+     * @return the duration in nanoseconds.
+     */
     public long getDuration() {
-        if (startTickInMs != null && stopTickInMs != null) {
-            return stopTickInMs.longValue() - startTickInMs.longValue();
+        if (startTickNanoSeconds != null && stopTickNanoSeconds != null) {
+            final long timeInMicroSeconds = stopTickNanoSeconds - startTickNanoSeconds;
+            return timeInMicroSeconds;
+        }
+
+        return -1;
+    }
+
+    /**
+     * 1 millisecond = 1e+6 nanoseconds
+     * 1 second = 1000 millisecond = 1e+9 nanoseconds
+     *
+     * @return the duration in milliseconds.
+     */
+    public long getDurationInMillis() {
+        if (startTickNanoSeconds != null && stopTickNanoSeconds != null) {
+            final long timeInMillis = (stopTickNanoSeconds - startTickNanoSeconds) / (long)Math.pow(MILLIS_FACTOR, EXPONENT);
+            return timeInMillis;
         }
 
         return -1;
     }
 
     public boolean isStarted() {
-        return startTickInMs != null;
+        return startTickNanoSeconds != null;
     }
 
     public boolean isStopped() {
-        return stopTickInMs != null;
+        return stopTickNanoSeconds != null;
     }
 
     @Override
     public String toString() {
-        if (startTickInMs == null) {
+        if (startTickNanoSeconds == null) {
             return "Not Started";
         }
 
-        if (stopTickInMs == null) {
+        if (stopTickNanoSeconds == null) {
             return "Started but not stopped";
         }
 
-        return "Done. Duration: " + getDuration() + "ms";
+        return "Done. Duration: " + getDurationInMillis() + "ms";
     }
 }

utils/test/com/cloud/utils/TestProfiler.java

@@ -28,25 +28,47 @@ import com.cloud.utils.testcase.Log4jEnabledTestCase;
 public class TestProfiler extends Log4jEnabledTestCase {
     protected final static Logger s_logger = Logger.getLogger(TestProfiler.class);
 
+    private static final long MILLIS_FACTOR = 1000l;
+    private static final int MARGIN = 100;
+    private static final double EXPONENT = 3d;
+
     @Test
-    public void testProfiler() {
+    public void testProfilerInMillis() {
         s_logger.info("testProfiler() started");
 
         final Profiler pf = new Profiler();
         pf.start();
         try {
-            Thread.sleep(1000);
+            Thread.sleep(MILLIS_FACTOR);
         } catch (final InterruptedException e) {
         }
         pf.stop();
 
-        s_logger.info("Duration : " + pf.getDuration());
+        final long durationInMillis = pf.getDurationInMillis();
+        s_logger.info("Duration : " + durationInMillis);
 
-        Assert.assertTrue(pf.getDuration() >= 1000);
+        // An error margin in order to cover the time taken by the star/stop calls.
+        // 100 milliseconds margin seems too much, but it will avoid assertion error
+        // and also fail in case a duration in nanoseconds is used instead.
+        Assert.assertTrue(durationInMillis >= MILLIS_FACTOR  &&  durationInMillis <= MILLIS_FACTOR + MARGIN);
 
         s_logger.info("testProfiler() stopped");
     }
 
+    @Test
+    public void testProfilerInMicro() {
+        final Profiler pf = new Profiler();
+        pf.start();
+        try {
+            Thread.sleep(MILLIS_FACTOR);
+        } catch (final InterruptedException e) {
+        }
+        pf.stop();
+
+        final long duration = pf.getDuration();
+        Assert.assertTrue(duration >= Math.pow(MILLIS_FACTOR, EXPONENT));
+    }
+
     @Test
     public void testProfilerNoStart() {
         final Profiler pf = new Profiler();
@@ -56,7 +78,7 @@ public class TestProfiler extends Log4jEnabledTestCase {
         }
         pf.stop();
 
-        Assert.assertTrue(pf.getDuration() == -1);
+        Assert.assertTrue(pf.getDurationInMillis() == -1);
         Assert.assertFalse(pf.isStarted());
     }
 
@@ -69,7 +91,7 @@ public class TestProfiler extends Log4jEnabledTestCase {
         } catch (final InterruptedException e) {
         }
 
-        Assert.assertTrue(pf.getDuration() == -1);
+        Assert.assertTrue(pf.getDurationInMillis() == -1);
         Assert.assertFalse(pf.isStopped());
     }
 }