Merge pull request #20712 from cjjdespres/verbose-dep-table

Add verbose logging to dependency table

runtime/compiler/codegen/J9AheadOfTimeCompile.cpp

@@ -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"
@@ -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) */

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

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())

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<J9Class *> &loadedClasses, bool needsInitialization)
    {

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