void
MM_VerboseHandlerOutputStandard::handleConcurrentHalted(J9HookInterface** hook, uintptr_t eventNum, void* eventData)
{
MM_ConcurrentHaltedEvent* event = (MM_ConcurrentHaltedEvent*)eventData;
MM_VerboseManager* manager = getManager();
MM_VerboseWriterChain* writer = manager->getWriterChain();
MM_EnvironmentBase* env = MM_EnvironmentBase::getEnvironment(event->currentThread);
OMRPORT_ACCESS_FROM_ENVIRONMENT(env);
char tagTemplate[200];
enterAtomicReportingBlock();
getTagTemplate(tagTemplate, sizeof(tagTemplate), manager->getIdAndIncrement(), omrtime_current_time_millis());
writer->formatAndOutput(env, 0, "<concurrent-halted %s>", tagTemplate);
handleConcurrentHaltedInternal(env, eventData);
writer->formatAndOutput(env, 1,
"<traced "
"bytesTarget=\"%zu\" bytesTotal=\"%zu\" "
"bytesByMutator=\"%zu\" bytesByHelper=\"%zu\" "
"percent=\"%zu\" />",
event->traceTarget, event->tracedTotal,
event->tracedByMutators, event->tracedByHelpers,
event->traceTarget == 0 ? 0 : (uintptr_t)(((uint64_t)event->tracedTotal * 100) / (uint64_t)event->traceTarget));
writer->formatAndOutput(env, 1, "<cards cleaned=\"%zu\" thresholdBytes=\"%zu\" />", event->cardsCleaned, event->cardCleaningThreshold);
writer->formatAndOutput(env, 0, "</concurrent-halted>");
writer->flush(env);
exitAtomicReportingBlock();
}
void
MM_VerboseHandlerOutput::handleInitialized(J9HookInterface** hook, uintptr_t eventNum, void* eventData)
{
MM_InitializedEvent* event = (MM_InitializedEvent*)eventData;
MM_VerboseWriterChain* writer = _manager->getWriterChain();
MM_EnvironmentBase* env = MM_EnvironmentBase::getEnvironment(event->currentThread);
OMRPORT_ACCESS_FROM_ENVIRONMENT(env);
char tagTemplate[200];
_manager->setInitializedTime(event->timestamp);
getTagTemplate(tagTemplate, sizeof(tagTemplate), _manager->getIdAndIncrement(), omrtime_current_time_millis());
enterAtomicReportingBlock();
writer->formatAndOutput(env, 0, "<initialized %s>", tagTemplate);
writer->formatAndOutput(env, 1, "<attribute name=\"gcPolicy\" value=\"%s\" />", event->gcPolicy);
#if defined(OMR_GC_CONCURRENT_SCAVENGER)
if (_extensions->isConcurrentScavengerEnabled()) {
writer->formatAndOutput(env, 1, "<attribute name=\"concurrentScavenger\" value=\"%s\" />",
#if defined(S390)
_extensions->concurrentScavengerHWSupport ?
"enabled, with H/W assistance" :
"enabled, without H/W assistance");
#else /* defined(S390) */
"enabled");
#endif /* defined(S390) */
}
void
MM_VerboseHandlerOutputStandard::handleConcurrentKickoff(J9HookInterface** hook, uintptr_t eventNum, void* eventData)
{
MM_ConcurrentKickoffEvent* event = (MM_ConcurrentKickoffEvent*)eventData;
MM_VerboseManager* manager = getManager();
MM_VerboseWriterChain* writer = manager->getWriterChain();
MM_EnvironmentBase* env = MM_EnvironmentBase::getEnvironment(event->currentThread);
MM_GCExtensionsBase* extensions = MM_GCExtensionsBase::getExtensions(env->getOmrVM());
OMRPORT_ACCESS_FROM_ENVIRONMENT(env);
char tagTemplate[200];
enterAtomicReportingBlock();
getTagTemplate(tagTemplate, sizeof(tagTemplate), manager->getIdAndIncrement(), omrtime_current_time_millis());
writer->formatAndOutput(env, 0, "<concurrent-kickoff %s>", tagTemplate);
const char* reasonString = getConcurrentKickoffReason(eventData);
if (extensions->scavengerEnabled) {
writer->formatAndOutput(
env, 1, "<kickoff reason=\"%s\" targetBytes=\"%zu\" thresholdFreeBytes=\"%zu\" remainingFree=\"%zu\" tenureFreeBytes=\"%zu\" nurseryFreeBytes=\"%zu\" />",
reasonString, event->traceTarget, event->kickOffThreshold, event->remainingFree, event->commonData->tenureFreeBytes, event->commonData->nurseryFreeBytes);
} else {
writer->formatAndOutput(
env, 1, "<kickoff reason=\"%s\" targetBytes=\"%zu\" thresholdFreeBytes=\"%zu\" remainingFree=\"%zu\" tenureFreeBytes=\"%zu\" />",
reasonString, event->traceTarget, event->kickOffThreshold, event->remainingFree, event->commonData->tenureFreeBytes);
}
writer->formatAndOutput(env, 0, "</concurrent-kickoff>");
writer->flush(env);
handleConcurrentKickoffInternal(env, eventData);
exitAtomicReportingBlock();
}
TEST_P(GCConfigTest, test)
{
OMRPORT_ACCESS_FROM_OMRPORT(gcTestEnv->portLib);
int32_t rt = 0;
pugi::xml_node configNode = doc.select_node("/gc-config").node().first_child();
if (0 == strcmp(configNode.name(), "option")) {
configNode = configNode.next_sibling();
}
for (; configNode; configNode = configNode.next_sibling()) {
if (0 == strcmp(configNode.name(), "allocation")) {
omrtty_printf("\n+++++++++++++++++++++++++++Allocation+++++++++++++++++++++++++++\n");
rt = parseGarbagePolicy(configNode.child("garbagePolicy"));
ASSERT_EQ(0, rt) << "Failed to parse garbage policy.";
pugi::xpath_node_set objects = configNode.select_nodes("object");
int64_t startTime = omrtime_current_time_millis();
for (pugi::xpath_node_set::const_iterator it = objects.begin(); it != objects.end(); ++it) {
rt = allocationWalker(it->node());
ASSERT_EQ(0, rt) << "Failed to perform allocation.";
}
omrtty_printf("Time elapsed in allocation: %lld ms\n", (omrtime_current_time_millis() - startTime));
} else if (0 == strcmp(configNode.name(), "verification")) {
omrtty_printf("\n++++++++++++++++++++++++++Verification++++++++++++++++++++++++++\n");
/* verboseGC verification */
pugi::xpath_node_set verboseGCs = configNode.select_nodes("verboseGC");
rt = verifyVerboseGC(verboseGCs);
ASSERT_EQ(0, rt) << "Failed in verbose GC verification.";
omrtty_printf("[ Verification Successful ]\n\n");
} else if (0 == strcmp(configNode.name(), "operation")) {
omrtty_printf("\n++++++++++++++++++++++++++++Operation+++++++++++++++++++++++++++\n");
rt = triggerOperation(configNode.first_child());
ASSERT_EQ(0, rt) << "Failed to perform gc operation.";
} else if (0 == strcmp(configNode.name(), "mutation")) {
/*TODO*/
} else {
FAIL() << "Invalid XML input: unrecognized XML node \"" << configNode.name() << "\" in configuration file.";
}
}
}
void
MM_VerboseHandlerOutputStandard::handleConcurrentCollectionEnd(J9HookInterface** hook, uintptr_t eventNum, void* eventData)
{
MM_ConcurrentCollectionEndEvent* event = (MM_ConcurrentCollectionEndEvent*)eventData;
MM_VerboseManager* manager = getManager();
MM_VerboseWriterChain* writer = manager->getWriterChain();
MM_EnvironmentBase* env = MM_EnvironmentBase::getEnvironment(event->currentThread);
OMRPORT_ACCESS_FROM_ENVIRONMENT(env);
char tagTemplate[200];
enterAtomicReportingBlock();
getTagTemplate(tagTemplate, sizeof(tagTemplate), manager->getIdAndIncrement(), omrtime_current_time_millis());
writer->formatAndOutput(env, 0, "<concurrent-collection-end %s />", tagTemplate);
writer->flush(env);
handleConcurrentCollectionEndInternal(env, eventData);
exitAtomicReportingBlock();
}
void
MM_VerboseHandlerOutputStandard::handleScavengePercolate(J9HookInterface** hook, uintptr_t eventNum, void* eventData)
{
MM_PercolateCollectEvent *event = (MM_PercolateCollectEvent *)eventData;
MM_EnvironmentBase* env = MM_EnvironmentBase::getEnvironment(event->currentThread);
OMRPORT_ACCESS_FROM_OMRPORT(env->getPortLibrary());
MM_VerboseManager* manager = getManager();
MM_VerboseWriterChain* writer = manager->getWriterChain();
char tagTemplate[200];
getTagTemplate(tagTemplate, sizeof(tagTemplate), omrtime_current_time_millis());
enterAtomicReportingBlock();
writer->formatAndOutput(env, 0, "<percolate-collect id=\"%zu\" from=\"%s\" to=\"%s\" reason=\"%s\" %s/>", manager->getIdAndIncrement(), "nursery", "global", getPercolateReasonAsString((PercolateReason)event->reason), tagTemplate);
writer->flush(env);
handleScavengePercolateInternal(env, eventData);
exitAtomicReportingBlock();
}
void
MM_VerboseHandlerOutputStandard::handleConcurrentCollectionStart(J9HookInterface** hook, uintptr_t eventNum, void* eventData)
{
MM_ConcurrentCollectionStartEvent* event = (MM_ConcurrentCollectionStartEvent*)eventData;
MM_VerboseManager* manager = getManager();
MM_VerboseWriterChain* writer = manager->getWriterChain();
MM_EnvironmentBase* env = MM_EnvironmentBase::getEnvironment(event->currentThread);
OMRPORT_ACCESS_FROM_ENVIRONMENT(env);
uint64_t currentTime = event->timestamp;
uint64_t previousTime = manager->getLastConcurrentGCTime();
manager->setLastConcurrentGCTime(currentTime);
if (0 == previousTime) {
previousTime = manager->getInitializedTime();
}
uint64_t deltaTime = omrtime_hires_delta(previousTime, currentTime, OMRPORT_TIME_DELTA_IN_MICROSECONDS);
const char* cardCleaningReasonString = "unknown";
switch (event->cardCleaningReason) {
case TRACING_COMPLETED:
cardCleaningReasonString = "tracing completed";
break;
case CARD_CLEANING_THRESHOLD_REACHED:
cardCleaningReasonString = "card cleaning threshold reached";
break;
}
char tagTemplate[200];
enterAtomicReportingBlock();
getTagTemplate(tagTemplate, sizeof(tagTemplate), manager->getIdAndIncrement(), omrtime_current_time_millis());
writer->formatAndOutput(env, 0, "<concurrent-collection-start %s intervalms=\"%llu.%03llu\" >",
tagTemplate, deltaTime / 1000, deltaTime % 1000);
writer->formatAndOutput(env, 1, "<concurrent-trace-info reason=\"%s\" tracedByMutators=\"%zu\" tracedByHelpers=\"%zu\" cardsCleaned=\"%zu\" workStackOverflowCount=\"%zu\" />",
cardCleaningReasonString, event->tracedByMutators, event->tracedByHelpers, event->cardsCleaned, event->workStackOverflowCount);
writer->formatAndOutput(env, 0, "</concurrent-collection-start>");
writer->flush(env);
handleConcurrentCollectionStartInternal(env, eventData);
exitAtomicReportingBlock();
}
/**
* Initialize the _tokens field.
* JTCJAZZ 36600 alias %p to be the same as %pid
*/
bool
MM_VerboseWriterFileLogging::initializeTokens(MM_EnvironmentBase *env)
{
OMRPORT_ACCESS_FROM_OMRPORT(env->getPortLibrary());
char pidBuffer[64];
_tokens = omrstr_create_tokens(omrtime_current_time_millis());
if (_tokens == NULL) {
return false;
}
if (sizeof(pidBuffer) < omrstr_subst_tokens(pidBuffer, sizeof(pidBuffer), "%pid", _tokens)) {
return false;
}
if (omrstr_set_token(_tokens, "p", "%s", pidBuffer)) {
return false;
}
return true;
}
void
MM_VerboseHandlerOutputStandard::handleConcurrentAborted(J9HookInterface** hook, uintptr_t eventNum, void* eventData)
{
MM_ConcurrentAbortedEvent* event = (MM_ConcurrentAbortedEvent*)eventData;
MM_VerboseManager* manager = getManager();
MM_VerboseWriterChain* writer = manager->getWriterChain();
MM_EnvironmentBase* env = MM_EnvironmentBase::getEnvironment(event->currentThread);
OMRPORT_ACCESS_FROM_ENVIRONMENT(env);
char tagTemplate[100];
enterAtomicReportingBlock();
getTagTemplate(tagTemplate, sizeof(tagTemplate), manager->getIdAndIncrement(), omrtime_current_time_millis());
writer->formatAndOutput(env, 0, "<concurrent-aborted %s>", tagTemplate);
const char* reason;
switch((CollectionAbortReason)event->reason) {
case ABORT_COLLECTION_INSUFFICENT_PROGRESS:
reason = "insufficient progress made";
break;
case ABORT_COLLECTION_REMEMBERSET_OVERFLOW:
reason = "remembered set overflow";
break;
case ABORT_COLLECTION_SCAVENGE_REMEMBEREDSET_OVERFLOW:
reason = "scavenge remembered set overflow";
break;
case ABORT_COLLECTION_PREPARE_HEAP_FOR_WALK:
reason = "prepare heap for walk";
break;
default:
reason = "unknown";
break;
}
writer->formatAndOutput(env, 1, "<reason value=\"%s\" />", reason);
writer->formatAndOutput(env, 0, "</concurrent-aborted>");
writer->flush(env);
handleConcurrentAbortedInternal(env, eventData);
exitAtomicReportingBlock();
}
/*
* Inform all registered listeners that the specified event has occurred. Details about the
* event should be available through eventData.
*
* If the J9HOOK_TAG_ONCE bit is set in the taggedEventNum, then the event is disabled
* before the listeners are informed. Any attempts to add listeners to a TAG_ONCE event
* once it has been reported will fail.
*
* This function should not be called directly. It should be called through the hook interface
*
*/
static void
J9HookDispatch(struct J9HookInterface **hookInterface, uintptr_t taggedEventNum, void *eventData)
{
uintptr_t eventNum = taggedEventNum & J9HOOK_EVENT_NUM_MASK;
J9CommonHookInterface *commonInterface = (J9CommonHookInterface *)hookInterface;
J9HookRecord *record = HOOK_RECORD(commonInterface, eventNum);
OMREventInfo4Dump *eventDump = J9HOOK_DUMPINFO(commonInterface, eventNum);
uintptr_t samplingInterval = (taggedEventNum & J9HOOK_TAG_SAMPLING_MASK) >> 16;
bool sampling = false;
if (taggedEventNum & J9HOOK_TAG_ONCE) {
uint8_t oldFlags;
omrthread_monitor_enter(commonInterface->lock);
oldFlags = HOOK_FLAGS(commonInterface, eventNum);
/* clear the HOOKED and RESERVED flags and set the DISABLED flag */
HOOK_FLAGS(commonInterface, eventNum) = (oldFlags | J9HOOK_FLAG_DISABLED) & ~(J9HOOK_FLAG_RESERVED | J9HOOK_FLAG_HOOKED);
omrthread_monitor_exit(commonInterface->lock);
if (oldFlags & J9HOOK_FLAG_DISABLED) {
/* already reported */
return;
}
}
while (record) {
J9HookFunction function;
void *userData;
uintptr_t id;
/* ensure that the id is read before any other fields */
id = record->id;
if (HOOK_IS_VALID_ID(id)) {
VM_AtomicSupport::readBarrier();
function = record->function;
userData = record->userData;
/* now read the id again to make sure that nothing has changed */
VM_AtomicSupport::readBarrier();
if (record->id == id) {
uint64_t startTime = 0;
uintptr_t count = 0;
if (NULL != eventDump) {
count = VM_AtomicSupport::add((volatile uintptr_t *)&eventDump->count, 1);
sampling = (1 >= samplingInterval) || ((100 >= samplingInterval) && (0 == (count % samplingInterval)));
} else {
sampling = false;
}
OMRPORT_ACCESS_FROM_OMRPORT(commonInterface->portLib);
if (sampling) {
startTime = omrtime_current_time_millis();
}
function(hookInterface, eventNum, eventData, userData);
if (sampling) {
uint64_t timeDelta = omrtime_current_time_millis() - startTime;
eventDump->lastHook.startTime = startTime;
eventDump->lastHook.callsite = record->callsite;
eventDump->lastHook.func_ptr = (void *)record->function;
eventDump->lastHook.duration = timeDelta;
if ((eventDump->longestHook.duration < timeDelta) ||
(0 == eventDump->longestHook.startTime)) {
eventDump->longestHook.startTime = startTime;
eventDump->longestHook.callsite = record->callsite;
eventDump->longestHook.func_ptr = (void *)record->function;
eventDump->longestHook.duration = timeDelta;
}
if (commonInterface->threshold4Trace <= timeDelta) {
const char *callsite = "UNKNOWN";
char buffer[32];
if (NULL != record->callsite) {
callsite = record->callsite;
} else {
/* if the callsite info can not be retrieved, use callback function pointer instead */
omrstr_printf(buffer, sizeof(buffer), "0x%p", record->function);
callsite = buffer;
}
Trc_Hook_Dispatch_Exceed_Threshold_Event(callsite, timeDelta);
}
}
} else {
/* this record has been updated while we were reading it. Skip it. */
}
}
record = record->next;
}
}
void
GCConfigTest::SetUp()
{
OMRPORT_ACCESS_FROM_OMRPORT(gcTestEnv->portLib);
printMemUsed("Setup()", gcTestEnv->portLib);
/* Initialize heap and collector */
MM_StartupManagerTestExample startupManager(exampleVM->_omrVM, GetParam());
omr_error_t rc = OMR_GC_IntializeHeapAndCollector(exampleVM->_omrVM, &startupManager);
ASSERT_EQ(OMR_ERROR_NONE, rc) << "Setup(): OMR_GC_IntializeHeapAndCollector failed, rc=" << rc;
/* Attach calling thread to the VM */
exampleVM->_omrVMThread = NULL;
rc = OMR_Thread_Init(exampleVM->_omrVM, NULL, &exampleVM->_omrVMThread, "OMRTestThread");
ASSERT_EQ(OMR_ERROR_NONE, rc) << "Setup(): OMR_Thread_Init failed, rc=" << rc;
/* Kick off the dispatcher threads */
rc = OMR_GC_InitializeDispatcherThreads(exampleVM->_omrVMThread);
ASSERT_EQ(OMR_ERROR_NONE, rc) << "Setup(): OMR_GC_InitializeDispatcherThreads failed, rc=" << rc;
env = MM_EnvironmentBase::getEnvironment(exampleVM->_omrVMThread);
/* load config file */
omrtty_printf("Configuration File: %s\n", GetParam());
#if defined(OMRGCTEST_PRINTFILE)
printFile(GetParam());
#endif
pugi::xml_parse_result result = doc.load_file(GetParam());
if (!result) {
FAIL() << "Failed to load test configuration file (" << GetParam() << ") with error description: " << result.description() << ".";
}
/* parse verbose information and initialize verbose manager */
pugi::xml_node optionNode = doc.select_node("/gc-config/option").node();
const char *verboseFileNamePrefix = optionNode.attribute("verboseLog").value();
numOfFiles = (uintptr_t)optionNode.attribute("numOfFiles").as_int();
uintptr_t numOfCycles = (uintptr_t)optionNode.attribute("numOfCycles").as_int();
if (0 == strcmp(verboseFileNamePrefix, "")) {
verboseFileNamePrefix = "VerboseGCOutput";
}
verboseFile = (char *)omrmem_allocate_memory(MAX_NAME_LENGTH, OMRMEM_CATEGORY_MM);
if (NULL == verboseFile) {
FAIL() << "Failed to allocate native memory.";
}
omrstr_printf(verboseFile, MAX_NAME_LENGTH, "%s_%d_%lld.xml", verboseFileNamePrefix, omrsysinfo_get_pid(), omrtime_current_time_millis());
verboseManager = MM_VerboseManager::newInstance(env, exampleVM->_omrVM);
verboseManager->configureVerboseGC(exampleVM->_omrVM, verboseFile, numOfFiles, numOfCycles);
omrtty_printf("Verbose File: %s\n", verboseFile);
#if defined(OMRGCTEST_DEBUG)
omrtty_printf("Verbose GC log name: %s; numOfFiles: %d; numOfCycles: %d.\n", verboseFile, numOfFiles, numOfCycles);
#endif
verboseManager->enableVerboseGC();
verboseManager->setInitializedTime(omrtime_hires_clock());
/* create object table */
objectTable.create();
/* create root table */
exampleVM->rootTable = hashTableNew(
gcTestEnv->portLib, OMR_GET_CALLSITE(), 0, sizeof(RootEntry), 0, 0, OMRMEM_CATEGORY_MM,
rootTableHashFn, rootTableHashEqualFn, NULL, NULL);
}
void
MM_VerboseHandlerOutputStandard::handleGCOPOuterStanzaStart(MM_EnvironmentBase* env, const char *type, uintptr_t contextID, uint64_t duration, bool deltaTimeSuccess)
{
MM_VerboseManager* manager = getManager();
MM_VerboseWriterChain* writer = manager->getWriterChain();
OMRPORT_ACCESS_FROM_OMRPORT(env->getPortLibrary());
if (!deltaTimeSuccess) {
writer->formatAndOutput(env, 0, "<warning details=\"clock error detected, following timing may be inaccurate\" />");
}
char tagTemplate[200];
getTagTemplate(tagTemplate, sizeof(tagTemplate), manager->getIdAndIncrement(), type ,contextID, duration, omrtime_current_time_millis());
writer->formatAndOutput(env, 0, "<gc-op %s>", tagTemplate);
}