Internal JSC profiler should have a timestamped log of events for each code block
https://bugs.webkit.org/show_bug.cgi?id=157538
Reviewed by Benjamin Poulain.
Source/JavaScriptCore:
For example, in 3d-cube, I can query the events for MMulti and I get:
1462917476.17083 MMulti#DTZ7qc installCode
1462917476.179663 MMulti#DTZ7qc MMulti#DTZ7qc-1-Baseline installCode
1462917476.179664 MMulti#DTZ7qc MMulti#DTZ7qc-1-Baseline osrEntry at bc#49
1462917476.185651 MMulti#DTZ7qc MMulti#DTZ7qc-1-Baseline delayOptimizeToDFG counter = 1011.214233/1717.000000, -707
1462917476.187913 MMulti#DTZ7qc MMulti#DTZ7qc-2-DFG installCode
1462917476.187917 MMulti#DTZ7qc MMulti#DTZ7qc-2-DFG osrEntry at bc#49
1462917476.205365 MMulti#DTZ7qc MMulti#DTZ7qc-2-DFG jettison due to OSRExit, counting = true, detail = (null)
1462917476.205368 MMulti#DTZ7qc MMulti#DTZ7qc-1-Baseline frequentExit bc#65: BadCache/FromDFG
1462917476.205369 MMulti#DTZ7qc MMulti#DTZ7qc-1-Baseline installCode
1462917476.205482 MMulti#DTZ7qc MMulti#DTZ7qc-1-Baseline delayOptimizeToDFG counter = 1013.000000/3434.000000, -1000
1462917476.211547 MMulti#DTZ7qc MMulti#DTZ7qc-1-Baseline delayOptimizeToDFG counter = 2013.000000/3434.000000, -1000
1462917476.213721 MMulti#DTZ7qc MMulti#DTZ7qc-3-DFG installCode
1462917476.213726 MMulti#DTZ7qc MMulti#DTZ7qc-3-DFG osrEntry at bc#49
1462917476.223976 MMulti#DTZ7qc MMulti#DTZ7qc-3-DFG jettison due to OSRExit, counting = true, detail = (null)
1462917476.223981 MMulti#DTZ7qc MMulti#DTZ7qc-1-Baseline frequentExit bc#77: BadCache/FromDFG
1462917476.223982 MMulti#DTZ7qc MMulti#DTZ7qc-1-Baseline frequentExit bc#94: BadCache/FromDFG
1462917476.223982 MMulti#DTZ7qc MMulti#DTZ7qc-1-Baseline installCode
1462917476.224064 MMulti#DTZ7qc MMulti#DTZ7qc-1-Baseline delayOptimizeToDFG counter = 1013.000000/6868.000000, -1000
1462917476.224151 MMulti#DTZ7qc MMulti#DTZ7qc-1-Baseline delayOptimizeToDFG counter = 2013.000000/6868.000000, -1000
1462917476.224258 MMulti#DTZ7qc MMulti#DTZ7qc-1-Baseline delayOptimizeToDFG counter = 3013.000000/6868.000000, -1000
1462917476.224337 MMulti#DTZ7qc MMulti#DTZ7qc-1-Baseline delayOptimizeToDFG counter = 4023.000000/6868.000000, -1000
1462917476.224425 MMulti#DTZ7qc MMulti#DTZ7qc-1-Baseline delayOptimizeToDFG counter = 5023.000000/6868.000000, -1000
1462917476.224785 MMulti#DTZ7qc MMulti#DTZ7qc-1-Baseline delayOptimizeToDFG counter = 6023.396484/6868.000000, -862
1462917476.227669 MMulti#DTZ7qc MMulti#DTZ7qc-4-DFG installCode
1462917476.227675 MMulti#DTZ7qc MMulti#DTZ7qc-4-DFG osrEntry at bc#0
The output is ugly but useful. We can make it less ugly later.
* CMakeLists.txt:
* JavaScriptCore.xcodeproj/project.pbxproj:
* bytecode/CodeBlock.cpp:
(JSC::CodeBlock::jettison):
* bytecode/CodeBlock.h:
(JSC::ScriptExecutable::forEachCodeBlock):
* bytecode/DFGExitProfile.cpp:
(JSC::DFG::ExitProfile::add):
* dfg/DFGJITFinalizer.cpp:
(JSC::DFG::JITFinalizer::finalizeCommon):
* dfg/DFGOperations.cpp:
* ftl/FTLJITFinalizer.cpp:
(JSC::FTL::JITFinalizer::finalizeFunction):
* jit/JIT.cpp:
(JSC::JIT::privateCompile):
* jit/JITOperations.cpp:
* llint/LLIntSlowPaths.cpp:
(JSC::LLInt::jitCompileAndSetHeuristics):
(JSC::LLInt::entryOSR):
(JSC::LLInt::LLINT_SLOW_PATH_DECL):
* profiler/ProfilerCompilation.cpp:
(JSC::Profiler::Compilation::Compilation):
(JSC::Profiler::Compilation::setJettisonReason):
(JSC::Profiler::Compilation::dump):
(JSC::Profiler::Compilation::toJS):
* profiler/ProfilerCompilation.h:
(JSC::Profiler::Compilation::uid):
* profiler/ProfilerDatabase.cpp:
(JSC::Profiler::Database::ensureBytecodesFor):
(JSC::Profiler::Database::notifyDestruction):
(JSC::Profiler::Database::addCompilation):
(JSC::Profiler::Database::toJS):
(JSC::Profiler::Database::registerToSaveAtExit):
(JSC::Profiler::Database::logEvent):
(JSC::Profiler::Database::addDatabaseToAtExit):
* profiler/ProfilerDatabase.h:
* profiler/ProfilerEvent.cpp: Added.
(JSC::Profiler::Event::dump):
(JSC::Profiler::Event::toJS):
* profiler/ProfilerEvent.h: Added.
(JSC::Profiler::Event::Event):
(JSC::Profiler::Event::operator bool):
(JSC::Profiler::Event::time):
(JSC::Profiler::Event::bytecodes):
(JSC::Profiler::Event::compilation):
(JSC::Profiler::Event::summary):
(JSC::Profiler::Event::detail):
* profiler/ProfilerUID.cpp: Added.
(JSC::Profiler::UID::create):
(JSC::Profiler::UID::dump):
(JSC::Profiler::UID::toJS):
* profiler/ProfilerUID.h: Added.
(JSC::Profiler::UID::UID):
(JSC::Profiler::UID::fromInt):
(JSC::Profiler::UID::toInt):
(JSC::Profiler::UID::operator==):
(JSC::Profiler::UID::operator!=):
(JSC::Profiler::UID::operator bool):
(JSC::Profiler::UID::isHashTableDeletedValue):
(JSC::Profiler::UID::hash):
(JSC::Profiler::UIDHash::hash):
(JSC::Profiler::UIDHash::equal):
* runtime/CommonIdentifiers.h:
* runtime/Executable.cpp:
(JSC::ScriptExecutable::installCode):
* runtime/VM.h:
(JSC::VM::bytecodeIntrinsicRegistry):
(JSC::VM::shadowChicken):
* runtime/VMInlines.h:
(JSC::VM::shouldTriggerTermination):
(JSC::VM::logEvent):
Source/WTF:
* wtf/PrintStream.h:
(WTF::PrintStream::print):
Tools:
* Scripts/display-profiler-output:
git-svn-id: http://svn.webkit.org/repository/webkit/trunk@200658 268f45cc-cd09-0410-ab3c-d52691b4dbfc
diff --git a/Source/JavaScriptCore/dfg/DFGOperations.cpp b/Source/JavaScriptCore/dfg/DFGOperations.cpp
index 0f2e505..0198066 100644
--- a/Source/JavaScriptCore/dfg/DFGOperations.cpp
+++ b/Source/JavaScriptCore/dfg/DFGOperations.cpp
@@ -57,7 +57,7 @@
#include "Symbol.h"
#include "TypeProfilerLog.h"
#include "TypedArrayInlines.h"
-#include "VM.h"
+#include "VMInlines.h"
#include <wtf/InlineASM.h>
#if ENABLE(JIT)
@@ -1765,6 +1765,7 @@
static bool shouldTriggerFTLCompile(CodeBlock* codeBlock, JITCode* jitCode)
{
if (codeBlock->baselineVersion()->m_didFailFTLCompilation) {
+ CODEBLOCK_LOG_EVENT(codeBlock, "abortFTLCompile", ());
if (Options::verboseOSR())
dataLog("Deferring FTL-optimization of ", *codeBlock, " indefinitely because there was an FTL failure.\n");
jitCode->dontOptimizeAnytimeSoon(codeBlock);
@@ -1773,6 +1774,7 @@
if (!codeBlock->hasOptimizedReplacement()
&& !jitCode->checkIfOptimizationThresholdReached(codeBlock)) {
+ CODEBLOCK_LOG_EVENT(codeBlock, "delayFTLCompile", ("counter = ", jitCode->tierUpCounter));
if (Options::verboseOSR())
dataLog("Choosing not to FTL-optimize ", *codeBlock, " yet.\n");
return false;
@@ -1790,12 +1792,14 @@
worklistState = Worklist::NotKnown;
if (worklistState == Worklist::Compiling) {
+ CODEBLOCK_LOG_EVENT(codeBlock, "delayFTLCompile", ("still compiling"));
jitCode->setOptimizationThresholdBasedOnCompilationResult(
codeBlock, CompilationDeferred);
return;
}
if (codeBlock->hasOptimizedReplacement()) {
+ CODEBLOCK_LOG_EVENT(codeBlock, "delayFTLCompile", ("has replacement"));
// That's great, we've compiled the code - next time we call this function,
// we'll enter that replacement.
jitCode->optimizeSoon(codeBlock);
@@ -1803,6 +1807,7 @@
}
if (worklistState == Worklist::Compiled) {
+ CODEBLOCK_LOG_EVENT(codeBlock, "delayFTLCompile", ("compiled and failed"));
// This means that we finished compiling, but failed somehow; in that case the
// thresholds will be set appropriately.
if (Options::verboseOSR())
@@ -1810,6 +1815,7 @@
return;
}
+ CODEBLOCK_LOG_EVENT(codeBlock, "triggerFTLReplacement", ());
// We need to compile the code.
compile(
*vm, codeBlock->newReplacement(), codeBlock, FTLMode, UINT_MAX,
@@ -1845,12 +1851,14 @@
if (codeBlock->hasOptimizedReplacement()) {
if (jitCode->tierUpEntryTriggers.isEmpty()) {
+ CODEBLOCK_LOG_EVENT(codeBlock, "delayFTLCompile", ("replacement in place, delaying indefinitely"));
// There is nothing more we can do, the only way this will be entered
// is through the function entry point.
jitCode->dontOptimizeAnytimeSoon(codeBlock);
return;
}
if (jitCode->osrEntryBlock() && jitCode->tierUpEntryTriggers.size() == 1) {
+ CODEBLOCK_LOG_EVENT(codeBlock, "delayFTLCompile", ("trigger in place, delaying indefinitely"));
// There is only one outer loop and its trigger must have been set
// when the plan completed.
// Exiting the inner loop is useless, we can ignore the counter and leave
@@ -1876,12 +1884,14 @@
JITCode* jitCode = codeBlock->jitCode()->dfg();
if (worklistState == Worklist::Compiling) {
+ CODEBLOCK_LOG_EVENT(codeBlock, "delayFTLCompile", ("still compiling"));
jitCode->setOptimizationThresholdBasedOnCompilationResult(
codeBlock, CompilationDeferred);
return nullptr;
}
if (worklistState == Worklist::Compiled) {
+ CODEBLOCK_LOG_EVENT(codeBlock, "delayFTLCompile", ("compiled and failed"));
// This means that compilation failed and we already set the thresholds.
if (Options::verboseOSR())
dataLog("Code block ", *codeBlock, " was compiled but it doesn't have an optimized replacement.\n");
@@ -1892,8 +1902,10 @@
if (originBytecodeIndex == osrEntryBytecodeIndex) {
unsigned streamIndex = jitCode->bytecodeIndexToStreamIndex.get(originBytecodeIndex);
if (CodeBlock* entryBlock = jitCode->osrEntryBlock()) {
- if (void* address = FTL::prepareOSREntry(exec, codeBlock, entryBlock, originBytecodeIndex, streamIndex))
+ if (void* address = FTL::prepareOSREntry(exec, codeBlock, entryBlock, originBytecodeIndex, streamIndex)) {
+ CODEBLOCK_LOG_EVENT(entryBlock, "osrEntry", ("at bc#", originBytecodeIndex));
return static_cast<char*>(address);
+ }
}
}
@@ -1911,14 +1923,17 @@
return nullptr;
if (jitCode->osrEntryRetry < Options::ftlOSREntryRetryThreshold()) {
+ CODEBLOCK_LOG_EVENT(codeBlock, "delayFTLCompile", ("avoiding OSR entry compile"));
jitCode->osrEntryRetry++;
return nullptr;
}
- }
+ } else
+ CODEBLOCK_LOG_EVENT(codeBlock, "delayFTLCompile", ("avoiding replacement compile"));
// It's time to try to compile code for OSR entry.
if (CodeBlock* entryBlock = jitCode->osrEntryBlock()) {
if (jitCode->osrEntryRetry < Options::ftlOSREntryRetryThreshold()) {
+ CODEBLOCK_LOG_EVENT(codeBlock, "delayFTLCompile", ("OSR entry failed, OSR entry threshold not met"));
jitCode->osrEntryRetry++;
jitCode->setOptimizationThresholdBasedOnCompilationResult(
codeBlock, CompilationDeferred);
@@ -1929,6 +1944,7 @@
entryCode->countEntryFailure();
if (entryCode->entryFailureCount() <
Options::ftlOSREntryFailureCountForReoptimization()) {
+ CODEBLOCK_LOG_EVENT(codeBlock, "delayFTLCompile", ("OSR entry failed"));
jitCode->setOptimizationThresholdBasedOnCompilationResult(
codeBlock, CompilationDeferred);
return nullptr;
@@ -1936,6 +1952,7 @@
// OSR entry failed. Oh no! This implies that we need to retry. We retry
// without exponential backoff and we only do this for the entry code block.
+ CODEBLOCK_LOG_EVENT(codeBlock, "delayFTLCompile", ("OSR entry failed too many times"));
unsigned osrEntryBytecode = entryBlock->jitCode()->ftlForOSREntry()->bytecodeIndex();
jitCode->clearOSREntryBlock();
jitCode->osrEntryRetry = 0;
@@ -1967,6 +1984,7 @@
exec, codeBlock, CodeOrigin(osrEntryBytecodeIndex), streamIndex, mustHandleValues);
CodeBlock* replacementCodeBlock = codeBlock->newReplacement();
+ CODEBLOCK_LOG_EVENT(codeBlock, "triggerFTLOSR", ());
CompilationResult forEntryResult = compile(
*vm, replacementCodeBlock, codeBlock, FTLForOSREntryMode, osrEntryBytecodeIndex,
mustHandleValues, ToFTLForOSREntryDeferredCompilationCallback::create(triggerAddress));
@@ -1975,11 +1993,13 @@
triggerFTLReplacementCompile(vm, codeBlock, jitCode);
if (forEntryResult != CompilationSuccessful) {
+ CODEBLOCK_LOG_EVENT(codeBlock, "delayFTLCompile", ("OSR ecompilation not successful"));
jitCode->setOptimizationThresholdBasedOnCompilationResult(
codeBlock, CompilationDeferred);
return nullptr;
}
-
+
+ CODEBLOCK_LOG_EVENT(jitCode->osrEntryBlock(), "osrEntry", ("at bc#", originBytecodeIndex));
// It's possible that the for-entry compile already succeeded. In that case OSR
// entry will succeed unless we ran out of stack. It's not clear what we should do.
// We signal to try again after a while if that happens.
@@ -2016,8 +2036,10 @@
triggerFTLReplacementCompile(vm, codeBlock, jitCode);
// Since we cannot OSR Enter here, the default "optimizeSoon()" is not useful.
- if (codeBlock->hasOptimizedReplacement())
+ if (codeBlock->hasOptimizedReplacement()) {
+ CODEBLOCK_LOG_EVENT(codeBlock, "delayFTLCompile", ("OSR in loop failed, deferring"));
jitCode->setOptimizationThresholdBasedOnCompilationResult(codeBlock, CompilationDeferred);
+ }
}
char* JIT_OPERATION triggerOSREntryNow(ExecState* exec, unsigned bytecodeIndex)
