From 860088a3cef5eceabb88008c490b5d852013f48f Mon Sep 17 00:00:00 2001 From: Christian Despres Date: Thu, 28 Nov 2024 15:51:33 -0500 Subject: [PATCH] Add verbose logging to dependency table 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 --- .../compiler/codegen/J9AheadOfTimeCompile.cpp | 8 ++ runtime/compiler/compile/J9Compilation.cpp | 17 ++++ .../compiler/control/CompilationThread.cpp | 6 ++ runtime/compiler/env/DependencyTable.cpp | 78 ++++++++++++++++--- runtime/compiler/env/DependencyTable.hpp | 6 +- 5 files changed, 103 insertions(+), 12 deletions(-) diff --git a/runtime/compiler/codegen/J9AheadOfTimeCompile.cpp b/runtime/compiler/codegen/J9AheadOfTimeCompile.cpp index 7dc19e2da14..2c61fa5284f 100644 --- a/runtime/compiler/codegen/J9AheadOfTimeCompile.cpp +++ b/runtime/compiler/codegen/J9AheadOfTimeCompile.cpp @@ -2633,6 +2633,8 @@ 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 { @@ -2640,7 +2642,13 @@ void J9::AheadOfTimeCompile::processRelocations() 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) */ diff --git a/runtime/compiler/compile/J9Compilation.cpp b/runtime/compiler/compile/J9Compilation.cpp index d3c5cb62636..c8a056f63e0 100644 --- a/runtime/compiler/compile/J9Compilation.cpp +++ b/runtime/compiler/compile/J9Compilation.cpp @@ -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 diff --git a/runtime/compiler/control/CompilationThread.cpp b/runtime/compiler/control/CompilationThread.cpp index 2a3f77c5ed8..730548af960 100644 --- a/runtime/compiler/control/CompilationThread.cpp +++ b/runtime/compiler/control/CompilationThread.cpp @@ -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()) diff --git a/runtime/compiler/env/DependencyTable.cpp b/runtime/compiler/env/DependencyTable.cpp index 5f5c1cfefe4..49ae6c53cfd 100644 --- a/runtime/compiler/env/DependencyTable.cpp +++ b/runtime/compiler/env/DependencyTable.cpp @@ -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; } @@ -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&) @@ -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; @@ -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 @@ -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 @@ -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) @@ -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 @@ -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 @@ -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(); } @@ -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 &loadedClasses, bool needsInitialization) { diff --git a/runtime/compiler/env/DependencyTable.hpp b/runtime/compiler/env/DependencyTable.hpp index a99fc45814a..7c2e2d513ce 100644 --- a/runtime/compiler/env/DependencyTable.hpp +++ b/runtime/compiler/env/DependencyTable.hpp @@ -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 @@ -135,6 +136,7 @@ class TR_AOTDependencyTable return needsInitialization ? offset : (offset & ~1); } + void printStats(); private: bool isActive() const { return _isActive; } void setInactive() { _isActive = false; } @@ -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