diff --git a/engine/orchestration/src/com/cloud/agent/manager/SynchronousListener.java b/engine/orchestration/src/com/cloud/agent/manager/SynchronousListener.java index 5da1b27abfe..28c60c1a07f 100644 --- a/engine/orchestration/src/com/cloud/agent/manager/SynchronousListener.java +++ b/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; diff --git a/framework/db/src/com/cloud/utils/db/GlobalLock.java b/framework/db/src/com/cloud/utils/db/GlobalLock.java index e03da53fc7d..662ba921ce9 100644 --- a/framework/db/src/com/cloud/utils/db/GlobalLock.java +++ b/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; diff --git a/framework/db/test/com/cloud/utils/db/GlobalLockTest.java b/framework/db/test/com/cloud/utils/db/GlobalLockTest.java index c26f2486018..58c496f330b 100644 --- a/framework/db/test/com/cloud/utils/db/GlobalLockTest.java +++ b/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); } diff --git a/server/src/com/cloud/network/security/SecurityGroupManagerImpl2.java b/server/src/com/cloud/network/security/SecurityGroupManagerImpl2.java index 3c0c5c3c141..47f6e774bac 100644 --- a/server/src/com/cloud/network/security/SecurityGroupManagerImpl2.java +++ b/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()); } } diff --git a/server/test/com/cloud/network/security/SecurityGroupManagerImpl2Test.java b/server/test/com/cloud/network/security/SecurityGroupManagerImpl2Test.java index 9c41ac220e4..ad1da3260e7 100644 --- a/server/test/com/cloud/network/security/SecurityGroupManagerImpl2Test.java +++ b/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 diff --git a/server/test/com/cloud/network/security/SecurityGroupQueueTest.java b/server/test/com/cloud/network/security/SecurityGroupQueueTest.java index 6c104c275aa..e90cc58e127 100644 --- a/server/test/com/cloud/network/security/SecurityGroupQueueTest.java +++ b/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()); } diff --git a/utils/src/com/cloud/utils/Profiler.java b/utils/src/com/cloud/utils/Profiler.java index 6082a92157d..5977453e2e1 100644 --- a/utils/src/com/cloud/utils/Profiler.java +++ b/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"; } } \ No newline at end of file diff --git a/utils/test/com/cloud/utils/TestProfiler.java b/utils/test/com/cloud/utils/TestProfiler.java index 4323f1d3c71..cbd28f504b6 100644 --- a/utils/test/com/cloud/utils/TestProfiler.java +++ b/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()); } } \ No newline at end of file