Add an option for logging total phase times
authorsbarati@apple.com <sbarati@apple.com@268f45cc-cd09-0410-ab3c-d52691b4dbfc>
Thu, 23 Jan 2020 02:27:26 +0000 (02:27 +0000)
committersbarati@apple.com <sbarati@apple.com@268f45cc-cd09-0410-ab3c-d52691b4dbfc>
Thu, 23 Jan 2020 02:27:26 +0000 (02:27 +0000)
https://bugs.webkit.org/show_bug.cgi?id=206623

Reviewed by Robin Morisset and Keith Miller.

* dfg/DFGPlan.cpp:
(JSC::DFG::Plan::compileInThreadImpl):
* jsc.cpp:
(runJSC):
* runtime/OptionsList.h:
* tools/CompilerTimingScope.cpp:
(JSC::CompilerTimingScope::CompilerTimingScope):
(JSC::CompilerTimingScope::~CompilerTimingScope):
(JSC::logTotalPhaseTimes):
* tools/CompilerTimingScope.h:

git-svn-id: https://svn.webkit.org/repository/webkit/trunk@254957 268f45cc-cd09-0410-ab3c-d52691b4dbfc

Source/JavaScriptCore/ChangeLog
Source/JavaScriptCore/dfg/DFGPlan.cpp
Source/JavaScriptCore/jsc.cpp
Source/JavaScriptCore/runtime/OptionsList.h
Source/JavaScriptCore/tools/CompilerTimingScope.cpp
Source/JavaScriptCore/tools/CompilerTimingScope.h

index 0b2f7a7..2ea6302 100644 (file)
@@ -1,3 +1,21 @@
+2020-01-22  Saam Barati  <sbarati@apple.com>
+
+        Add an option for logging total phase times
+        https://bugs.webkit.org/show_bug.cgi?id=206623
+
+        Reviewed by Robin Morisset and Keith Miller.
+
+        * dfg/DFGPlan.cpp:
+        (JSC::DFG::Plan::compileInThreadImpl):
+        * jsc.cpp:
+        (runJSC):
+        * runtime/OptionsList.h:
+        * tools/CompilerTimingScope.cpp:
+        (JSC::CompilerTimingScope::CompilerTimingScope):
+        (JSC::CompilerTimingScope::~CompilerTimingScope):
+        (JSC::logTotalPhaseTimes):
+        * tools/CompilerTimingScope.h:
+
 2020-01-22  Caio Lima  <ticaiolima@gmail.com>
 
         [32-bits][JIT] Fix build issues.
index 9d6d102..c9bbc4c 100644 (file)
@@ -238,7 +238,10 @@ void Plan::compileInThread(ThreadData* threadData)
 
 Plan::CompilationPath Plan::compileInThreadImpl()
 {
-    cleanMustHandleValuesIfNecessary();
+    {
+        CompilerTimingScope timingScope("DFG", "clean must handle values");
+        cleanMustHandleValuesIfNecessary();
+    }
 
     if (verboseCompilationEnabled(m_mode) && m_osrEntryBytecodeIndex) {
         dataLog("\n");
@@ -247,7 +250,11 @@ Plan::CompilationPath Plan::compileInThreadImpl()
     }
 
     Graph dfg(*m_vm, *this);
-    parse(dfg);
+
+    {
+        CompilerTimingScope timingScope("DFG", "bytecode parser");
+        parse(dfg);
+    }
 
     m_codeBlock->setCalleeSaveRegisters(RegisterSet::dfgCalleeSaveRegisters());
 
@@ -381,11 +388,15 @@ Plan::CompilationPath Plan::compileInThreadImpl()
         RUN_PHASE(performWatchpointCollection);
         dumpAndVerifyGraph(dfg, "Graph after optimization:");
         
-        JITCompiler dataFlowJIT(dfg);
-        if (m_codeBlock->codeType() == FunctionCode)
-            dataFlowJIT.compileFunction();
-        else
-            dataFlowJIT.compile();
+        {
+            CompilerTimingScope timingScope("DFG", "machine code generation");
+
+            JITCompiler dataFlowJIT(dfg);
+            if (m_codeBlock->codeType() == FunctionCode)
+                dataFlowJIT.compileFunction();
+            else
+                dataFlowJIT.compile();
+        }
         
         return DFGPath;
     }
index 7371d55..9166d52 100644 (file)
@@ -31,6 +31,7 @@
 #include "CatchScope.h"
 #include "CodeBlock.h"
 #include "CodeCache.h"
