Skip to content

Commit

Permalink
Add verbose logging to dependency table
Browse files Browse the repository at this point in the history 
The verbose options dependencyTracking and dependencyTrackingDetails
turn on various verbose log messages related to class and method
tracking in the dependency table, and method dependency gathering at
compile time.

Signed-off-by: Christian Despres <[email protected]>
  • Loading branch information
@cjjdespres
cjjdespres committed Dec 3, 2024
1 parent 7576b59 commit b82811b
Show file tree
Hide file tree
Showing 5 changed files with 104 additions and 12 deletions.
9 changes: 9 additions & 0 deletions runtime/compiler/codegen/J9AheadOfTimeCompile.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -31,6 +31,7 @@
#include "il/Node_inlines.hpp"
#include "il/SymbolReference.hpp"
#include "il/StaticSymbol.hpp"
#include "env/VerboseLog.hpp"
#include "env/VMJ9.h"
#include "codegen/AheadOfTimeCompile.hpp"
#include "runtime/RelocationRuntime.hpp"
Expand Down Expand Up @@ -2633,14 +2634,22 @@ void J9::AheadOfTimeCompile::processRelocations()
// flag must still be set to distinguish methods with zero
// dependencies from methods with untracked dependencies.
comp->getAotMethodHeaderEntry()->flags |= TR_AOTMethodHeader_TracksDependencies;
if (comp->getOptions()->getVerboseOption(TR_VerboseDependencyTracking))
TR_VerboseLog::writeLineLocked(TR_Vlog_INFO, "Method %p compiled with 0 tracked dependencies", method);
}
else
{
auto sharedCache = fej9->sharedCache();
auto vmThread = fej9->getCurrentVMThread();
auto dependencyChain = sharedCache->storeAOTMethodDependencies(vmThread, method, definingClass, dependencies.data(), dependencies.size());
if (dependencyChain)
{
comp->getAotMethodHeaderEntry()->flags |= TR_AOTMethodHeader_TracksDependencies;
if (comp->getOptions()->getVerboseOption(TR_VerboseDependencyTracking))
{
TR_VerboseLog::writeLineLocked(TR_Vlog_INFO, "Method %p compiled with %lu tracked dependencies", method, totalDependencies);
}
}
}
}
#endif /* !defined(PERSISTENT_COLLECTIONS_UNSUPPORTED) */
Expand Down
17 changes: 17 additions & 0 deletions runtime/compiler/compile/J9Compilation.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1607,11 +1607,28 @@ J9::Compilation::addAOTMethodDependency(uintptr_t chainOffset, bool ensureClassI
TR_ASSERT(TR_SharedCache::INVALID_CLASS_CHAIN_OFFSET != chainOffset, "Attempted to remember invalid chain offset");
TR_ASSERT(self()->compileRelocatableCode(), "Must be generating AOT code");

bool newDependency = false;

auto it = _aotMethodDependencies.find(chainOffset);
if (it != _aotMethodDependencies.end())
{
newDependency = ensureClassIsInitialized && !it->second;
it->second = it->second || ensureClassIsInitialized;
}
else
{
newDependency = true;
_aotMethodDependencies.insert(it, {chainOffset, ensureClassIsInitialized});
}

if (self()->getOptions()->getVerboseOption(TR_VerboseDependencyTrackingDetails))
{
auto method = self()->getMethodBeingCompiled()->getPersistentIdentifier();
auto sharedCache = self()->fej9()->sharedCache();
auto romClassOffset = sharedCache->startingROMClassOffsetOfClassChain(sharedCache->pointerFromOffsetInSharedCache(chainOffset));
TR_VerboseLog::writeLineLocked(TR_Vlog_INFO, "Method %p dependency: chainOffset=%lu romClassOffset=%lu needsInit=%d",
method, chainOffset, romClassOffset, ensureClassIsInitialized);
}
}

// Populate the given dependencyBuffer with dependencies of this method, in the
Expand Down
6 changes: 6 additions & 0 deletions runtime/compiler/control/CompilationThread.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3579,6 +3579,12 @@ void TR::CompilationInfo::stopCompilationThreads()
deserializer->printStats(stderr);
}
#endif /* defined(J9VM_OPT_JITSERVER) */
static char *printDependencyTableStats = feGetEnv("TR_PrintDependencyTableStats");
if (printDependencyTableStats)
{
if (auto dependencyTable = getPersistentInfo()->getAOTDependencyTable())
dependencyTable->printStats();
}

