diff --git a/platform/testFramework/src/com/intellij/testFramework/PlatformTestUtil.java b/platform/testFramework/src/com/intellij/testFramework/PlatformTestUtil.java index 2f025e90c3d7..60de37e321e4 100644 --- a/platform/testFramework/src/com/intellij/testFramework/PlatformTestUtil.java +++ b/platform/testFramework/src/com/intellij/testFramework/PlatformTestUtil.java @@ -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); } diff --git a/platform/testFramework/src/com/intellij/testFramework/Timings.java b/platform/testFramework/src/com/intellij/testFramework/Timings.java index 74173a93bc82..7c4d864a2d5f 100644 --- a/platform/testFramework/src/com/intellij/testFramework/Timings.java +++ b/platform/testFramework/src/com/intellij/testFramework/Timings.java @@ -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."; } }