public static void assertTiming(final String message, final long expectedMs, final long actual) {
if (COVERAGE_ENABLED_BUILD) return;
final long expectedOnMyMachine =
Math.max(1, expectedMs * Timings.MACHINE_TIMING / Timings.ETALON_TIMING);
// Allow 10% more in case of test machine is busy.
String logMessage = message;
if (actual > expectedOnMyMachine) {
int percentage = (int) (100.0 * (actual - expectedOnMyMachine) / expectedOnMyMachine);
logMessage += ". Operation took " + percentage + "% longer than expected";
}
logMessage +=
". Expected on my machine: "
+ expectedOnMyMachine
+ "."
+ " Actual: "
+ actual
+ "."
+ " Expected on Standard machine: "
+ expectedMs
+ ";"
+ " Actual on Standard: "
+ actual * Timings.ETALON_TIMING / Timings.MACHINE_TIMING
+ ";"
+ " Timings: CPU="
+ Timings.CPU_TIMING
+ ", I/O="
+ Timings.IO_TIMING
+ "."
+ " ("
+ (int) (Timings.MACHINE_TIMING * 1.0 / Timings.ETALON_TIMING * 100)
+ "% of the Standard)"
+ ".";
final double acceptableChangeFactor = 1.1;
if (actual < expectedOnMyMachine) {
System.out.println(logMessage);
TeamCityLogger.info(logMessage);
} else if (actual < expectedOnMyMachine * acceptableChangeFactor) {
TeamCityLogger.warning(logMessage, null);
} else {
// throw AssertionFailedError to try one more time
throw new AssertionFailedError(logMessage);
}
}
public void assertTiming() {
assert expectedMs != 0 : "Must call .expect() before run test";
if (COVERAGE_ENABLED_BUILD) return;
while (true) {
attempts--;
long start;
try {
if (setup != null) setup.run();
start = System.currentTimeMillis();
test.run();
} catch (Throwable throwable) {
throw new RuntimeException(throwable);
}
long finish = System.currentTimeMillis();
long duration = finish - start;
int expectedOnMyMachine = expectedMs;
if (adjustForCPU) {
expectedOnMyMachine =
adjust(expectedOnMyMachine, Timings.CPU_TIMING, Timings.ETALON_CPU_TIMING);
expectedOnMyMachine =
usesAllCPUCores
? expectedOnMyMachine * 8 / JobSchedulerImpl.CORES_COUNT
: expectedOnMyMachine;
}
if (adjustForIO) {
expectedOnMyMachine =
adjust(expectedOnMyMachine, Timings.IO_TIMING, Timings.ETALON_IO_TIMING);
}
// Allow 10% more in case of test machine is busy.
String logMessage = message;
if (duration > expectedOnMyMachine) {
int percentage = (int) (100.0 * (duration - expectedOnMyMachine) / expectedOnMyMachine);
logMessage += ": " + percentage + "% longer";
}
logMessage +=
". Expected: "
+ formatTime(expectedOnMyMachine)
+ ". Actual: "
+ formatTime(duration)
+ "."
+ Timings.getStatistics();
final double acceptableChangeFactor = 1.1;
if (duration < expectedOnMyMachine) {
int percentage = (int) (100.0 * (expectedOnMyMachine - duration) / expectedOnMyMachine);
logMessage = percentage + "% faster. " + logMessage;
TeamCityLogger.info(logMessage);
System.out.println("SUCCESS: " + logMessage);
} else if (duration < expectedOnMyMachine * acceptableChangeFactor) {
TeamCityLogger.warning(logMessage, null);
System.out.println("WARNING: " + logMessage);
} else {
// try one more time
if (attempts == 0) {
// try {
// Object result =
// Class.forName("com.intellij.util.ProfilingUtil").getMethod("captureCPUSnapshot").invoke(null);
// System.err.println("CPU snapshot captured in '"+result+"'");
// }
// catch (Exception e) {
// }
throw new AssertionFailedError(logMessage);
}
System.gc();
System.gc();
System.gc();
String s = "Another epic fail (remaining attempts: " + attempts + "): " + logMessage;
TeamCityLogger.warning(s, null);
System.err.println(s);
// if (attempts == 1) {
// try {
//
// Class.forName("com.intellij.util.ProfilingUtil").getMethod("startCPUProfiling").invoke(null);
// }
// catch (Exception e) {
// }
// }
continue;
}
break;
}
}