Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Make timing tests compare to upper / lower bounds #2068

Merged
merged 1 commit into from
Dec 9, 2022
Merged

Make timing tests compare to upper / lower bounds #2068

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
45 changes: 33 additions & 12 deletions pxr/base/tf/testenv/stopwatch.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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()
{
Expand All @@ -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<double> elapsed = end - start;
std::chrono::duration<double> minElapsed = pre_stop - post_start;
std::chrono::duration<double> 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) {
Expand Down
24 changes: 15 additions & 9 deletions pxr/base/trace/testenv/testTrace.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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__':
Expand Down