Merge pull request #14384 from AlexeyKhrabrov/jitserver_aotcache_vlog

JITServer AOT cache vlog improvements
eclipse-openj9 · Apr 19, 2022 · 10bf2cd · 10bf2cd
2 parents 319d8f7 + 6aa7d13
commit 10bf2cd
Show file tree

Hide file tree

Showing 4 changed files with 75 additions and 2 deletions.
diff --git a/runtime/compiler/codegen/J9AheadOfTimeCompile.cpp b/runtime/compiler/codegen/J9AheadOfTimeCompile.cpp
@@ -121,6 +121,17 @@ J9::AheadOfTimeCompile::addSerializationRecord(const AOTCacheRecord *record, con
       uint8_t *end = start + *(uintptr_t *)start;// Total size of relocation data is stored in the first word
       TR_ASSERT_FATAL(((uint8_t *)sccOffsetAddr >= start + sizeof(uintptr_t)) && ((uint8_t *)sccOffsetAddr < end),
                       "SCC offset address %p not in range %p - %p", sccOffsetAddr, start + sizeof(uintptr_t), end);
+#if defined(DEBUG)
+      if (record && TR::Options::getVerboseOption(TR_VerboseJITServer))
+         {
+         const AOTSerializationRecord *r = record->dataAddr();
+         TR_VerboseLog::writeLineLocked(TR_Vlog_JITServer,
+            "AOT cache %s: Adding record type %u ID %zu for SCC offset %zu at relo data offset %zu in method %s",
+            comp->getClientData()->getAOTCache()->name().c_str(), r->type(), r->id(),
+            *sccOffsetAddr, (uint8_t *)sccOffsetAddr - start, comp->signature()
+         );
+         }
+#endif /* defined(DEBUG) */
       comp->addSerializationRecord(record, (uint8_t *)sccOffsetAddr - start);
       }
    }

