Beef up JSC profiler event log
authorfpizlo@apple.com <fpizlo@apple.com@268f45cc-cd09-0410-ab3c-d52691b4dbfc>
Wed, 11 May 2016 21:41:03 +0000 (21:41 +0000)
committerfpizlo@apple.com <fpizlo@apple.com@268f45cc-cd09-0410-ab3c-d52691b4dbfc>
Wed, 11 May 2016 21:41:03 +0000 (21:41 +0000)
https://bugs.webkit.org/show_bug.cgi?id=157584

Reviewed by Saam Barati.

Also log more about compilation.

* bytecode/ExecutionCounter.cpp: Changed the meaning of codeBlock to be the codeBlock that is doing the profiling. This will now get the baseline version if it needs it. This is needed for logging the threshold checking event.
(JSC::applyMemoryUsageHeuristics):
(JSC::ExecutionCounter<countingVariant>::hasCrossedThreshold):
* dfg/DFGJITCode.cpp: Pass the right codeBlock.
(JSC::DFG::JITCode::checkIfOptimizationThresholdReached):
(JSC::DFG::JITCode::optimizeNextInvocation):
(JSC::DFG::JITCode::dontOptimizeAnytimeSoon):
(JSC::DFG::JITCode::optimizeSoon):
(JSC::DFG::JITCode::forceOptimizationSlowPathConcurrently):
* dfg/DFGPlan.cpp: Log things about compile times and whether the compiler succeeded or failed.
(JSC::DFG::Plan::computeCompileTimes):
(JSC::DFG::Plan::reportCompileTimes):
(JSC::DFG::Plan::compileInThread):
(JSC::DFG::Plan::finalizeWithoutNotifyingCallback):
* jit/ExecutableAllocatorFixedVMPool.cpp: Make it possible to look at memory usage, though separately from the log, for now.
(JSC::ExecutableAllocator::allocate):
* runtime/Options.h:

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

Source/JavaScriptCore/ChangeLog
Source/JavaScriptCore/bytecode/ExecutionCounter.cpp
Source/JavaScriptCore/dfg/DFGJITCode.cpp
Source/JavaScriptCore/dfg/DFGPlan.cpp
Source/JavaScriptCore/jit/ExecutableAllocatorFixedVMPool.cpp
Source/JavaScriptCore/runtime/Options.h

index ea48403..67cd5b0 100644 (file)
@@ -1,3 +1,30 @@
+2016-05-11  Filip Pizlo  <fpizlo@apple.com>
+
+        Beef up JSC profiler event log
+        https://bugs.webkit.org/show_bug.cgi?id=157584
+
+        Reviewed by Saam Barati.
+        
+        Also log more about compilation.
+
+        * bytecode/ExecutionCounter.cpp: Changed the meaning of codeBlock to be the codeBlock that is doing the profiling. This will now get the baseline version if it needs it. This is needed for logging the threshold checking event.
+        (JSC::applyMemoryUsageHeuristics):
+        (JSC::ExecutionCounter<countingVariant>::hasCrossedThreshold):
+        * dfg/DFGJITCode.cpp: Pass the right codeBlock.
+        (JSC::DFG::JITCode::checkIfOptimizationThresholdReached):
+        (JSC::DFG::JITCode::optimizeNextInvocation):
+        (JSC::DFG::JITCode::dontOptimizeAnytimeSoon):
+        (JSC::DFG::JITCode::optimizeSoon):
+        (JSC::DFG::JITCode::forceOptimizationSlowPathConcurrently):
+        * dfg/DFGPlan.cpp: Log things about compile times and whether the compiler succeeded or failed.
+        (JSC::DFG::Plan::computeCompileTimes):
+        (JSC::DFG::Plan::reportCompileTimes):
+        (JSC::DFG::Plan::compileInThread):
+        (JSC::DFG::Plan::finalizeWithoutNotifyingCallback):
+        * jit/ExecutableAllocatorFixedVMPool.cpp: Make it possible to look at memory usage, though separately from the log, for now.
+        (JSC::ExecutableAllocator::allocate):
+        * runtime/Options.h:
+
 2016-05-11  Saam barati  <sbarati@apple.com>
 
         Air may decide to put the result register of an arithmetic snippet in the tag register