#ifdef STATS
if (compBudgetSupport() || dynamicThreadPriority())
Expand Down
78 changes: 68 additions & 10 deletions runtime/compiler/env/DependencyTable.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -47,6 +47,9 @@ TR_AOTDependencyTable::trackMethod(J9VMThread *vmThread, J9Method *method, J9ROM
if (!methodDependencies)
{
dependenciesSatisfied = true;
if (TR::Options::getVerboseOption(TR_VerboseDependencyTracking))
TR_VerboseLog::writeLineLocked(TR_Vlog_INFO, "Dependency table: method %p with 0 dependencies will start at count 0", method);

return true;
}

Expand Down Expand Up @@ -79,12 +82,20 @@ TR_AOTDependencyTable::trackMethod(J9VMThread *vmThread, J9Method *method, J9ROM

if (numberRemainingDependencies == 0)
{
stopTracking(methodEntry);
stopTracking(methodEntry, false);
dependenciesSatisfied = true;

if (TR::Options::getVerboseOption(TR_VerboseDependencyTracking))
TR_VerboseLog::writeLineLocked(TR_Vlog_INFO, "Dependency table: method %p with %lu dependencies will start at count 0", method, totalDependencies);
}
else
{
methodEntry->second._remainingDependencies = numberRemainingDependencies;
if (TR::Options::getVerboseOption(TR_VerboseDependencyTracking))
TR_VerboseLog::writeLineLocked(TR_Vlog_INFO, "Dependency table: method %p with %lu dependencies will be tracked with %lu remaining",
method,
totalDependencies,
numberRemainingDependencies);
}
}
catch (std::exception&)
Expand All @@ -108,16 +119,23 @@ TR_AOTDependencyTable::methodWillBeCompiled(J9Method *method)
// AOT load we might consider preventing the load from taking place (by
// increasing the counts and continuing to track the method, or marking the
// method as ineligible for loads and giving up on tracking it).
stopTracking(method);
stopTracking(method, true);
}

