Skip to content

Commit

Permalink
Code to periodically track IProfiler overhead
Browse files Browse the repository at this point in the history 
Every 5 seconds we will print the number of profiling entries,
teh CPU taken by the IProfiler thread and the top 5 methods
that received profiling samples.
The code is not active to minimize overhead. In order to
compile it in one needs to define `TRACK_SAMPLE_SOURCES`
Also, to activate it at runtime, one needs to define the
following env var: `TR_PrintIProfilerActivity``

Signed-off-by: Marius Pirvu <[email protected]>
  • Loading branch information
@mpirvu
mpirvu committed Jan 9, 2025
1 parent 3d7fea2 commit 991a9c4
Show file tree
Hide file tree
Showing 2 changed files with 145 additions and 4 deletions.
113 changes: 111 additions & 2 deletions runtime/compiler/runtime/IProfiler.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4144,6 +4144,53 @@ static inline uint16_t readU16(U_8 *_offset)
static inline uint16_t readU16(U_8 *_offset) { return (*(U_16*)(_offset)); }
#endif /* !FIXUP_UNALIGNED */

#if defined(TRACK_SAMPLE_SOURCES)
void
TR_IProfiler::TopFiveMethods::processElement(const std::pair<const J9ROMMethod*, uint32_t> & newElem)
{
if (_sortedList.size() == 5)
{
if (_sortedList.back().second < newElem.second)
{
// Take the last element out (smallest) to make room for the new one
_sortedList.pop_back();
}
}
if (_sortedList.size() < 5)
{
// Insert new element
bool inserted = false;
for (auto it = _sortedList.begin(); it != _sortedList.end(); ++it)
{
if (it->second < newElem.second) // compare number of samples
{
_sortedList.insert(it, newElem);
inserted = true;
break;
}
} // end for
if (!inserted)
{
_sortedList.push_back(newElem);
}
}
} // processElement

void
TR_IProfiler::TopFiveMethods::print(const std::unordered_map<const J9ROMMethod *, std::string> &methodNames)
{
for (auto it = _sortedList.cbegin(); it != _sortedList.cend(); ++it)
{
const J9ROMMethod *romMethod = it->first;
uint32_t numSamples = it->second;
auto methodEntryIter = methodNames.find(romMethod);
const std::string methodName = (methodEntryIter != methodNames.end()) ? methodEntryIter->second : "";

fprintf(stderr, "%lu samples in method %p %s\n", (unsigned long)numSamples, romMethod, methodName.c_str());
}
}

#endif //#if defined(TRACK_SAMPLE_SOURCES)

//------------------------------ parseBuffer -------------------------
// Parses a buffer from the VM and populates a hash table
Expand Down Expand Up @@ -4228,6 +4275,10 @@ UDATA TR_IProfiler::parseBuffer(J9VMThread * vmThread, const U_8* dataStart, UDA
int32_t skipCount = skipCountMain;
bool profileFlag = true;

#if defined(TRACK_SAMPLE_SOURCES)
static char * printIProfilerActivity = feGetEnv("TR_PrintIProfilerActivity");
#endif

while (cursor < dataStart + size)
{
const U_8* cursorCopy = cursor;
Expand Down Expand Up @@ -4414,7 +4465,39 @@ UDATA TR_IProfiler::parseBuffer(J9VMThread * vmThread, const U_8* dataStart, UDA

if (addSample && !verboseReparse)
{
profilingSample ((uintptr_t)pc, (uintptr_t)data, true);
TR_IPBytecodeHashTableEntry *entry = profilingSample ((uintptr_t)pc, (uintptr_t)data, true);
#if defined(TRACK_SAMPLE_SOURCES)
if (printIProfilerActivity && entry && vmThread == _iprofilerThread) // only IProfiler thread is allowed to execute this)
{
// If this sample does not yet have the romMethod set, find it and set it
if (entry->getROMMethod() == NULL)
{
J9ROMClass *romClass = NULL;
J9ROMMethod *romMethod = findROMMethodFromPC(vmThread, (uintptr_t)pc, romClass);
entry->setROMMethod(romMethod);
// Determine the full method name and memorize it
if (romMethod && romClass)
{
auto methodIt = _methodNames.find(romMethod);
if (methodIt == _methodNames.end())
{
J9UTF8* className = J9ROMCLASS_CLASSNAME(romClass);
J9UTF8* name = J9ROMMETHOD_NAME(romMethod);
J9UTF8* signature = J9ROMMETHOD_SIGNATURE(romMethod);
std::string fullMethodName(utf8Data(className), J9UTF8_LENGTH(className));
size_t len = J9UTF8_LENGTH(className) + J9UTF8_LENGTH(name) + J9UTF8_LENGTH(signature) + 2;
fullMethodName.reserve(len);
fullMethodName.push_back('.');
fullMethodName.append(utf8Data(name), J9UTF8_LENGTH(name));
fullMethodName.append(utf8Data(signature), J9UTF8_LENGTH(signature));
_methodNames.insert({romMethod, fullMethodName});
}
}
}
// Search the hashtable for my method and increment the number of samples
_samplesPerMethod[entry->getROMMethod()]++;
}
#endif
records++;
}
}
Expand All @@ -4426,7 +4509,33 @@ UDATA TR_IProfiler::parseBuffer(J9VMThread * vmThread, const U_8* dataStart, UDA
return 0;
}
_iprofilerNumRecords += records;

#if defined(TRACK_SAMPLE_SOURCES)
// If enough time has passed since the last operation
// determine the top 5 romMethods with the most number of samples and
// print their names. Then clear _samplesPerMethod and start all over.
static uint64_t lastPrintTime = 0;
static uint64_t lastNumIPsamples = 0;
if (printIProfilerActivity && vmThread == _iprofilerThread) // only IProfiler thread is allowed to execute this)
{
uint64_t crtTime = _compInfo->getPersistentInfo()->getElapsedTime();
if (crtTime - lastPrintTime >= 5000) // every 5 seconds or so
{
TopFiveMethods topFive;
for (auto it = _samplesPerMethod.begin(); it != _samplesPerMethod.end(); ++it)
topFive.processElement(*it);
fprintf(stderr, "t=%lu Total IP samples in the last interval = %lu\n",
(unsigned long)crtTime, (unsigned long)(_iprofilerNumRecords - lastNumIPsamples));
fprintf(stderr, "Top five methods in terms of samples in the last interval:\n");
topFive.print(_methodNames);
fprintf(stderr, "Total CPU spent in IProfiler thread =%u ms\n",
(unsigned)(j9thread_get_self_cpu_time(j9thread_self())/1000000));
// Prepare for next interval
_samplesPerMethod.clear();
lastPrintTime = crtTime;
lastNumIPsamples = _iprofilerNumRecords;
}
}
#endif
return records;
}

Expand Down
36 changes: 34 additions & 2 deletions runtime/compiler/runtime/IProfiler.hpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -61,6 +61,11 @@
* Interpreter Profiling Framework" by Ian Gartley, Marius Pirvu, Vijay
* Sundaresan and Nikola Grecvski, published in *Code Generation and Optimization (CGO)*, 2013.
*/
#define TRACK_SAMPLE_SOURCES
#if defined(TRACK_SAMPLE_SOURCES)
#include <list>
#include <unordered_map>
#endif // defined(TRACK_SAMPLE_SOURCES)

#include "j9.h"
#include "j9cfg.h"
Expand Down Expand Up @@ -196,9 +201,18 @@ class TR_IPBytecodeHashTableEntry
void * operator new (size_t size, void * placement) {return placement;}
void operator delete(void *p, void *) {}

TR_IPBytecodeHashTableEntry(uintptr_t pc) : _next(NULL), _pc(pc), _lastSeenClassUnloadID(-1), _entryFlags(0), _persistFlags(IPBC_ENTRY_CAN_PERSIST_FLAG) {}
TR_IPBytecodeHashTableEntry(uintptr_t pc) : _next(NULL), _pc(pc), _lastSeenClassUnloadID(-1), _entryFlags(0), _persistFlags(IPBC_ENTRY_CAN_PERSIST_FLAG)
{
#if defined(TRACK_SAMPLE_SOURCES)
_romMethod = NULL;
#endif
}
virtual ~TR_IPBytecodeHashTableEntry() {}
uintptr_t getPC() const { return _pc; }
#if defined(TRACK_SAMPLE_SOURCES)
J9ROMMethod *getROMMethod() const { return _romMethod; }
void setROMMethod(J9ROMMethod *method) { _romMethod = method; }
#endif // TRACK_SAMPLE_SOURCES
TR_IPBytecodeHashTableEntry * getNext() const { return _next; }
void setNext(TR_IPBytecodeHashTableEntry *n) { _next = n; }
int32_t getLastSeenClassUnloadID() const { return _lastSeenClassUnloadID; }
Expand Down Expand Up @@ -243,6 +257,9 @@ class TR_IPBytecodeHashTableEntry
protected:
TR_IPBytecodeHashTableEntry *_next;
uintptr_t _pc;
#if defined(TRACK_SAMPLE_SOURCES)
J9ROMMethod *_romMethod; // romMethod containing the _pc
#endif // TRACK_SAMPLE_SOURCES
int32_t _lastSeenClassUnloadID;

enum TR_PersistenceFlags
Expand Down Expand Up @@ -818,6 +835,21 @@ class TR_IProfiler : public TR_ExternalProfiler

volatile TR_IprofilerThreadLifetimeStates _iprofilerThreadLifetimeState;

#if defined(TRACK_SAMPLE_SOURCES)
// hashtable that maps ROMMethods to number of samples. Uses malloc underneath
std::unordered_map<const J9ROMMethod *, uint32_t> _samplesPerMethod;
// Hashtable that maps ROMMethods to their names; this avoids any class unloading concerns
std::unordered_map<const J9ROMMethod *, std::string> _methodNames;
class TopFiveMethods
{
public:
void processElement(const std::pair<const J9ROMMethod*, uint32_t> & newElem);
void print(const std::unordered_map<const J9ROMMethod *, std::string> &names);
private:
std::list<std::pair<const J9ROMMethod*, uint32_t> > _sortedList;
}; // class TopFiveMethods
#endif

public:
static int32_t _STATS_noProfilingInfo;
static int32_t _STATS_doesNotWantToGiveProfilingInfo;
Expand Down Expand Up @@ -852,7 +884,7 @@ class TR_IProfiler : public TR_ExternalProfiler

static int32_t _STATS_IPEntryRead;
static int32_t _STATS_IPEntryChoosePersistent;
};
}; // TR_IProfiler

void printIprofilerStats(TR::Options *options, J9JITConfig * jitConfig, TR_IProfiler *iProfiler, const char *event);
void turnOffInterpreterProfiling(J9JITConfig *jitConfig);
Expand Down

0 comments on commit 991a9c4

Please sign in to comment.