CPU and process util stats

gc/CMakeLists.txt

@@ -173,7 +173,7 @@ set(omrgc_sources
 	stats/AllocationStats.cpp
 	stats/CardCleaningStats.cpp
 	stats/ClassUnloadStats.cpp
-
+	stats/CPUUtilStats.cpp
 	stats/FreeEntrySizeClassStats.cpp
 	stats/HeapResizeStats.cpp
 	stats/LargeObjectAllocateStats.cpp

gc/base/GCExtensionsBase.hpp

@@ -33,6 +33,7 @@
 #include "AllocationStats.hpp"
 #include "ArrayObjectModel.hpp"
 #include "BaseVirtual.hpp"
+#include "CPUUtilStats.hpp"
 #include "ExcessiveGCStats.hpp"
 #include "Forge.hpp"
 #include "GlobalGCStats.hpp"
@@ -876,6 +877,7 @@ class MM_GCExtensionsBase : public MM_BaseVirtual {
 #endif /* defined(OMR_VALGRIND_MEMCHECK) */
 
 	bool shouldForceLowMemoryHeapCeilingShiftIfPossible; /**< Whether we should force compressed reference shift to 3 **/
+	MM_CPUUtilStats cpuUtilStats; /**< CPU/process util between any STW GC increments, hence not part of any Collector Stats */
 	/* Function Members */
 private:
 
@@ -1967,6 +1969,7 @@ class MM_GCExtensionsBase : public MM_BaseVirtual {
 		, valgrindMempoolAddr(0)
 		, memcheckHashTable(NULL)
 		, shouldForceLowMemoryHeapCeilingShiftIfPossible(false)
+		, cpuUtilStats()
 #endif /* defined(OMR_VALGRIND_MEMCHECK) */
 	{
 		_typeId = __FUNCTION__;

gc/base/j9mm.tdf

@@ -1028,3 +1028,7 @@ TraceEvent=Trc_MM_MSSSS_flip_restore_tilt_after_percolate_current_status Overhea
 
 TraceEvent=Trc_MM_clearheap Overhead=1 Level=1 Group=gclogger Template="clearheap with free memory size: %zu, object size: %zu"
 TraceEvent=Trc_MM_cleanUpSegmentsInAnonymousClassLoader_stats Overhead=1 Level=1 Group=gclogger Template="Anonymous classes: total: %zu, unloaded: %zu, searched ROM: %zu, found ROM fast: %zu, found ROM slow: %zu, not found ROM: %zu"
+
+TraceEvent=Trc_MM_CPUUtilStats_processAndCpuUtilization_process_larger_than_elapsed Overhead=1 Level=1 Group=gclogger Template="process %lld larger than elapsed %lld; both adjusted to %lld"
+TraceEvent=Trc_MM_CPUUtilStats_processAndCpuUtilization_cpu_larger_than_elapsed Overhead=1 Level=1 Group=gclogger Template="cpu %lld larger than elapsed %lld; cpu adjusted to elapsed"
+TraceEvent=Trc_MM_CPUUtilStats_processAndCpuUtilization_cpu_smaller_than_process Overhead=1 Level=1 Group=gclogger Template="cpu %lld smaller than process %lld; cpu adjusted to process"

gc/base/standard/ParallelGlobalGC.cpp

@@ -1712,23 +1712,12 @@ MM_ParallelGlobalGC::reportGCStart(MM_EnvironmentBase *env)
 void
 MM_ParallelGlobalGC::reportGCIncrementStart(MM_EnvironmentBase *env)
 {
-	OMRPORT_ACCESS_FROM_ENVIRONMENT(env);
 	MM_CollectionStatisticsStandard *stats = (MM_CollectionStatisticsStandard *)env->_cycleState->_collectionStatistics;
 	stats->collectCollectionStatistics(env, stats);
-	stats->_startTime = omrtime_hires_clock();
-
-	intptr_t rc = omrthread_get_process_times(&stats->_startProcessTimes);
-	switch (rc){
-	case -1: /* Error: Function un-implemented on architecture */
-	case -2: /* Error: getrusage() or GetProcessTimes() returned error value */
-		stats->_startProcessTimes._userTime = I_64_MAX;
-		stats->_startProcessTimes._systemTime = I_64_MAX;
-		break;
-	case  0:
-		break; /* Success */
-	default:
-		Assert_MM_unreachable();
-	}
+	/* Among other things this will get process and elapse time info&timestamps that are not only needed for
+	 * mutator CPU util calc but also needed for GC STW user/system/stall breakdown reporting
+	 */
+	_extensions->cpuUtilStats.calculateProcessAndCpuUtilizationDelta(env, stats);
 
 	TRIGGER_J9HOOK_MM_PRIVATE_GC_INCREMENT_START(
 		_extensions->privateHookInterface,
@@ -1741,25 +1730,14 @@ MM_ParallelGlobalGC::reportGCIncrementStart(MM_EnvironmentBase *env)
 void
 MM_ParallelGlobalGC::reportGCIncrementEnd(MM_EnvironmentBase *env)
 {
-	OMRPORT_ACCESS_FROM_ENVIRONMENT(env);
 	MM_CollectionStatisticsStandard *stats = (MM_CollectionStatisticsStandard *)env->_cycleState->_collectionStatistics;
 	stats->collectCollectionStatistics(env, stats);
-
-	intptr_t rc = omrthread_get_process_times(&stats->_endProcessTimes);
-	switch (rc){
-	case -1: /* Error: Function un-implemented on architecture */
-	case -2: /* Error: getrusage() or GetProcessTimes() returned error value */
-		stats->_endProcessTimes._userTime = 0;
-		stats->_endProcessTimes._systemTime = 0;
-		break;
-	case  0:
-		break; /* Success */
-	default:
-		Assert_MM_unreachable();
-	}
-
-	stats->_endTime = omrtime_hires_clock();
+	/* Among other things this will get process and elapse time info&timestamps that are not only needed for
+	 * mutator CPU util calc but also needed for GC STW user/system/stall breakdown reporting
+	 */
+	_extensions->cpuUtilStats.recordProcessAndCpuUtilization(env, stats);
 	stats->_stallTime = _extensions->globalGCStats.getStallTime();
+
 	TRIGGER_J9HOOK_MM_PRIVATE_GC_INCREMENT_END(
 		_extensions->privateHookInterface,
 		env->getOmrVMThread(),

gc/base/standard/Scavenger.cpp

@@ -4967,24 +4967,12 @@ MM_Scavenger::calculateTiltRatio()
 void
 MM_Scavenger::reportGCIncrementStart(MM_EnvironmentStandard *env)
 {
-	OMRPORT_ACCESS_FROM_ENVIRONMENT(env);
 	MM_CollectionStatisticsStandard *stats = (MM_CollectionStatisticsStandard *)env->_cycleState->_collectionStatistics;
 	stats->collectCollectionStatistics(env, stats);
-	stats->_startTime = omrtime_hires_clock();
-
-	intptr_t rc = omrthread_get_process_times(&stats->_startProcessTimes);
-	switch (rc){
-	case -1: /* Error: Function un-implemented on architecture */
-	case -2: /* Error: getrusage() or GetProcessTimes() returned error value */
-		stats->_startProcessTimes._userTime = I_64_MAX;
-		stats->_startProcessTimes._systemTime = I_64_MAX;
-		break;
-	case  0:
-		break; /* Success */
-	default:
-		Assert_MM_unreachable();
-	}
-
+	/* Among other things this will get process and elapse time info&timestamps that are not only needed for
+	 * mutator CPU util calc but also needed for GC STW user/system/stall breakdown reporting
+	 */
+	_extensions->cpuUtilStats.calculateProcessAndCpuUtilizationDelta(env, stats);
 	TRIGGER_J9HOOK_MM_PRIVATE_GC_INCREMENT_START(
 		_extensions->privateHookInterface,
 		env->getOmrVMThread(),
@@ -4996,24 +4984,12 @@ MM_Scavenger::reportGCIncrementStart(MM_EnvironmentStandard *env)
 void
 MM_Scavenger::reportGCIncrementEnd(MM_EnvironmentStandard *env)
 {
-	OMRPORT_ACCESS_FROM_ENVIRONMENT(env);
 	MM_CollectionStatisticsStandard *stats = (MM_CollectionStatisticsStandard *)env->_cycleState->_collectionStatistics;
 	stats->collectCollectionStatistics(env, stats);
-
-	intptr_t rc = omrthread_get_process_times(&stats->_endProcessTimes);
-	switch (rc){
-	case -1: /* Error: Function un-implemented on architecture */
-	case -2: /* Error: getrusage() or GetProcessTimes() returned error value */
-		stats->_endProcessTimes._userTime = 0;
-		stats->_endProcessTimes._systemTime = 0;
-		break;
-	case  0:
-		break; /* Success */
-	default:
-		Assert_MM_unreachable();
-	}
-
-	stats->_endTime = omrtime_hires_clock();
+	/* Among other things this will get process and elapse time info&timestamps that are not only needed for
+	 * mutator CPU util calc but also needed for GC STW user/system/stall breakdown reporting
+	 */
+	_extensions->cpuUtilStats.recordProcessAndCpuUtilization(env, stats);
 	stats->_stallTime = _extensions->scavengerStats.getStallTime();
 
 	TRIGGER_J9HOOK_MM_PRIVATE_GC_INCREMENT_END(

gc/stats/CPUUtilStats.cpp

@@ -0,0 +1,156 @@
+/*******************************************************************************
+ * Copyright IBM Corp. and others 2024
+ *
+ * This program and the accompanying materials are made available under
+ * the terms of the Eclipse Public License 2.0 which accompanies this
+ * distribution and is available at https://www.eclipse.org/legal/epl-2.0/
+ * or the Apache License, Version 2.0 which accompanies this distribution and
+ * is available at https://www.apache.org/licenses/LICENSE-2.0.
+ *
+ * This Source Code may also be made available under the following
+ * Secondary Licenses when the conditions for such availability set
+ * forth in the Eclipse Public License, v. 2.0 are satisfied: GNU
+ * General Public License, version 2 with the GNU Classpath
+ * Exception [1] and GNU General Public License, version 2 with the
+ * OpenJDK Assembly Exception [2].
+ *
+ * [1] https://www.gnu.org/software/classpath/license.html
+ * [2] https://openjdk.org/legal/assembly-exception.html
+ *
+ * SPDX-License-Identifier: EPL-2.0 OR Apache-2.0 OR GPL-2.0-only WITH Classpath-exception-2.0 OR GPL-2.0-only WITH OpenJDK-assembly-exception-1.0
+ *******************************************************************************/
+
+/**
+ * @file
+ * @ingroup GC_Stats
+ */
+
+#include <math.h>
+
+#include "CPUUtilStats.hpp"
+
+#include "CollectionStatistics.hpp"
+#include "EnvironmentBase.hpp"
+#include "ModronAssertions.h"
+
+void
+MM_CPUUtilStats::recordProcessAndCpuUtilization(MM_EnvironmentBase *env, MM_CollectionStatistics *stats)
+{
+	OMRPORT_ACCESS_FROM_OMRPORT(env->getPortLibrary());
+
+	/* For process and cpu utilization, this is a start point (since we measure it between GC STW point.
+	 * However for GC (user/system/stall) measurement this is a end point.
+	 * Since some of the params like timestamp is shared for both measurements, the naming of some fields may be confusing, depending on perspective
+	 */
+
+	stats->_endTime = omrtime_hires_clock();
+
+	J9SysinfoCPUTime cpuTime;
+	intptr_t portLibraryStatus = omrsysinfo_get_CPU_utilization(&cpuTime);
+
+	_validData = (0 == portLibraryStatus);
+
+	intptr_t processRc = omrthread_get_process_times(&stats->_endProcessTimes);
+
+	switch (processRc) {
+	case -1: /* Error: Function un-implemented on architecture */
+	case -2: /* Error: getrusage() or GetProcessTimes() returned error value */
+		stats->_endProcessTimes._userTime = 0;
+		stats->_endProcessTimes._systemTime = 0;
+		_validData = false;
+		break;
+	case  0:
+		break; /* Success */
+	default:
+		Assert_MM_unreachable();
+	}
+
+	_elapsedTime = stats->_endTime;
+
+	if (_validData) {
+		_processUserTime = stats->_endProcessTimes._userTime;
+		_processSystemTime = stats->_endProcessTimes._systemTime;
+		_cpuTime = cpuTime.cpuTime;
+
+		/* Expose CPU stats data to the higher level stats struct (but with Collector specific instance), so it can be accessible via hooks */
+		stats->_cpuUtilStats = *this;
+	}
+}
+
+void
+MM_CPUUtilStats::calculateProcessAndCpuUtilizationDelta(MM_EnvironmentBase *env, MM_CollectionStatistics *stats)
+{
+	OMRPORT_ACCESS_FROM_OMRPORT(env->getPortLibrary());
+
+	/* For process and cpu utilization, this is an end point (since we measure it between GC STW point.
+	 * However for GC (user/system/stall) measurement this is a start point.
+	 * Since some of the params like timestamp is shared for both measurements, the naming of some fields may be confusing, depending on perspective
+	 */
+
+	intptr_t processRc = omrthread_get_process_times(&stats->_startProcessTimes);
+
+	switch (processRc) {
+	case -1: /* Error: Function un-implemented on architecture */
+	case -2: /* Error: getrusage() or GetProcessTimes() returned error value */
+		stats->_startProcessTimes._userTime = I_64_MAX;
+		stats->_startProcessTimes._systemTime = I_64_MAX;
+		break;
+	case  0:
+		break; /* Success */
+	default:
+		Assert_MM_unreachable();
+	}
+
+	J9SysinfoCPUTime cpuTime;
+	intptr_t portLibraryStatus = omrsysinfo_get_CPU_utilization(&cpuTime);
+
+	stats->_startTime = omrtime_hires_clock();
+
+	if (_validData && (0 == portLibraryStatus) && (0 == processRc) && (_elapsedTime < stats->_startTime)) {
+		int64_t elapsedTime = omrtime_hires_delta(_elapsedTime, stats->_startTime, OMRPORT_TIME_DELTA_IN_MICROSECONDS) * omrsysinfo_get_number_CPUs_by_type(OMRPORT_CPU_TARGET);
+		int64_t cpuTimeDiff = 0;
+
+		if (cpuTime.cpuTime > _cpuTime) {
+			cpuTimeDiff += omrtime_hires_delta(_cpuTime, cpuTime.cpuTime, OMRPORT_TIME_DELTA_IN_MICROSECONDS);
+		}
+
+		int64_t processTimeDiff = 0;
+
+		if (stats->_startProcessTimes._systemTime > _processSystemTime) {
+			processTimeDiff += omrtime_hires_delta(_processSystemTime, stats->_startProcessTimes._systemTime, OMRPORT_TIME_DELTA_IN_MICROSECONDS);
+		}
+
+		if (stats->_startProcessTimes._userTime > _processUserTime) {
+			processTimeDiff += omrtime_hires_delta(_processUserTime, stats->_startProcessTimes._userTime, OMRPORT_TIME_DELTA_IN_MICROSECONDS);
+		}
+
+		if (processTimeDiff > elapsedTime) {
+			int64_t adjustedValue = (processTimeDiff + elapsedTime) / 2;
+			Trc_MM_CPUUtilStats_processAndCpuUtilization_process_larger_than_elapsed(env->getLanguageVMThread(), processTimeDiff, elapsedTime, adjustedValue);
+			processTimeDiff = adjustedValue;
+			elapsedTime = adjustedValue;
+		}
+		if (cpuTimeDiff > elapsedTime) {
+			Trc_MM_CPUUtilStats_processAndCpuUtilization_cpu_larger_than_elapsed(env->getLanguageVMThread(), cpuTimeDiff, elapsedTime);
+			cpuTimeDiff = elapsedTime;
+		}
+		if (cpuTimeDiff < processTimeDiff) {
+			Trc_MM_CPUUtilStats_processAndCpuUtilization_cpu_smaller_than_process(env->getLanguageVMThread(), cpuTimeDiff, processTimeDiff);
+			cpuTimeDiff = processTimeDiff;
+		}
+		/* When calculating averages, take the new value with a weight < 1 */
+		const float baseWeight = 0.5f;
+		/* Since we calculate utilization on GC points, and intervals between GCs are not of constant duration, we will adjust the weight
+		 * so it's larger than the base weight if the current internal is larger then the average interval duration (and vice versa for shorter current intervals)
+		 * Still, make sure the adjusted weight remains within (0, 1) range.
+		 */
+		float utilWeight = 1.0f - powf(1.0f - baseWeight, elapsedTime / _avgInterval);
+		_avgInterval = MM_Math::weightedAverage(_avgInterval, (float)elapsedTime, 1.0f - baseWeight);
+
+		_avgCpuUtil = MM_Math::weightedAverage(_avgCpuUtil, cpuTimeDiff / (float)elapsedTime, 1.0f - utilWeight);
+		_avgProcUtil = MM_Math::weightedAverage(_avgProcUtil, processTimeDiff / (float)elapsedTime, 1.0f - utilWeight);
+
+		/* Expose CPU stats data to the higher level stats struct (but with Collector specific instance), so it can be accessible via hooks */
+		stats->_cpuUtilStats = *this;
+	}
+}

gc/stats/CPUUtilStats.hpp

@@ -0,0 +1,82 @@
+/*******************************************************************************
+ * Copyright IBM Corp. and others 2024
+ *
+ * This program and the accompanying materials are made available under
+ * the terms of the Eclipse Public License 2.0 which accompanies this
+ * distribution and is available at https://www.eclipse.org/legal/epl-2.0/
+ * or the Apache License, Version 2.0 which accompanies this distribution and
+ * is available at https://www.apache.org/licenses/LICENSE-2.0.
+ *
+ * This Source Code may also be made available under the following
+ * Secondary Licenses when the conditions for such availability set
+ * forth in the Eclipse Public License, v. 2.0 are satisfied: GNU
+ * General Public License, version 2 with the GNU Classpath
+ * Exception [1] and GNU General Public License, version 2 with the
+ * OpenJDK Assembly Exception [2].
+ *
+ * [1] https://www.gnu.org/software/classpath/license.html
+ * [2] https://openjdk.org/legal/assembly-exception.html
+ *
+ * SPDX-License-Identifier: EPL-2.0 OR Apache-2.0 OR GPL-2.0-only WITH Classpath-exception-2.0 OR GPL-2.0-only WITH OpenJDK-assembly-exception-1.0
+ *******************************************************************************/
+
+/**
+ * @file
+ * @ingroup GC_Stats
+ */
+
+#if !defined(CPUUTILSTATS_HPP_)
+#define CPUUTILSTATS_HPP_
+
+#include <stdint.h>
+
+#include "Base.hpp"
+
+class  MM_CollectionStatistics;
+class  MM_EnvironmentBase;
+
+
+/**
+ * CPU and process utilization between GC STW points (excluding GC STW points)
+ * Measured between end of STW GC and next start STW GC.
+ * Process util is mostly application thread activity but also various VM (GC, JIT,...) background threads.
+ */
+class MM_CPUUtilStats : public MM_Base {
+public:
+	int64_t _processUserTime; /**< process user time snapshot at the start of measurement, at GC start */
+	int64_t _processSystemTime; /**< process system time snapshot at the start of measurement, at GC start */
+	int64_t _cpuTime; /**< cpu time snapshot at the start of measurement, at GC start */
+	uint64_t _elapsedTime; /*< wall clock TS at the start of measurement, at GC start */
+	float _avgProcUtil; /**< historically averaged values of process (user + system) times */
+	float _avgCpuUtil; /**< historically averaged values of cpu time */
+	float _avgInterval; /**< historically averaged values of intervals between GCs */
+	bool _validData; /**< true, if both start and end points have valid data (no system calls failed) */
+
+	MM_CPUUtilStats() :
+		MM_Base()
+		,_processUserTime(0)
+		,_processSystemTime(0)
+		,_cpuTime(0)
+		,_elapsedTime(0)
+		,_avgProcUtil(0.0)
+		,_avgCpuUtil(0.0)
+		,_avgInterval(0.0)
+		,_validData(false)
+	{}
+
+	/**
+	 * Called at STW GC end point to record starting values of CPU and process consumed times
+	 * @param env calling GC thread env
+	 * @param stats higher level, Collector specific stats struct
+	 */
+	void recordProcessAndCpuUtilization(MM_EnvironmentBase *env, MM_CollectionStatistics *stats);
+	/**
+	 * Called at STW GC start point to record end values of CPU and process consumed times,
+	 * and than calculated the deltas (and their averages) since the previous 'record' call
+	 * @param env calling GC thread env
+	 * @param stats higher level, Collector specific stats struct
+	 */
+	void calculateProcessAndCpuUtilizationDelta(MM_EnvironmentBase *env, MM_CollectionStatistics *stats);
+};
+
+#endif /* CPUUTILSTATS_HPP_ */