report cleanup: no more "etalons" and "epic fails"

This commit is contained in:
Gregory.Shrago
2017-03-28 19:26:58 +03:00
parent ce25c88fe4
commit ac4e31c5d8
2 changed files with 35 additions and 51 deletions
@@ -80,8 +80,6 @@ import java.io.IOException;
import java.io.OutputStream;
import java.io.PrintStream;
import java.nio.charset.Charset;
import java.text.DecimalFormat;
import java.text.DecimalFormatSymbols;
import java.util.*;
import java.util.List;
import java.util.concurrent.CopyOnWriteArrayList;
@@ -461,7 +459,7 @@ public class PlatformTestUtil {
public static void assertTiming(final String message, final long expectedMs, final long actual) {
if (COVERAGE_ENABLED_BUILD) return;
long expectedOnMyMachine = Math.max(1, expectedMs * Timings.CPU_TIMING / Timings.ETALON_CPU_TIMING);
long expectedOnMyMachine = Math.max(1, expectedMs * Timings.CPU_TIMING / Timings.REFERENCE_CPU_TIMING);
// Allow 10% more in case of test machine is busy.
String logMessage = message;
@@ -493,7 +491,7 @@ public class PlatformTestUtil {
*/
@Contract(pure = true) // to warn about not calling .assertTiming() in the end
public static TestInfo startPerformanceTest(@NonNls @NotNull String message, int expectedMs, @NotNull ThrowableRunnable test) {
return new TestInfo(test, expectedMs,message);
return new TestInfo(test, expectedMs, message);
}
public static boolean canRunTest(@NotNull Class testCaseClass) {
@@ -541,7 +539,7 @@ public class PlatformTestUtil {
private final ThrowableRunnable test; // runnable to measure
private final int expectedMs; // millis the test is expected to run
private ThrowableRunnable setup; // to run before each test
private int usedEtalonCpuCores = 1;
private int usedReferenceCpuCores = 1;
private int attempts = 4; // number of retries if performance failed
private final String message; // to print on fail
private boolean adjustForIO = true; // true if test uses IO, timings need to be re-calibrated according to this agent disk performance
@@ -560,7 +558,7 @@ public class PlatformTestUtil {
@Contract(pure = true) // to warn about not calling .assertTiming() in the end
public TestInfo usesAllCPUCores() { return usesMultipleCPUCores(8); }
@Contract(pure = true) // to warn about not calling .assertTiming() in the end
public TestInfo usesMultipleCPUCores(int maxCores) { assert adjustForCPU : "This test configured to be io-bound, it cannot use all cores";usedEtalonCpuCores = maxCores; return this; }
public TestInfo usesMultipleCPUCores(int maxCores) { assert adjustForCPU : "This test configured to be io-bound, it cannot use all cores"; usedReferenceCpuCores = maxCores; return this; }
@Contract(pure = true) // to warn about not calling .assertTiming() in the end
public TestInfo cpuBound() { adjustForIO = false; adjustForCPU = true; return this; }
@Contract(pure = true) // to warn about not calling .assertTiming() in the end
@@ -602,39 +600,37 @@ public class PlatformTestUtil {
int expectedOnMyMachine = expectedMs;
if (adjustForCPU) {
int coreCountUsedHere = usedEtalonCpuCores < 8 ? Math.min(JobSchedulerImpl.CORES_COUNT, usedEtalonCpuCores) : JobSchedulerImpl.CORES_COUNT;
expectedOnMyMachine *= usedEtalonCpuCores;
expectedOnMyMachine = adjust(expectedOnMyMachine, Timings.CPU_TIMING, Timings.ETALON_CPU_TIMING, useLegacyScaling);
int coreCountUsedHere = usedReferenceCpuCores < 8 ? Math.min(JobSchedulerImpl.CORES_COUNT, usedReferenceCpuCores) : JobSchedulerImpl.CORES_COUNT;
expectedOnMyMachine *= usedReferenceCpuCores;
expectedOnMyMachine = adjust(expectedOnMyMachine, Timings.CPU_TIMING, Timings.REFERENCE_CPU_TIMING, useLegacyScaling);
expectedOnMyMachine /= coreCountUsedHere;
}
if (adjustForIO) {
expectedOnMyMachine = adjust(expectedOnMyMachine, Timings.IO_TIMING, Timings.ETALON_IO_TIMING, useLegacyScaling);
expectedOnMyMachine = adjust(expectedOnMyMachine, Timings.IO_TIMING, Timings.REFERENCE_IO_TIMING, useLegacyScaling);
}
// 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 += ": " + "\u001B[31;1m " + percentage + "% longer" + "\u001B[0m";
}
else {
logMessage += " NOT!";
}
logMessage +=
"\n Expected: " + formatTime(expectedOnMyMachine) +
"\n Actual: " + formatTime(duration) +
"\n " + Timings.getStatistics() + "\n GC stats: " + data.getGcStats() + "\n Most active threads: " + data.getThreadStats();
final double acceptableChangeFactor = 1.1;
if (duration < expectedOnMyMachine) {
int percentage = (int)(100.0 * (expectedOnMyMachine - duration) / expectedOnMyMachine);
logMessage = percentage + "% faster. " + logMessage;
int percentage = (int)(100.0 * (duration - expectedOnMyMachine) / expectedOnMyMachine);
String logMessage = String.format(
"%s took \u001B[31;1m%d%% %s time\u001B[0m than expected" +
"\n Expected: %s" +
"\n Actual: %s" +
"\n %s\n GC stats: %s" +
"\n Most active threads: %s",
message, Math.abs(percentage), percentage > 0 ? "more" : "less",
StringUtil.formatDuration(expectedOnMyMachine),
StringUtil.formatDuration(duration),
Timings.getStatistics(),
data.getGcStats(), data.getThreadStats());
double acceptableChangeFactor = 1.1;
if (duration < expectedOnMyMachine) {
TeamCityLogger.info(logMessage);
System.out.println("SUCCESS: " + logMessage);
System.out.println("\nSUCCESS: " + logMessage);
}
else if (duration < expectedOnMyMachine * acceptableChangeFactor) {
TeamCityLogger.warning(logMessage, null);
System.out.println("WARNING: " + logMessage);
System.out.println("\nWARNING: " + logMessage);
}
else {
// try one more time
@@ -651,7 +647,7 @@ public class PlatformTestUtil {
System.gc();
System.gc();
System.gc();
String s = "Another epic fail (remaining attempts: " + attempts + "): " + logMessage;
String s = logMessage + "\n " + attempts + " attempts remain";
TeamCityLogger.warning(s, null);
if (UsefulTestCase.IS_UNDER_TEAMCITY) {
System.err.println(s);
@@ -669,21 +665,9 @@ public class PlatformTestUtil {
}
}
private static String formatTime(long millis) {
String hint = "";
DecimalFormat format = new DecimalFormat("#.0", DecimalFormatSymbols.getInstance(Locale.US));
if (millis >= 60 * 1000) hint = format.format(millis / 60 / 1000.f) + "m";
if (millis >= 1000) hint += (hint.isEmpty() ? "" : " ") + format.format(millis / 1000.f) + "s";
String result = millis + "ms";
if (!hint.isEmpty()) {
result = result + " (" + hint + ")";
}
return result;
}
private static int adjust(int expectedOnMyMachine, long thisTiming, long etalonTiming, boolean useLegacyScaling) {
private static int adjust(int expectedOnMyMachine, long thisTiming, long referenceTiming, boolean useLegacyScaling) {
if (useLegacyScaling) {
double speed = 1.0 * thisTiming / etalonTiming;
double speed = 1.0 * thisTiming / referenceTiming;
double delta = speed < 1
? 0.9 + Math.pow(speed - 0.7, 2)
: 0.45 + Math.pow(speed - 0.25, 2);
@@ -691,7 +675,7 @@ public class PlatformTestUtil {
return expectedOnMyMachine;
}
else {
return (int)(expectedOnMyMachine * thisTiming / etalonTiming);
return (int)(expectedOnMyMachine * thisTiming / referenceTiming);
}
}
}
@@ -731,7 +715,7 @@ public class PlatformTestUtil {
System.gc();
System.gc();
System.gc();
String s = "Another epic fail (remaining attempts: " + attempts + "): " + e.getMessage();
String s = e.getMessage() + "\n " + attempts + " attempts remain";
TeamCityLogger.warning(s, null);
System.err.println(s);
}
@@ -33,8 +33,8 @@ public class Timings {
/**
* Measured on dual core p4 3HZ 1gig ram
*/
public static final long ETALON_CPU_TIMING = 200;
public static final long ETALON_IO_TIMING = 100;
public static final long REFERENCE_CPU_TIMING = 200;
public static final long REFERENCE_IO_TIMING = 100;
static {
CpuTimings timings = CpuTimings.calcStableCpuTiming();
@@ -91,13 +91,13 @@ public class Timings {
* @return value calibrated according to this machine speed. For slower machine, lesser value will be returned
*/
public static int adjustAccordingToMySpeed(int value, boolean isParallelizable) {
return Math.max(1, (int)(1.0 * value * ETALON_CPU_TIMING / CPU_TIMING) / 8 * (isParallelizable ? JobSchedulerImpl.CORES_COUNT : 1));
return Math.max(1, (int)(1.0 * value * REFERENCE_CPU_TIMING / CPU_TIMING) / 8 * (isParallelizable ? JobSchedulerImpl.CORES_COUNT : 1));
}
public static String getStatistics() {
return
" Timings: CPU=" + CPU_TIMING + " (" + (int)(CPU_TIMING*1.0/ ETALON_CPU_TIMING*100) + "% of the etalon)" +
", I/O=" + IO_TIMING + " (" + (int)(IO_TIMING*1.0/ ETALON_IO_TIMING*100) + "% of the etalon)" +
Runtime.getRuntime().availableProcessors() + " cores.";
" Timings: CPU=" + CPU_TIMING + " (" + (int)(CPU_TIMING * 1.0 / REFERENCE_CPU_TIMING * 100) + "% of the reference CPU)" +
", I/O=" + IO_TIMING + " (" + (int)(IO_TIMING * 1.0 / REFERENCE_IO_TIMING * 100) + "% of the reference IO)" +
", " + Runtime.getRuntime().availableProcessors() + " cores.";
}
}