Relax 053-wait-some sucess criteria
Drop constraint on total extra delay. Shorten maximum wait time.
But then only only require success in 2 out of 3 runs.
Switch timing to use nanoTime() to get a monotonic clock. This might
have contributed to a few of the observed failures.
Bug: 175435088
Test: Prun-test --host 053-wait-some
Test: Retest with sleepy.wait(delay * 3/2); on line 66.
Test: Retest with timing set to true in code.
Change-Id: Ic8e392340ba1d70782f2a5303bfebf1d7251a86b
diff --git a/test/053-wait-some/src/Main.java b/test/053-wait-some/src/Main.java
index 0fd9e8d..2de90b7 100644
--- a/test/053-wait-some/src/Main.java
+++ b/test/053-wait-some/src/Main.java
@@ -22,6 +22,17 @@
private final static long[] DELAYS = {
200, 500, 1000, 2000, 3500, 8000
};
+ // This test is inherently prone to failures through scheduling delays and spurious wakeups.
+ // We try it repeatedly, and check that failures are "rare enough".
+ // Currently we go for success on the first try or 2 out of 3.
+ private final static int NUM_TRIES = 3;
+ private final static int MAX_FAILURES = 1;
+ private final static int NANOS_PER_MILLI = 1_000_000;
+
+ // Allow a random scheduling delay of up to 400 msecs. That value is empirically determined
+ // from failure logs, though we do get occasional violations.
+ // We seem to get very occasional very long delays on host, perhaps due to getting paged out.
+ private final static int MAX_SCHED_MILLIS = 400;
public static void main(String[] args) {
boolean timing = (args.length >= 1) && args[0].equals("--timing");
@@ -30,7 +41,6 @@
public static void doit(boolean timing) {
Object sleepy = new Object();
- long start, end;
synchronized (sleepy) {
try {
@@ -42,53 +52,56 @@
ie.printStackTrace(System.out);
}
- long total_extra_delay = 0;
for (long delay : DELAYS) {
System.out.println("Waiting for " + delay + "ms...");
+ long min = delay - 1;
+ long max = delay + MAX_SCHED_MILLIS;
- start = System.currentTimeMillis();
- try {
- sleepy.wait(delay);
- } catch (InterruptedException ie) {
- ie.printStackTrace(System.out);
- }
- end = System.currentTimeMillis();
-
- long elapsed = end - start;
+ int num_failures = 0;
+ long elapsed_to_report = 0;
boolean showTime = timing;
+ for (int i = 0; i < (timing ? 1 : NUM_TRIES); ++i) {
+ final long start = System.nanoTime();
+ try {
+ sleepy.wait(delay);
+ } catch (InterruptedException ie) {
+ ie.printStackTrace(System.out);
+ }
+ final long end = System.nanoTime();
- if (! timing) {
- // Allow a random scheduling delay of up to 600 msecs.
- // That value is empirically determined from failure logs.
- // We seem to get very occasional very long delays on host, perhaps due
- // to getting paged out.
- final long epsilon = 600;
- long min = delay - 1;
- long max = delay + epsilon;
- total_extra_delay += elapsed - delay;
+ long elapsed = (end - start + NANOS_PER_MILLI / 2) / NANOS_PER_MILLI;
- if (elapsed < min) {
- // This can legitimately happen due to premature wake-ups.
- // This seems rare and unexpected enough in practice that we should
- // still report.
- System.out.println(" Elapsed time was too short");
- showTime = true;
- } else if (elapsed > max) {
- System.out.println(" Elapsed time was too long: "
- + "elapsed=" + elapsed + " max=" + max);
- showTime = true;
+ if (timing) {
+ elapsed_to_report = elapsed;
+ } else {
+ if (elapsed < min || elapsed > max) {
+ ++ num_failures;
+ elapsed_to_report = elapsed;
+ } else if (i == 0) {
+ // Save time if we immediately succeeded.
+ break;
+ }
}
}
-
+ if (num_failures > MAX_FAILURES) {
+ System.out.println("Failed " + num_failures + " times out of "
+ + NUM_TRIES + " tries.");
+ showTime = true;
+ if (elapsed_to_report < min) {
+ // This can legitimately happen due to premature wake-ups.
+ // This seems rare and unexpected enough in practice that we should
+ // still report if it occurs repeatedly.
+ System.out.println(" Elapsed time was too short");
+ } else if (elapsed_to_report > max) {
+ System.out.println(" Elapsed time was too long: "
+ + "elapsed = " + elapsed_to_report + " max = " + max);
+ }
+ }
if (showTime) {
System.out.println(" Wall clock elapsed "
- + elapsed + "ms");
+ + elapsed_to_report + "ms");
}
}
- if (total_extra_delay > 1000) {
- System.out.println(" Total unrequested delay of " + total_extra_delay
- + "msecs was too long");
- }
}
}
}