performance tests: print gc and per-thread time stats

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<GarbageCollectorMXBean> ourGcBeans = ManagementFactory.getGarbageCollectorMXBeans();
+
+  final long durationMs;
+  private final TObjectLongHashMap<GarbageCollectorMXBean> myGcTimes;
+  private final TLongLongHashMap myThreadTimes;
+
+  private CpuUsageData(long durationMs, TObjectLongHashMap<GarbageCollectorMXBean> gcTimes, TLongLongHashMap threadTimes) {
+    this.durationMs = durationMs;
+    myGcTimes = gcTimes;
+    myThreadTimes = threadTimes;
+  }
+
+  String getGcStats() {
+    List<Pair<Long, String>> times = new ArrayList<>();
+    myGcTimes.forEachEntry((bean, time) -> {
+      times.add(Pair.create(time, bean.getName()));
+      return true;
+    });
+    return printLongestNames(times);
+  }
+
+  String getThreadStats() {
+    List<Pair<Long, String>> times = new ArrayList<>();
+    myThreadTimes.forEachEntry((id, time) -> {
+      ThreadInfo info = ourThreadMXBean.getThreadInfo(id);
+      times.add(Pair.create(toMillis(time), info == null ? "<unknown>" : info.getThreadName()));
+      return true;
+    });
+    return printLongestNames(times);
+  }
+
+  @NotNull
+  private static String printLongestNames(List<Pair<Long, String>> 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 <E extends Throwable> CpuUsageData measureCpuUsage(ThrowableRunnable<E> runnable) throws E {
+    TObjectLongHashMap<GarbageCollectorMXBean> 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);
+  }
+
+}

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);