void
TR_AOTDependencyTable::stopTracking(MethodEntryRef entry)
TR_AOTDependencyTable::stopTracking(MethodEntryRef entry, bool isEarlyStop)
{
auto method = entry->first;
auto methodEntry = entry->second;
auto dependencyChain = methodEntry._dependencyChain;
auto dependencyChainLength = *dependencyChain;

bool verboseUnsatisfied = isEarlyStop && TR::Options::getVerboseOption(TR_VerboseDependencyTracking);
bool verboseUnsatisfiedDetails = isEarlyStop && TR::Options::getVerboseOption(TR_VerboseDependencyTrackingDetails);

if (verboseUnsatisfied)
TR_VerboseLog::writeLineLocked(TR_Vlog_INFO, "Dependency table: early tracking stop for method %p with %lu remaining dependencies", method, methodEntry._remainingDependencies);

for (size_t i = 1; i <= dependencyChainLength; ++i)
{
bool needsInitialization = false;
Expand All @@ -126,6 +144,10 @@ TR_AOTDependencyTable::stopTracking(MethodEntryRef entry)

auto o_it = _offsetMap.find(offset);

if (verboseUnsatisfiedDetails && !findCandidateForDependency(o_it->second._loadedClasses, needsInitialization))
TR_VerboseLog::writeLineLocked(TR_Vlog_INFO, "Dependency table: stopped tracking method %p with unsatisfied dependency chainOffset=%lu romClassOffset=%lu needsInit=%d",
method, chainOffset, offset, needsInitialization);

if (needsInitialization)
o_it->second._waitingInitMethods.erase(entry);
else
Expand All @@ -138,11 +160,11 @@ TR_AOTDependencyTable::stopTracking(MethodEntryRef entry)
}

void
TR_AOTDependencyTable::stopTracking(J9Method *method)
TR_AOTDependencyTable::stopTracking(J9Method *method, bool isEarlyStop)
{
auto entry = _methodMap.find(method);
if (entry != _methodMap.end())
stopTracking(&*entry);
stopTracking(&*entry, isEarlyStop);
}

void
Expand Down Expand Up @@ -208,6 +230,13 @@ TR_AOTDependencyTable::classLoadEventAtOffset(J9Class *ramClass, uintptr_t offse
if (!isClassLoad && (offsetEntry->_loadedClasses.find(ramClass) == offsetEntry->_loadedClasses.end()))
return;

if (TR::Options::getVerboseOption(TR_VerboseDependencyTracking))
{
auto name = J9ROMCLASS_CLASSNAME(ramClass->romClass);
TR_VerboseLog::writeLineLocked(TR_Vlog_INFO, "Dependency table: class load event %.*s ramClass=%p romClassOffset=%lu isLoad=%d isInit=%d",
J9UTF8_LENGTH(name), J9UTF8_DATA(name), ramClass, offset, isClassLoad, isClassInitialization);
}

// Check for dependency satisfaction if this is the first class initialized
// for this offset.
if (isClassInitialization)
Expand Down Expand Up @@ -289,6 +318,9 @@ TR_AOTDependencyTable::invalidateClassAtOffset(J9Class *ramClass, uintptr_t romC
auto entry = getOffsetEntry(romClassOffset, false);
if (entry)
{
if (TR::Options::getVerboseOption(TR_VerboseDependencyTracking))
TR_VerboseLog::writeLineLocked(TR_Vlog_INFO, "Dependency table: invalidating class %p romClassOffset=%lu", ramClass, romClassOffset);

entry->_loadedClasses.erase(ramClass);

// Update the waiting methods if the removal of ramClass caused a
Expand All @@ -314,7 +346,7 @@ void
TR_AOTDependencyTable::invalidateMethodsOfClass(J9Class *ramClass)
{
for (uint32_t i = 0; i < ramClass->romClass->romMethodCount; i++)
stopTracking(&ramClass->ramMethods[i]);
stopTracking(&ramClass->ramMethods[i], true);
}

// If an entry exists for a class, remove it. Otherwise, if we should
Expand Down Expand Up @@ -414,10 +446,25 @@ TR_AOTDependencyTable::resolvePendingLoads()
for (auto& entry: _pendingLoads)
{
auto method = entry->first;
auto count = TR::CompilationInfo::getInvocationCount(method);
while ((count > 0) && !TR::CompilationInfo::setInvocationCount(method, count, 0))
count = TR::CompilationInfo::getInvocationCount(method);
stopTracking(entry);
auto initCount = TR::CompilationInfo::getInvocationCount(method);
auto count = initCount;
while (count > 0)
{
if (TR::CompilationInfo::setInvocationCount(method, count, 0))
count = 0;
else
count = TR::CompilationInfo::getInvocationCount(method);
}

if (TR::Options::isAnyVerboseOptionSet(TR_VerboseDependencyTracking, TR_VerboseCounts))
TR_VerboseLog::writeLineLocked(TR_Vlog_INFO,
"Dependency table: pending load %s - method %p count %lu --> %lu",
(count == 0) ? "success" : "failure",
method,
initCount,
count);

stopTracking(entry, false);
}
_pendingLoads.clear();
}
Expand All @@ -437,6 +484,17 @@ TR_AOTDependencyTable::findClassCandidate(uintptr_t romClassOffset)
return (TR_OpaqueClassBlock *)findCandidateForDependency(it->second._loadedClasses, true);
}

void
TR_AOTDependencyTable::printStats()
{
TR_VerboseLog::CriticalSection vlogLock;

TR_VerboseLog::writeLine(TR_Vlog_INFO, "Dependency table: %lu methods remain tracked", _methodMap.size());

for (auto methodEntry : _methodMap)
stopTracking(&methodEntry, true);
}

J9Class *
TR_AOTDependencyTable::findCandidateForDependency(const PersistentUnorderedSet<J9Class *> &loadedClasses, bool needsInitialization)
{
Expand Down
6 changes: 4 additions & 2 deletions runtime/compiler/env/DependencyTable.hpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -41,6 +41,7 @@ class TR_AOTDependencyTable
void invalidateRedefinedClass(TR_PersistentCHTable *table, TR_J9VMBase *fej9, TR_OpaqueClassBlock *oldClass, TR_OpaqueClassBlock *freshClass) {}
TR_OpaqueClassBlock *findClassCandidate(uintptr_t offset) { return NULL; }
void methodWillBeCompiled(J9Method *method) {}
void printStats() {}
};

#else
Expand Down Expand Up @@ -135,6 +136,7 @@ class TR_AOTDependencyTable
return needsInitialization ? offset : (offset & ~1);
}

void printStats();
private:
bool isActive() const { return _isActive; }
void setInactive() { _isActive = false; }
Expand Down Expand Up @@ -170,8 +172,8 @@ class TR_AOTDependencyTable

// Stop tracking the given method. This will invalidate the MethodEntryRef
// for the method.
void stopTracking(MethodEntryRef entry);
void stopTracking(J9Method *method);
void stopTracking(MethodEntryRef entry, bool isEarlyStop);
void stopTracking(J9Method *method, bool isEarlyStop);

// Queue and clear the _pendingLoads, and remove those methods from tracking.
// Must be called at the end of any dependency table operation that could
Expand Down

0 comments on commit b82811b

Please sign in to comment.