diff --git a/platform/testFramework/src/com/intellij/testFramework/CpuUsageData.java b/platform/testFramework/src/com/intellij/testFramework/CpuUsageData.java new file mode 100644 index 000000000000..2adfca806b75 --- /dev/null +++ b/platform/testFramework/src/com/intellij/testFramework/CpuUsageData.java @@ -0,0 +1,105 @@ +/* + * Copyright 2000-2017 JetBrains s.r.o. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package com.intellij.testFramework; + +import com.intellij.openapi.util.Pair; +import com.intellij.util.ThrowableRunnable; +import gnu.trove.TLongLongHashMap; +import gnu.trove.TObjectLongHashMap; +import one.util.streamex.StreamEx; +import org.jetbrains.annotations.NotNull; + +import java.lang.management.GarbageCollectorMXBean; +import java.lang.management.ManagementFactory; +import java.lang.management.ThreadInfo; +import java.lang.management.ThreadMXBean; +import java.util.ArrayList; +import java.util.List; + +class CpuUsageData { + private static final ThreadMXBean ourThreadMXBean = ManagementFactory.getThreadMXBean(); + private static final List ourGcBeans = ManagementFactory.getGarbageCollectorMXBeans(); + + final long durationMs; + private final TObjectLongHashMap myGcTimes; + private final TLongLongHashMap myThreadTimes; + + private CpuUsageData(long durationMs, TObjectLongHashMap gcTimes, TLongLongHashMap threadTimes) { + this.durationMs = durationMs; + myGcTimes = gcTimes; + myThreadTimes = threadTimes; + } + + String getGcStats() { + List> times = new ArrayList<>(); + myGcTimes.forEachEntry((bean, time) -> { + times.add(Pair.create(time, bean.getName())); + return true; + }); + return printLongestNames(times); + } + + String getThreadStats() { + List> times = new ArrayList<>(); + myThreadTimes.forEachEntry((id, time) -> { + ThreadInfo info = ourThreadMXBean.getThreadInfo(id); + times.add(Pair.create(toMillis(time), info == null ? "" : info.getThreadName())); + return true; + }); + return printLongestNames(times); + } + + @NotNull + private static String printLongestNames(List> times) { + String stats = StreamEx.of(times) + .sortedBy(p -> -p.first) + .filter(p -> p.first > 10).limit(10) + .map(p -> "\"" + p.second + "\"" + " took " + p.first + "ms") + .joining(", "); + return stats.isEmpty() ? "insignificant" : stats; + } + + private static long toMillis(long timeNs) { + return timeNs / 1_000_000; + } + + static CpuUsageData measureCpuUsage(ThrowableRunnable runnable) throws E { + TObjectLongHashMap gcTimes = new TObjectLongHashMap<>(); + for (GarbageCollectorMXBean bean : ourGcBeans) { + gcTimes.put(bean, bean.getCollectionTime()); + } + + TLongLongHashMap threadTimes = new TLongLongHashMap(); + for (long id : ourThreadMXBean.getAllThreadIds()) { + threadTimes.put(id, ourThreadMXBean.getThreadUserTime(id)); + } + + long start = System.currentTimeMillis(); + runnable.run(); + long duration = System.currentTimeMillis() - start; + + for (long id : ourThreadMXBean.getAllThreadIds()) { + threadTimes.put(id, ourThreadMXBean.getThreadUserTime(id) - threadTimes.get(id)); + } + + for (GarbageCollectorMXBean bean : ourGcBeans) { + gcTimes.put(bean, bean.getCollectionTime() - gcTimes.get(bean)); + } + + return new CpuUsageData(duration, gcTimes, threadTimes); + } + +} diff --git a/platform/testFramework/src/com/intellij/testFramework/PlatformTestUtil.java b/platform/testFramework/src/com/intellij/testFramework/PlatformTestUtil.java index 820a3da099ea..78646ed91768 100644 --- a/platform/testFramework/src/com/intellij/testFramework/PlatformTestUtil.java +++ b/platform/testFramework/src/com/intellij/testFramework/PlatformTestUtil.java @@ -15,7 +15,6 @@ */ package com.intellij.testFramework; -import com.intellij.concurrency.JobSchedulerImpl; import com.intellij.execution.ExecutionException; import com.intellij.execution.configurations.GeneralCommandLine; import com.intellij.execution.process.ProcessOutput; @@ -575,23 +574,21 @@ public class PlatformTestUtil { while (true) { attempts--; - long start; + CpuUsageData data; try { if (setup != null) setup.run(); - start = System.currentTimeMillis(); - test.run(); + data = CpuUsageData.measureCpuUsage(test); } catch (Throwable throwable) { throw new RuntimeException(throwable); } - long finish = System.currentTimeMillis(); - long duration = finish - start; + long duration = data.durationMs; int expectedOnMyMachine = expectedMs; if (adjustForCPU) { expectedOnMyMachine = adjust(expectedOnMyMachine, Timings.CPU_TIMING, Timings.ETALON_CPU_TIMING, useLegacyScaling); - expectedOnMyMachine = usesAllCPUCores ? expectedOnMyMachine * 8 / JobSchedulerImpl.CORES_COUNT : expectedOnMyMachine; + expectedOnMyMachine = usesAllCPUCores ? expectedOnMyMachine * 8 : expectedOnMyMachine; } if (adjustForIO) { expectedOnMyMachine = adjust(expectedOnMyMachine, Timings.IO_TIMING, Timings.ETALON_IO_TIMING, useLegacyScaling); @@ -604,7 +601,9 @@ public class PlatformTestUtil { logMessage += ": " + "\u001B[31;1m " + percentage + "% longer" + "\u001B[0m"; } logMessage += - "\n Expected: " + formatTime(expectedOnMyMachine) + "\n Actual: " + formatTime(duration) + "\n " + Timings.getStatistics(); + "\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);