You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@cloudstack.apache.org by da...@apache.org on 2015/06/24 09:36:54 UTC
[1/3] git commit: updated refs/heads/master to cbf5155
Repository: cloudstack
Updated Branches:
refs/heads/master e3daa1096 -> cbf5155f7
Testing the elapsed time between 2 consecultive calls to System.nanoTime()
- 1 test was added
Signed-off-by: Daan Hoogland <da...@onecht.net>
Project: http://git-wip-us.apache.org/repos/asf/cloudstack/repo
Commit: http://git-wip-us.apache.org/repos/asf/cloudstack/commit/2f145378
Tree: http://git-wip-us.apache.org/repos/asf/cloudstack/tree/2f145378
Diff: http://git-wip-us.apache.org/repos/asf/cloudstack/diff/2f145378
Branch: refs/heads/master
Commit: 2f145378dff577bd153e0585f4990f637185d900
Parents: 5557ad5
Author: wilderrodrigues <wr...@schubergphilis.com>
Authored: Tue Jun 23 19:21:29 2015 +0200
Committer: Daan Hoogland <da...@onecht.net>
Committed: Wed Jun 24 09:36:40 2015 +0200
----------------------------------------------------------------------
utils/test/com/cloud/utils/TestProfiler.java | 14 ++++++++++++++
1 file changed, 14 insertions(+)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/cloudstack/blob/2f145378/utils/test/com/cloud/utils/TestProfiler.java
----------------------------------------------------------------------
diff --git a/utils/test/com/cloud/utils/TestProfiler.java b/utils/test/com/cloud/utils/TestProfiler.java
index cbd28f5..d801059 100644
--- a/utils/test/com/cloud/utils/TestProfiler.java
+++ b/utils/test/com/cloud/utils/TestProfiler.java
@@ -94,4 +94,18 @@ public class TestProfiler extends Log4jEnabledTestCase {
Assert.assertTrue(pf.getDurationInMillis() == -1);
Assert.assertFalse(pf.isStopped());
}
+
+ @Test
+ public void testResolution() {
+ long nanoTime1 = 0l;
+ long nanoTime2 = 0l;
+ nanoTime1 = System.nanoTime();
+ nanoTime2 = System.nanoTime();
+ System.out.println("Nano time 1: " + nanoTime1);
+ System.out.println("Nano time 2: " + nanoTime2);
+
+ // We are measuring the elapsed time in 2 consecutive calls of System.nanoTime()
+ // That's the same as 0.002 milliseconds or 2000 nanoseconds.
+ Assert.assertTrue("It took more than 2 microseconds between 2 consecutive calls to System.nanoTime().", nanoTime2 - nanoTime1 <= 2000);
+ }
}
\ No newline at end of file
[2/3] git commit: updated refs/heads/master to cbf5155
Posted by da...@apache.org.
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 <da...@onecht.net>
Project: http://git-wip-us.apache.org/repos/asf/cloudstack/repo
Commit: http://git-wip-us.apache.org/repos/asf/cloudstack/commit/5557ad55
Tree: http://git-wip-us.apache.org/repos/asf/cloudstack/tree/5557ad55
Diff: http://git-wip-us.apache.org/repos/asf/cloudstack/diff/5557ad55
Branch: refs/heads/master
Commit: 5557ad55880f981c2621a4f411b80e4301469104
Parents: e3daa10
Author: wilderrodrigues <wr...@schubergphilis.com>
Authored: Tue Jun 23 15:46:53 2015 +0200
Committer: Daan Hoogland <da...@onecht.net>
Committed: Wed Jun 24 09:36:40 2015 +0200
----------------------------------------------------------------------
.../agent/manager/SynchronousListener.java | 2 +-
.../db/src/com/cloud/utils/db/GlobalLock.java | 2 +-
.../test/com/cloud/utils/db/GlobalLockTest.java | 2 +-
.../security/SecurityGroupManagerImpl2.java | 2 +-
.../security/SecurityGroupManagerImpl2Test.java | 2 +-
.../security/SecurityGroupQueueTest.java | 2 +-
utils/src/com/cloud/utils/Profiler.java | 53 +++++++++++++++-----
utils/test/com/cloud/utils/TestProfiler.java | 34 ++++++++++---
8 files changed, 74 insertions(+), 25 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/cloudstack/blob/5557ad55/engine/orchestration/src/com/cloud/agent/manager/SynchronousListener.java
----------------------------------------------------------------------
diff --git a/engine/orchestration/src/com/cloud/agent/manager/SynchronousListener.java b/engine/orchestration/src/com/cloud/agent/manager/SynchronousListener.java
index 5da1b27..28c60c1 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;
http://git-wip-us.apache.org/repos/asf/cloudstack/blob/5557ad55/framework/db/src/com/cloud/utils/db/GlobalLock.java
----------------------------------------------------------------------
diff --git a/framework/db/src/com/cloud/utils/db/GlobalLock.java b/framework/db/src/com/cloud/utils/db/GlobalLock.java
index e03da53..662ba92 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;
http://git-wip-us.apache.org/repos/asf/cloudstack/blob/5557ad55/framework/db/test/com/cloud/utils/db/GlobalLockTest.java
----------------------------------------------------------------------
diff --git a/framework/db/test/com/cloud/utils/db/GlobalLockTest.java b/framework/db/test/com/cloud/utils/db/GlobalLockTest.java
index c26f248..58c496f 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);
}
http://git-wip-us.apache.org/repos/asf/cloudstack/blob/5557ad55/server/src/com/cloud/network/security/SecurityGroupManagerImpl2.java
----------------------------------------------------------------------
diff --git a/server/src/com/cloud/network/security/SecurityGroupManagerImpl2.java b/server/src/com/cloud/network/security/SecurityGroupManagerImpl2.java
index 3c0c5c3..47f6e77 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());
}
}
http://git-wip-us.apache.org/repos/asf/cloudstack/blob/5557ad55/server/test/com/cloud/network/security/SecurityGroupManagerImpl2Test.java
----------------------------------------------------------------------
diff --git a/server/test/com/cloud/network/security/SecurityGroupManagerImpl2Test.java b/server/test/com/cloud/network/security/SecurityGroupManagerImpl2Test.java
index 9c41ac2..ad1da32 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
http://git-wip-us.apache.org/repos/asf/cloudstack/blob/5557ad55/server/test/com/cloud/network/security/SecurityGroupQueueTest.java
----------------------------------------------------------------------
diff --git a/server/test/com/cloud/network/security/SecurityGroupQueueTest.java b/server/test/com/cloud/network/security/SecurityGroupQueueTest.java
index 6c104c2..e90cc58 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());
}
http://git-wip-us.apache.org/repos/asf/cloudstack/blob/5557ad55/utils/src/com/cloud/utils/Profiler.java
----------------------------------------------------------------------
diff --git a/utils/src/com/cloud/utils/Profiler.java b/utils/src/com/cloud/utils/Profiler.java
index 6082a92..5977453 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
http://git-wip-us.apache.org/repos/asf/cloudstack/blob/5557ad55/utils/test/com/cloud/utils/TestProfiler.java
----------------------------------------------------------------------
diff --git a/utils/test/com/cloud/utils/TestProfiler.java b/utils/test/com/cloud/utils/TestProfiler.java
index 4323f1d..cbd28f5 100644
--- a/utils/test/com/cloud/utils/TestProfiler.java
+++ b/utils/test/com/cloud/utils/TestProfiler.java
@@ -28,26 +28,48 @@ 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();
try {
@@ -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
[3/3] git commit: updated refs/heads/master to cbf5155
Posted by da...@apache.org.
Renaming a couple of varibale to avoid misunderstanding
- All "micro" references have been replaced with "nano"
Signed-off-by: Daan Hoogland <da...@onecht.net>
This closes #516
Project: http://git-wip-us.apache.org/repos/asf/cloudstack/repo
Commit: http://git-wip-us.apache.org/repos/asf/cloudstack/commit/cbf5155f
Tree: http://git-wip-us.apache.org/repos/asf/cloudstack/tree/cbf5155f
Diff: http://git-wip-us.apache.org/repos/asf/cloudstack/diff/cbf5155f
Branch: refs/heads/master
Commit: cbf5155f7b89d032c092c95e4dd507e927cf37a0
Parents: 2f14537
Author: wilderrodrigues <wr...@schubergphilis.com>
Authored: Tue Jun 23 22:46:19 2015 +0200
Committer: Daan Hoogland <da...@onecht.net>
Committed: Wed Jun 24 09:36:41 2015 +0200
----------------------------------------------------------------------
utils/src/com/cloud/utils/Profiler.java | 4 ++--
utils/test/com/cloud/utils/TestProfiler.java | 13 +++++++++----
2 files changed, 11 insertions(+), 6 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/cloudstack/blob/cbf5155f/utils/src/com/cloud/utils/Profiler.java
----------------------------------------------------------------------
diff --git a/utils/src/com/cloud/utils/Profiler.java b/utils/src/com/cloud/utils/Profiler.java
index 5977453..f8e44bd 100644
--- a/utils/src/com/cloud/utils/Profiler.java
+++ b/utils/src/com/cloud/utils/Profiler.java
@@ -46,8 +46,8 @@ public class Profiler {
*/
public long getDuration() {
if (startTickNanoSeconds != null && stopTickNanoSeconds != null) {
- final long timeInMicroSeconds = stopTickNanoSeconds - startTickNanoSeconds;
- return timeInMicroSeconds;
+ final long timeInNanoSeconds = stopTickNanoSeconds - startTickNanoSeconds;
+ return timeInNanoSeconds;
}
return -1;
http://git-wip-us.apache.org/repos/asf/cloudstack/blob/cbf5155f/utils/test/com/cloud/utils/TestProfiler.java
----------------------------------------------------------------------
diff --git a/utils/test/com/cloud/utils/TestProfiler.java b/utils/test/com/cloud/utils/TestProfiler.java
index d801059..6861f06 100644
--- a/utils/test/com/cloud/utils/TestProfiler.java
+++ b/utils/test/com/cloud/utils/TestProfiler.java
@@ -28,6 +28,7 @@ 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 ONE_SECOND = 1000l;
private static final long MILLIS_FACTOR = 1000l;
private static final int MARGIN = 100;
private static final double EXPONENT = 3d;
@@ -39,13 +40,13 @@ public class TestProfiler extends Log4jEnabledTestCase {
final Profiler pf = new Profiler();
pf.start();
try {
- Thread.sleep(MILLIS_FACTOR);
+ Thread.sleep(ONE_SECOND);
} catch (final InterruptedException e) {
}
pf.stop();
final long durationInMillis = pf.getDurationInMillis();
- s_logger.info("Duration : " + durationInMillis);
+ s_logger.info("Duration in Millis: " + durationInMillis);
// 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
@@ -56,16 +57,17 @@ public class TestProfiler extends Log4jEnabledTestCase {
}
@Test
- public void testProfilerInMicro() {
+ public void testProfilerInNano() {
final Profiler pf = new Profiler();
pf.start();
try {
- Thread.sleep(MILLIS_FACTOR);
+ Thread.sleep(ONE_SECOND);
} catch (final InterruptedException e) {
}
pf.stop();
final long duration = pf.getDuration();
+ s_logger.info("Duration in Nano: " + duration);
Assert.assertTrue(duration >= Math.pow(MILLIS_FACTOR, EXPONENT));
}
@@ -101,6 +103,9 @@ public class TestProfiler extends Log4jEnabledTestCase {
long nanoTime2 = 0l;
nanoTime1 = System.nanoTime();
nanoTime2 = System.nanoTime();
+
+ // Using sysout here because is faster than the logger and we don't want to
+ // waste time.
System.out.println("Nano time 1: " + nanoTime1);
System.out.println("Nano time 2: " + nanoTime2);