From fcb22f08f01a47e1813e67327065eb884d1fb76a Mon Sep 17 00:00:00 2001
From: Tagir Valeev <Tagir.Valeev@jetbrains.com>
Date: Fri, 14 Dec 2018 12:06:03 +0700
Subject: [PATCH] DataFlowRunner: add reporting of slow analysis in
 EAP/internal

---
 .../dataFlow/DataFlowRunner.java              | 72 +++++++++++++++++++
 1 file changed, 72 insertions(+)

diff --git a/java/java-analysis-impl/src/com/intellij/codeInspection/dataFlow/DataFlowRunner.java b/java/java-analysis-impl/src/com/intellij/codeInspection/dataFlow/DataFlowRunner.java
index 148133d0e86a..461a75a12f4b 100644
--- a/java/java-analysis-impl/src/com/intellij/codeInspection/dataFlow/DataFlowRunner.java
+++ b/java/java-analysis-impl/src/com/intellij/codeInspection/dataFlow/DataFlowRunner.java
@@ -8,6 +8,8 @@ import com.intellij.codeInspection.dataFlow.value.DfaExpressionFactory;
 import com.intellij.codeInspection.dataFlow.value.DfaValue;
 import com.intellij.codeInspection.dataFlow.value.DfaValueFactory;
 import com.intellij.codeInspection.dataFlow.value.DfaVariableValue;
+import com.intellij.openapi.application.Application;
+import com.intellij.openapi.application.ApplicationManager;
 import com.intellij.openapi.diagnostic.Attachment;
 import com.intellij.openapi.diagnostic.Logger;
 import com.intellij.openapi.diagnostic.RuntimeExceptionWithAttachments;
@@ -30,7 +32,10 @@ import one.util.streamex.StreamEx;
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.annotations.Nullable;
 
+import java.lang.management.ManagementFactory;
+import java.lang.management.ThreadMXBean;
 import java.util.*;
+import java.util.concurrent.TimeUnit;
 import java.util.function.BiConsumer;
 import java.util.function.Consumer;
 
@@ -150,7 +155,9 @@ public class DataFlowRunner {
     ControlFlow flow = null;
     DfaInstructionState lastInstructionState = null;
     try {
+      TimeStats stats = new TimeStats();
       flow = new ControlFlowAnalyzer(myValueFactory, psiBlock, ignoreAssertions, myInlining).buildControlFlow();
+      stats.endFlow();
       if (flow == null) return RunnerResult.NOT_APPLICABLE;
       int[] loopNumber = LoopAnalyzer.calcInLoop(flow);
 
@@ -181,7 +188,9 @@ public class DataFlowRunner {
       int stateLimit = Registry.intValue("ide.dfa.state.limit");
       int count = 0;
       while (!queue.isEmpty()) {
+        stats.startMerge();
         List<DfaInstructionState> states = queue.getNextInstructionStates(joinInstructions);
+        stats.endMerge();
         if (states.size() > MAX_STATES_PER_BRANCH) {
           LOG.trace("Too complex because too many different possible states");
           return RunnerResult.TOO_COMPLEX;
@@ -209,7 +218,9 @@ public class DataFlowRunner {
               continue;
             }
             if (processed.size() > MERGING_BACK_BRANCHES_THRESHOLD) {
+              stats.startMerge();
               instructionState = mergeBackBranches(instructionState, processed);
+              stats.endMerge();
               if (containsState(processed, instructionState)) {
                 continue;
               }
@@ -262,6 +273,11 @@ public class DataFlowRunner {
 
       LOG.trace("Analysis ok");
       myWasForciblyMerged |= queue.wasForciblyMerged();
+      stats.endProcess();
+      if (stats.isTooSlow()) {
+        String message = "Too slow DFA\nIf you report this problem, please consider including the attachments\n" + stats;
+        reportDfaProblem(psiBlock, flow, null, new RuntimeException(message));
+      }
       return RunnerResult.OK;
     }
     catch (ProcessCanceledException ex) {
@@ -578,4 +594,60 @@ public class DataFlowRunner {
 
     return Pair.create(trueSet, falseSet);
   }
+  
+  private static class TimeStats {
+    private static final long DFA_EXECUTION_TIME_TO_REPORT_NANOS = TimeUnit.SECONDS.toNanos(1);
+    private final @Nullable ThreadMXBean myMxBean;
+    private final long myStart;
+    private long myMergeStart, myFlowTime, myMergeTime, myProcessTime;
+
+    TimeStats() {
+      Application application = ApplicationManager.getApplication();
+      if (application.isInternal() || application.isEAP()) {
+        myMxBean = ManagementFactory.getThreadMXBean();
+        myStart = myMxBean.getCurrentThreadCpuTime();
+      } else {
+        myMxBean = null;
+        myStart = 0;
+      }
+    }
+    
+    void endFlow() {
+      if (myMxBean != null) {
+        myFlowTime = myMxBean.getCurrentThreadCpuTime() - myStart;
+      }
+    }
+    
+    void startMerge() {
+      if (myMxBean != null) {
+        myMergeStart = myMxBean.getCurrentThreadCpuTime();
+      }
+    }
+    
+    void endMerge() {
+      if (myMxBean != null) {
+        myMergeTime += myMxBean.getCurrentThreadCpuTime() - myMergeStart;
+      }
+    }
+    
+    void endProcess() {
+      if (myMxBean != null) {
+        myProcessTime = myMxBean.getCurrentThreadCpuTime() - myStart;
+      }
+    }
+    
+    boolean isTooSlow() {
+      return myProcessTime > DFA_EXECUTION_TIME_TO_REPORT_NANOS; 
+    }
+
+    @Override
+    public String toString() {
+      double flowTime = myFlowTime/1e9;
+      double mergeTime = myMergeTime/1e9;
+      double interpretTime = (myProcessTime - myFlowTime - myMergeTime)/1e9;
+      double totalTime = myProcessTime/1e9;
+      return String.format(Locale.ENGLISH, "Building ControlFlow: %.2fs\nMerging states: %.2fs\nInterpreting: %.2fs\nTotal: %.2fs", 
+                           flowTime, mergeTime, interpretTime, totalTime);
+    }
+  }
 }