diff --git a/pxr/base/tf/testenv/stopwatch.cpp b/pxr/base/tf/testenv/stopwatch.cpp index 4b7dc03e6c..6e6214504a 100644 --- a/pxr/base/tf/testenv/stopwatch.cpp +++ b/pxr/base/tf/testenv/stopwatch.cpp @@ -43,6 +43,13 @@ IsClose(double a, double b, double epsilon=1e-3) && diff <= epsilon * abs(b); } +static bool +IsCloselyBounded(double value, double lower, double upper, double epsilon=1e-3) +{ + return (1 - epsilon) * lower <= value + && value <= (1 + epsilon) * upper; +} + static bool Test_TfStopwatch() { @@ -64,43 +71,57 @@ Test_TfStopwatch() // Delay .5 seconds (500 million nanoseconds) // + auto pre_start = std::chrono::steady_clock::now(); watch1.Start(); - auto start = std::chrono::steady_clock::now(); + auto post_start = std::chrono::steady_clock::now(); std::this_thread::sleep_for(std::chrono::milliseconds(500)); + auto pre_stop = std::chrono::steady_clock::now(); watch1.Stop(); - auto end = std::chrono::steady_clock::now(); + auto post_stop = std::chrono::steady_clock::now(); - std::chrono::duration elapsed = end - start; + std::chrono::duration minElapsed = pre_stop - post_start; + std::chrono::duration maxElapsed = post_stop - pre_start; - // The value of watch1 should match the elapsed duration + // The value of watch1 should be bounded by minElapsed / maxElapsed: + // minElapsed < watch1 < maxElapsed // measured via std::chrono. This should be roughly .5 seconds, // but may be higher since sleep_for may overshoot the requested - // time. - if (!IsClose(watch1.GetSeconds(), elapsed.count())) { + // time. We take the upper / lower bounds to account for possible thread + // scheduling issues. + if (!IsCloselyBounded(watch1.GetSeconds(), minElapsed.count(), + maxElapsed.count())) { cout << "Sleep for .5 seconds but got: " << endl << "TfStopwatch: " << watch1.GetSeconds() << endl - << "std::chrono: " << elapsed.count() << endl; + << "std::chrono (lower bound): " << minElapsed.count() << endl + << "std::chrono (upper bound): " << maxElapsed.count() << endl; ok = false; } // Delay another .5 seconds and see if watch is near 1 // + pre_start = std::chrono::steady_clock::now(); watch1.Start(); - start = std::chrono::steady_clock::now(); + post_start = std::chrono::steady_clock::now(); std::this_thread::sleep_for(std::chrono::milliseconds(500)); + pre_stop = std::chrono::steady_clock::now(); watch1.Stop(); - end = std::chrono::steady_clock::now(); + post_stop = std::chrono::steady_clock::now(); + - elapsed += (end - start); + minElapsed += pre_stop - post_start; + maxElapsed += post_stop - pre_start; // The value of watch1 should match the updated elapsed duration. - if (!IsClose(watch1.GetSeconds(), elapsed.count())) { + if (!IsCloselyBounded(watch1.GetSeconds(), minElapsed.count(), + maxElapsed.count())) { cout << "Sleep for 1.0 seconds but got: " << endl << "TfStopwatch: " << watch1.GetSeconds() << endl - << "std::chrono: " << elapsed.count() << endl; + << "std::chrono (lower bound): " << minElapsed.count() << endl + << "std::chrono (upper bound): " << maxElapsed.count() << endl; ok = false; } + // The value of watchCopy should be zero // if (watchCopy.GetSeconds() != 0.0) { diff --git a/pxr/base/trace/testenv/testTrace.py b/pxr/base/trace/testenv/testTrace.py index 0842d03ee9..bd2c3d7fff 100644 --- a/pxr/base/trace/testenv/testTrace.py +++ b/pxr/base/trace/testenv/testTrace.py @@ -204,22 +204,28 @@ def testFunc(): gc.enabled = True sleepTime = 1.0 + pre_begin = time.time() b = gc.BeginEvent("Test tuple") - b2 = time.time() + post_begin = time.time() time.sleep(sleepTime) + pre_end = time.time() e = gc.EndEvent("Test tuple") - e2 = time.time() + post_end = time.time() elapsedSeconds = Trace.GetElapsedSeconds(b, e) - expectedElapsedSeconds = e2 - b2 + expectedMinSeconds = pre_end - post_begin + expectedMaxSeconds = post_end - pre_begin gr.Report() - elapsedDiff = abs(elapsedSeconds - expectedElapsedSeconds) - self.assertTrue(elapsedDiff < 0.005, - "Elapsed: {} Expected: {} Diff: {}".format( - elapsedSeconds, expectedElapsedSeconds, - elapsedDiff)) - + epsilon = 0.005 + self.assertGreater(elapsedSeconds, expectedMinSeconds - epsilon, + "Elapsed: {} Expected Min: {} Diff: {}".format( + elapsedSeconds, expectedMinSeconds, + expectedMinSeconds - elapsedSeconds)) + self.assertLess(elapsedSeconds, expectedMaxSeconds + epsilon, + "Elapsed: {} Expected Max: {} Diff: {}".format( + elapsedSeconds, expectedMaxSeconds, + elapsedSeconds - expectedMaxSeconds)) print("") if __name__ == '__main__':