index fe4e430..237c0e7 100644 (file)
@@ -1,5 +1,5 @@
 /*
- * Copyright (C) 2012, 2014 Apple Inc. All rights reserved.
+ * Copyright (C) 2012, 2014, 2016 Apple Inc. All rights reserved.
  *
  * Redistribution and use in source and binary forms, with or without
  * modification, are permitted provided that the following conditions
@@ -29,6 +29,7 @@
 #include "CodeBlock.h"
 #include "ExecutableAllocator.h"
 #include "JSCInlines.h"
+#include "VMInlines.h"
 #include <wtf/StringExtras.h>
 
 namespace JSC {
@@ -78,7 +79,7 @@ double applyMemoryUsageHeuristics(int32_t value, CodeBlock* codeBlock)
 #if ENABLE(JIT)
     double multiplier =
         ExecutableAllocator::memoryPressureMultiplier(
-            codeBlock->predictedMachineCodeSize());
+            codeBlock->baselineAlternative()->predictedMachineCodeSize());
 #else
     // This code path will probably not be taken, but if it is, we fake it.
     double multiplier = 1.0;
@@ -123,9 +124,15 @@ bool ExecutionCounter<countingVariant>::hasCrossedThreshold(CodeBlock* codeBlock
     
     double modifiedThreshold = applyMemoryUsageHeuristics(m_activeThreshold, codeBlock);
     
-    return static_cast<double>(m_totalCount) + m_counter >=
-        modifiedThreshold - static_cast<double>(
-            std::min(m_activeThreshold, maximumExecutionCountsBetweenCheckpoints())) / 2;
+    double actualCount = static_cast<double>(m_totalCount) + m_counter;
+    double desiredCount = modifiedThreshold - static_cast<double>(
+        std::min(m_activeThreshold, maximumExecutionCountsBetweenCheckpoints())) / 2;
+    
+    bool result = actualCount >= desiredCount;
+    
+    CODEBLOCK_LOG_EVENT(codeBlock, "thresholdCheck", ("activeThreshold = ", m_activeThreshold, ", modifiedThreshold = ", modifiedThreshold, ", actualCount = ", actualCount, ", desiredCount = ", desiredCount));
+    
+    return result;
 }
 
 template<CountingVariant countingVariant>
index 7554913..e9ac3e5 100644 (file)
@@ -123,7 +123,7 @@ RegisterSet JITCode::liveRegistersToPreserveAtExceptionHandlingCallSite(CodeBloc
 bool JITCode::checkIfOptimizationThresholdReached(CodeBlock* codeBlock)
 {
     ASSERT(codeBlock->jitType() == JITCode::DFGJIT);
-    return tierUpCounter.checkIfThresholdCrossedAndSet(codeBlock->baselineVersion());
+    return tierUpCounter.checkIfThresholdCrossedAndSet(codeBlock);
 }
 
 void JITCode::optimizeNextInvocation(CodeBlock* codeBlock)
@@ -131,7 +131,7 @@ void JITCode::optimizeNextInvocation(CodeBlock* codeBlock)
     ASSERT(codeBlock->jitType() == JITCode::DFGJIT);
     if (Options::verboseOSR())
         dataLog(*codeBlock, ": FTL-optimizing next invocation.\n");
-    tierUpCounter.setNewThreshold(0, codeBlock->baselineVersion());
+    tierUpCounter.setNewThreshold(0, codeBlock);
 }
 
 void JITCode::dontOptimizeAnytimeSoon(CodeBlock* codeBlock)
@@ -161,7 +161,7 @@ void JITCode::optimizeSoon(CodeBlock* codeBlock)
     CodeBlock* baseline = codeBlock->baselineVersion();
     tierUpCounter.setNewThreshold(
         baseline->adjustedCounterValue(Options::thresholdForFTLOptimizeSoon()),
-        baseline);
+        codeBlock);
 }
 
 void JITCode::forceOptimizationSlowPathConcurrently(CodeBlock* codeBlock)
index 21ae411..d3e095e 100644 (file)
@@ -1,5 +1,5 @@
 /*
- * Copyright (C) 2013-2015 Apple Inc. All rights reserved.
+ * Copyright (C) 2013-2016 Apple Inc. All rights reserved.
  *
  * Redistribution and use in source and binary forms, with or without
  * modification, are permitted provided that the following conditions
@@ -79,6 +79,7 @@
 #include "OperandsInlines.h"
 #include "ProfilerDatabase.h"
 #include "TrackedReferences.h"
+#include "VMInlines.h"
 #include <wtf/CurrentTime.h>
 
 #if ENABLE(FTL_JIT)
@@ -158,7 +159,8 @@ Plan::~Plan()
 bool Plan::computeCompileTimes() const
 {
     return reportCompileTimes()
-        || Options::reportTotalCompileTimes();
+        || Options::reportTotalCompileTimes()
+        || vm.m_perBytecodeProfiler;
 }
 
 bool Plan::reportCompileTimes() const
@@ -202,28 +204,31 @@ void Plan::compileInThread(LongLivedState& longLivedState, ThreadData* threadDat
                 totalDFGCompileTime += after - before;
         }
     }
+    const char* pathName = nullptr;
+    switch (path) {
+    case FailPath:
+        pathName = "N/A (fail)";
+        break;
+    case DFGPath:
+        pathName = "DFG";
+        break;
+    case FTLPath:
+        pathName = "FTL";
+        break;
+    case CancelPath:
+        pathName = "Cancelled";
+        break;
+    default:
+        RELEASE_ASSERT_NOT_REACHED();
+        break;
+    }
+    if (codeBlock) { // codeBlock will be null if the compilation was cancelled.
+        if (path == FTLPath)
+            CODEBLOCK_LOG_EVENT(codeBlock, "ftlCompile", ("took ", after - before, " ms (DFG: ", m_timeBeforeFTL - before, ", B3: ", after - m_timeBeforeFTL, ") with ", pathName));
+        else
+            CODEBLOCK_LOG_EVENT(codeBlock, "dfgCompile", ("took ", after - before, " ms with ", pathName));
+    }
     if (UNLIKELY(reportCompileTimes())) {
-        const char* pathName;
-        switch (path) {
-        case FailPath:
-            pathName = "N/A (fail)";
-            break;
-        case DFGPath:
-            pathName = "DFG";
-            break;
-        case FTLPath:
-            pathName = "FTL";
-            break;
-        case CancelPath:
-            pathName = "Cancelled";
-            break;
-        default:
-            RELEASE_ASSERT_NOT_REACHED();
-#if COMPILER_QUIRK(CONSIDERS_UNREACHABLE_CODE)
-            pathName = "";
-#endif
-            break;
-        }
         dataLog("Optimized ", codeBlockName, " using ", mode, " with ", pathName, " into ", finalizer ? finalizer->codeSize() : 0, " bytes in ", after - before, " ms");
         if (path == FTLPath)
             dataLog(" (DFG: ", m_timeBeforeFTL - before, ", B3: ", after - m_timeBeforeFTL, ")");
@@ -558,8 +563,10 @@ CompilationResult Plan::finalizeWithoutNotifyingCallback()
     // We will establish new references from the code block to things. So, we need a barrier.
     vm.heap.writeBarrier(codeBlock);
     
-    if (!isStillValid())
+    if (!isStillValid()) {
+        CODEBLOCK_LOG_EVENT(codeBlock, "dfgFinalize", ("invalidated"));
         return CompilationInvalidated;
+    }
 
     bool result;
     if (codeBlock->codeType() == FunctionCode)
@@ -567,8 +574,10 @@ CompilationResult Plan::finalizeWithoutNotifyingCallback()
     else
         result = finalizer->finalize();
     
-    if (!result)
+    if (!result) {
+        CODEBLOCK_LOG_EVENT(codeBlock, "dfgFinalize", ("failed"));
         return CompilationFailed;
+    }
     
     reallyAdd(codeBlock->jitCode()->dfgCommon());
     
@@ -587,6 +596,7 @@ CompilationResult Plan::finalizeWithoutNotifyingCallback()
         codeBlock->jitCode()->validateReferences(trackedReferences);
     }
     
+    CODEBLOCK_LOG_EVENT(codeBlock, "dfgFinalize", ("succeeded"));
     return CompilationSuccessful;
 }
 
index 26a94b1..4afff69 100644 (file)
@@ -362,6 +362,11 @@ double ExecutableAllocator::memoryPressureMultiplier(size_t addedMemoryUsage)
 
 RefPtr<ExecutableMemoryHandle> ExecutableAllocator::allocate(VM&, size_t sizeInBytes, void* ownerUID, JITCompilationEffort effort)
 {
+    if (Options::logExecutableAllocation()) {
+        MetaAllocator::Statistics stats = allocator->currentStatistics();
+        dataLog("Allocating ", sizeInBytes, " bytes of executable memory with ", stats.bytesAllocated, " bytes allocated, ", stats.bytesReserved, " bytes reserved, and ", stats.bytesCommitted, " committed.\n");
+    }
+    
     if (effort != JITCompilationCanFail && Options::reportMustSucceedExecutableAllocations()) {
         dataLog("Allocating ", sizeInBytes, " bytes of executable memory with JITCompilationMustSucceed.\n");
         WTFReportBacktrace();
index 66add3c..1d0e564 100644 (file)
@@ -211,6 +211,7 @@ typedef const char* optionString;
     v(bool, useMovHintRemoval, true, Normal, nullptr) \
     v(bool, usePutStackSinking, true, Normal, nullptr) \
     v(bool, useObjectAllocationSinking, true, Normal, nullptr) \
+    v(bool, logExecutableAllocation, false, Normal, nullptr) \
     \
     v(bool, useConcurrentJIT, true, Normal, "allows the DFG / FTL compilation in threads other than the executing JS thread") \
     v(unsigned, numberOfDFGCompilerThreads, computeNumberOfWorkerThreads(2, 2) - 1, Normal, nullptr) \