diff --git a/runtime/compiler/control/CompilationThread.cpp b/runtime/compiler/control/CompilationThread.cpp
@@ -3636,6 +3636,8 @@ void TR::CompilationInfo::stopCompilationThreads()
          {
          JITServer::ClientStream client(getPersistentInfo());
          client.writeError(JITServer::MessageType::clientSessionTerminate, getPersistentInfo()->getClientUID());
+         if (TR::Options::getVerboseOption(TR_VerboseJITServer))
+            TR_VerboseLog::writeLineLocked(TR_Vlog_JITServer, "Sent clientSessionTerminate message");
          }
       catch (const JITServer::StreamFailure &e)
          {

diff --git a/runtime/compiler/control/JITServerCompilationThread.cpp b/runtime/compiler/control/JITServerCompilationThread.cpp
@@ -399,6 +399,9 @@ TR::CompilationInfoPerThreadRemote::serveCachedAOTMethod(TR_MethodToBeCompiled &
                                                          TR_OptimizationPlan *optPlan, ClientSessionData *clientData,
                                                          J9::J9SegmentProvider &scratchSegmentProvider)
    {
+   PORT_ACCESS_FROM_JITCONFIG(_jitConfig);
+   uintptr_t startTime = TR::Options::getVerboseOption(TR_VerbosePerformance) ? j9time_usec_clock() : 0;
+
    auto aotCache = clientData->getAOTCache();
    auto serializedMethod = aotCache->findMethod(_definingClassChainRecord, _methodIndex,
                                                 optPlan->getOptLevel(), clientData->getAOTHeaderRecord());
@@ -426,12 +429,61 @@ TR::CompilationInfoPerThreadRemote::serveCachedAOTMethod(TR_MethodToBeCompiled &
    for (auto r : records)
       serializedRecords.push_back(std::string((const char *)r, r->size()));
 
+   // Record the AOT cache hit as a "compilation end" in vlog.
+   // The code is mostly copied from CompilationInfoPerThreadBase::logCompilationSuccess().
+   if (TR::Options::isAnyVerboseOptionSet(TR_VerbosePerformance, TR_VerboseCompileEnd))
+      {
+      uintptr_t currentTime = TR::Options::getVerboseOption(TR_VerbosePerformance) ? j9time_usec_clock() : 0;
+
+      auto &classRecord = serializedMethod->definingClassRecord()->data();
+      const J9ROMMethod *romMethod;
+         {
+         OMR::CriticalSection cs(clientData->getROMMapMonitor());
+         auto it = clientData->getJ9MethodMap().find(method);
+         TR_ASSERT(it != clientData->getJ9MethodMap().end(), "Method %p must be cached", method);
+         romMethod = it->second._romMethod;
+         }
+
+      TR_VerboseLog::CriticalSection vlogLock;
+      TR_VerboseLog::write(TR_Vlog_COMP,
+         "(AOT cache %s) %.*s.%.*s%.*s %s Q_SZ=%d Q_SZI=%d QW=%d j9m=%p bcsz=%u",
+         TR::Compilation::getHotnessName(optPlan->getOptLevel()), (int)classRecord.nameLength(), classRecord.name(),
+         J9UTF8_LENGTH(J9ROMMETHOD_NAME(romMethod)), (const char *)J9UTF8_DATA(J9ROMMETHOD_NAME(romMethod)),
+         J9UTF8_LENGTH(J9ROMMETHOD_SIGNATURE(romMethod)), (const char *)J9UTF8_DATA(J9ROMMETHOD_SIGNATURE(romMethod)),
+         entry.getMethodDetails().name(), _compInfo.getMethodQueueSize(), _compInfo.getNumQueuedFirstTimeCompilations(),
+         _compInfo.getQueueWeight(), method, _compInfo.getMethodBytecodeSize(romMethod)
+      );
+
+      if (TR::Options::getVerboseOption(TR_VerbosePerformance))
+         TR_VerboseLog::write(" time=%zuus mem=[region=%llu system=%llu]KB", currentTime - startTime,
+                              (unsigned long long)segmentProvider.regionBytesAllocated() / 1024,
+                              (unsigned long long)segmentProvider.systemBytesAllocated() / 1024);
+
+      TR_VerboseLog::write(" compThreadID=%d", getCompThreadId());
+
+      CpuUtilization *cpuUtil = _compInfo.getCpuUtil();
+      if (cpuUtil->isFunctional())
+         TR_VerboseLog::write(" CpuLoad=%d%%(%d%%avg) JvmCpu=%d%%", cpuUtil->getCpuUsage(),
+                              cpuUtil->getAvgCpuUsage(), cpuUtil->getVmCpuUsage());
+
+      if (TR::Options::getVerboseOption(TR_VerboseCompilationThreads))
+         {
+         int32_t cpuUtil = getCompThreadCPU().getThreadLastCpuUtil();
+         if (cpuUtil >= 0)
+            TR_VerboseLog::write(" compCPU=%d%%", cpuUtil);
+         }
+
+      if (TR::Options::getVerboseOption(TR_VerbosePerformance))
+         TR_VerboseLog::write(" queueTime=%zuus", currentTime - entry._entryTime);
+
+      TR_VerboseLog::writeLine("");
+      }
+
    //NOTE: Leaving optimization plan unchanged. This can be changed in the future.
    entry._stream->write(JITServer::MessageType::AOTCache_serializedAOTMethod,
                         std::string((const char *)&serializedMethod->data(), serializedMethod->data().size()),
                         serializedRecords, *optPlan, computeServerMemoryState(getCompilationInfo()),
                         computeServerActiveThreadsState(getCompilationInfo()));
-
    return true;
    }
 

diff --git a/runtime/compiler/runtime/JITServerAOTDeserializer.cpp b/runtime/compiler/runtime/JITServerAOTDeserializer.cpp
@@ -1,5 +1,5 @@
 /*******************************************************************************
- * Copyright (c) 2021, 2021 IBM Corp. and others
+ * Copyright (c) 2021, 2022 IBM Corp. and others
  *
  * This program and the accompanying materials are made available under
  * the terms of the Eclipse Public License 2.0 which accompanies this
@@ -862,6 +862,14 @@ JITServerAOTDeserializer::updateSCCOffsets(SerializedAOTMethod *method, TR::Comp
       TR_ASSERT_FATAL((ptr >= start + sizeof(uintptr_t)/*skip the size word*/) && (ptr < end),
                       "Out-of-bounds relocation data offset %zu in serialized method %s",
                       serializedOffset.reloDataOffset(), comp->signature());
+#if defined(DEBUG)
+      if (TR::Options::getVerboseOption(TR_VerboseJITServer))
+         TR_VerboseLog::writeLineLocked(TR_Vlog_JITServer,
+            "Updating SCC offset %zu -> %zu for record type %u ID %zu at relo data offset %zu in serialized method %s",
+            *(uintptr_t *)ptr, sccOffset, serializedOffset.recordType(), serializedOffset.recordId(),
+            serializedOffset.reloDataOffset(), comp->signature()
+         );
+#endif /* defined(DEBUG) */
       *(uintptr_t *)ptr = sccOffset;
       }