+#include "CompilerTimingScope.h"
 #include "Completion.h"
 #include "ConfigFile.h"
 #include "Disassembler.h"
@@ -3089,6 +3090,9 @@ int runJSC(const CommandLine& options, bool isWorker, const Func& func)
         std::sort(compileTimeKeys.begin(), compileTimeKeys.end());
         for (const CString& key : compileTimeKeys)
             printf("%40s: %.3lf ms\n", key.data(), compileTimeStats.get(key).milliseconds());
+
+        if (Options::reportTotalPhaseTimes())
+            logTotalPhaseTimes();
     }
 #endif
 
index f35c5e1..bc568f8 100644 (file)
@@ -164,6 +164,7 @@ constexpr bool enableWebAssemblyStreamingApi = false;
     v(Bool, reportDFGCompileTimes, false, Normal, "dumps JS function signature and the time it took to DFG and FTL compile") \
     v(Bool, reportFTLCompileTimes, false, Normal, "dumps JS function signature and the time it took to FTL compile") \
     v(Bool, reportTotalCompileTimes, false, Normal, nullptr) \
+    v(Bool, reportTotalPhaseTimes, false, Normal, "This prints phase times at the end of running script inside jsc.cpp") \
     v(Bool, reportParseTimes, false, Normal, "dumps JS function signature and the time it took to parse") \
     v(Bool, reportBytecodeCompileTimes, false, Normal, "dumps JS function signature and the time it took to bytecode compile") \
     v(Bool, countParseTimes, false, Normal, "counts parse times") \
index 524a85e..a6c87cd 100644 (file)
@@ -44,11 +44,28 @@ public:
     Seconds addToTotal(const char* compilerName, const char* name, Seconds duration)
     {
         auto locker = holdLock(lock);
-        return totals.add(std::make_pair(compilerName, name), Seconds(0)).iterator->value += duration;
+
+        for (auto& tuple : totals) {
+            if (String(std::get<0>(tuple)) == String(compilerName) && String(std::get<1>(tuple)) == String(name)) {
+                std::get<2>(tuple) += duration;
+                return std::get<2>(tuple);
+            }
+        }
+
+        totals.append({ compilerName, name, duration });
+        return duration;
+    }
+
+    void logTotals()
+    {
+        for (auto& tuple : totals) {
+            dataLogLn(
+                "[", std::get<0>(tuple), "] ", std::get<1>(tuple), " total ms: ", std::get<2>(tuple).milliseconds());
+        }
     }
     
 private:
-    HashMap<std::pair<const char*, const char*>, Seconds> totals;
+    Vector<std::tuple<const char*, const char*, Seconds>> totals;
     Lock lock;
 };
 
@@ -64,21 +81,27 @@ CompilerTimingScope::CompilerTimingScope(const char* compilerName, const char* n
     : m_compilerName(compilerName)
     , m_name(name)
 {
-    if (UNLIKELY(Options::logPhaseTimes()))
+    if (UNLIKELY(Options::logPhaseTimes() || Options::reportTotalPhaseTimes()))
         m_before = MonotonicTime::now();
 }
 
 CompilerTimingScope::~CompilerTimingScope()
 {
-    if (UNLIKELY(Options::logPhaseTimes())) {
+    if (UNLIKELY(Options::logPhaseTimes() || Options::reportTotalPhaseTimes())) {
         Seconds duration = MonotonicTime::now() - m_before;
-        dataLog(
-            "[", m_compilerName, "] ", m_name, " took: ", duration.milliseconds(), " ms ",
-            "(total: ", compilerTimingScopeState().addToTotal(m_compilerName, m_name, duration).milliseconds(),
-            " ms).\n");
+        auto total = compilerTimingScopeState().addToTotal(m_compilerName, m_name, duration);
+        if (Options::logPhaseTimes()) {
+            dataLog(
+                "[", m_compilerName, "] ", m_name, " took: ", duration.milliseconds(), " ms ",
+                "(total: ", total.milliseconds(),
+                " ms).\n");
+        }
     }
 }
 
-} // namespace JSC
-
+void logTotalPhaseTimes()
+{
+    compilerTimingScopeState().logTotals();
+}
 
+} // namespace JSC
index 52a4f6b..771295a 100644 (file)
@@ -47,5 +47,6 @@ private:
     MonotonicTime m_before;
 };
 
-} // namespace JSC
+JS_EXPORT_PRIVATE void logTotalPhaseTimes();
 
+} // namespace JSC