diff --git a/runtime/compiler/codegen/J9AheadOfTimeCompile.cpp b/runtime/compiler/codegen/J9AheadOfTimeCompile.cpp index 7dc19e2da14..3684f5dcb55 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"); } 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", totalDependencies); + } + } } } #endif /* !defined(PERSISTENT_COLLECTIONS_UNSUPPORTED) */ diff --git a/runtime/compiler/compile/J9Compilation.cpp b/runtime/compiler/compile/J9Compilation.cpp index d649dcb6a90..eb775e1e729 100644 --- a/runtime/compiler/compile/J9Compilation.cpp +++ b/runtime/compiler/compile/J9Compilation.cpp @@ -1617,11 +1617,27 @@ 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: %lu %lu %d", 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..cfacf587ffe 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 %lu %lu %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 %p %.*s %lu %d %d", + ramClass, J9UTF8_LENGTH(name), J9UTF8_DATA(name), 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 %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