diff --git a/AutomatedTesting/Gem/PythonTests/atom_renderer/atom_hydra_scripts/hydra_GPUTest_AtomFeatureIntegrationBenchmark.py b/AutomatedTesting/Gem/PythonTests/atom_renderer/atom_hydra_scripts/hydra_GPUTest_AtomFeatureIntegrationBenchmark.py index b899d7dcde..3aa9fe660c 100644 --- a/AutomatedTesting/Gem/PythonTests/atom_renderer/atom_hydra_scripts/hydra_GPUTest_AtomFeatureIntegrationBenchmark.py +++ b/AutomatedTesting/Gem/PythonTests/atom_renderer/atom_hydra_scripts/hydra_GPUTest_AtomFeatureIntegrationBenchmark.py @@ -93,6 +93,7 @@ def run(): general.idle_wait_frames(100) for i in range(1, 101): benchmarker.capture_pass_timestamp(i) + benchmarker.capture_cpu_frame_time(i) general.exit_game_mode() helper.wait_for_condition(function=lambda: not general.is_in_game_mode(), timeout_in_seconds=2.0) general.log("Capturing complete.") diff --git a/AutomatedTesting/Gem/PythonTests/atom_renderer/atom_utils/benchmark_utils.py b/AutomatedTesting/Gem/PythonTests/atom_renderer/atom_utils/benchmark_utils.py index 21c7489ed3..b4fdfcb8a0 100644 --- a/AutomatedTesting/Gem/PythonTests/atom_renderer/atom_utils/benchmark_utils.py +++ b/AutomatedTesting/Gem/PythonTests/atom_renderer/atom_utils/benchmark_utils.py @@ -61,6 +61,25 @@ class BenchmarkHelper(object): general.log('Failed to capture pass timestamps.') return self.capturedData + def capture_cpu_frame_time(self, frame_number): + """ + Capture CPU frame times and block further execution until it has been written to the disk. + """ + self.handler = azlmbr.atom.ProfilingCaptureNotificationBusHandler() + self.handler.connect() + self.handler.add_callback('OnCaptureCpuFrameTimeFinished', self.on_data_captured) + + self.done = False + self.capturedData = False + success = azlmbr.atom.ProfilingCaptureRequestBus( + azlmbr.bus.Broadcast, "CaptureCpuFrameTime", f'{self.output_path}/cpu_frame{frame_number}_time.json') + if success: + self.wait_until_data() + general.log('CPU frame time captured.') + else: + general.log('Failed to capture CPU frame time.') + return self.capturedData + def on_data_captured(self, parameters): # the parameters come in as a tuple if parameters[0]: diff --git a/AutomatedTesting/Gem/PythonTests/atom_renderer/test_Atom_GPUTests.py b/AutomatedTesting/Gem/PythonTests/atom_renderer/test_Atom_GPUTests.py index ede140c075..9165bced90 100644 --- a/AutomatedTesting/Gem/PythonTests/atom_renderer/test_Atom_GPUTests.py +++ b/AutomatedTesting/Gem/PythonTests/atom_renderer/test_Atom_GPUTests.py @@ -99,6 +99,7 @@ class TestPerformanceBenchmarkSuite(object): expected_lines = [ "Benchmark metadata captured.", "Pass timestamps captured.", + "CPU frame time captured.", "Capturing complete.", "Captured data successfully." ] @@ -106,6 +107,7 @@ class TestPerformanceBenchmarkSuite(object): unexpected_lines = [ "Failed to capture data.", "Failed to capture pass timestamps.", + "Failed to capture CPU frame time.", "Failed to capture benchmark metadata." ] diff --git a/Gems/Atom/Feature/Common/Code/Include/Atom/Feature/Utils/ProfilingCaptureBus.h b/Gems/Atom/Feature/Common/Code/Include/Atom/Feature/Utils/ProfilingCaptureBus.h index 15f15705c8..03f522ba44 100644 --- a/Gems/Atom/Feature/Common/Code/Include/Atom/Feature/Utils/ProfilingCaptureBus.h +++ b/Gems/Atom/Feature/Common/Code/Include/Atom/Feature/Utils/ProfilingCaptureBus.h @@ -22,6 +22,9 @@ namespace AZ //! Dump the Timestamp from passes to a json file. virtual bool CapturePassTimestamp(const AZStd::string& outputFilePath) = 0; + //! Dump the Cpu frame time statistics to a json file. + virtual bool CaptureCpuFrameTime(const AZStd::string& outputFilePath) = 0; + //! Dump the PipelineStatistics from passes to a json file. virtual bool CapturePassPipelineStatistics(const AZStd::string& outputFilePath) = 0; @@ -44,6 +47,11 @@ namespace AZ //! @param info The output file path or error information which depends on the return. virtual void OnCaptureQueryTimestampFinished(bool result, const AZStd::string& info) = 0; + //! Notify when the current CpuFrameTimeStatistics capture is finished + //! @param result Set to true if it's finished successfully + //! @param info The output file path or error information which depends on the return. + virtual void OnCaptureCpuFrameTimeFinished(bool result, const AZStd::string& info) = 0; + //! Notify when the current PipelineStatistics query capture is finished //! @param result Set to true if it's finished successfully //! @param info The output file path or error information which depends on the return. diff --git a/Gems/Atom/Feature/Common/Code/Source/ProfilingCaptureSystemComponent.cpp b/Gems/Atom/Feature/Common/Code/Source/ProfilingCaptureSystemComponent.cpp index 0c4c4d9689..1e2d549e7a 100644 --- a/Gems/Atom/Feature/Common/Code/Source/ProfilingCaptureSystemComponent.cpp +++ b/Gems/Atom/Feature/Common/Code/Source/ProfilingCaptureSystemComponent.cpp @@ -10,6 +10,9 @@ #include #include +#include +#include +#include #include #include @@ -34,6 +37,7 @@ namespace AZ public: AZ_EBUS_BEHAVIOR_BINDER(ProfilingCaptureNotificationBusHandler, "{E45E4F37-EC1F-4010-994B-4F80998BEF15}", AZ::SystemAllocator, OnCaptureQueryTimestampFinished, + OnCaptureCpuFrameTimeFinished, OnCaptureQueryPipelineStatisticsFinished, OnCaptureCpuProfilingStatisticsFinished, OnCaptureBenchmarkMetadataFinished @@ -44,6 +48,11 @@ namespace AZ Call(FN_OnCaptureQueryTimestampFinished, result, info); } + void OnCaptureCpuFrameTimeFinished(bool result, const AZStd::string& info) override + { + Call(FN_OnCaptureCpuFrameTimeFinished, result, info); + } + void OnCaptureQueryPipelineStatisticsFinished(bool result, const AZStd::string& info) override { Call(FN_OnCaptureQueryPipelineStatisticsFinished, result, info); @@ -95,6 +104,19 @@ namespace AZ AZStd::vector m_timestampEntries; }; + // Intermediate class to serialize CPU frame time statistics. + class CpuFrameTimeSerializer + { + public: + AZ_TYPE_INFO(Render::CpuFrameTimeSerializer, "{584B415E-8769-4757-AC64-EA57EDBCBC3E}"); + static void Reflect(AZ::ReflectContext* context); + + CpuFrameTimeSerializer() = default; + CpuFrameTimeSerializer(double frameTime); + + double m_frameTime; + }; + // Intermediate class to serialize pass' PipelineStatistics data. class PipelineStatisticsSerializer { @@ -248,6 +270,24 @@ namespace AZ } } + // --- CpuFrameTimeSerializer --- + + CpuFrameTimeSerializer::CpuFrameTimeSerializer(double frameTime) + { + m_frameTime = frameTime; + } + + void CpuFrameTimeSerializer::Reflect(AZ::ReflectContext* context) + { + if (auto* serializeContext = azrtti_cast(context)) + { + serializeContext->Class() + ->Version(1) + ->Field("frameTime", &CpuFrameTimeSerializer::m_frameTime) + ; + } + } + // --- PipelineStatisticsSerializer --- PipelineStatisticsSerializer::PipelineStatisticsSerializer(AZStd::vector&& passes) @@ -408,6 +448,7 @@ namespace AZ ->Attribute(AZ::Script::Attributes::Scope, AZ::Script::Attributes::ScopeFlags::Automation) ->Attribute(AZ::Script::Attributes::Module, "atom") ->Event("CapturePassTimestamp", &ProfilingCaptureRequestBus::Events::CapturePassTimestamp) + ->Event("CaptureCpuFrameTime", &ProfilingCaptureRequestBus::Events::CaptureCpuFrameTime) ->Event("CapturePassPipelineStatistics", &ProfilingCaptureRequestBus::Events::CapturePassPipelineStatistics) ->Event("CaptureCpuProfilingStatistics", &ProfilingCaptureRequestBus::Events::CaptureCpuProfilingStatistics) ->Event("CaptureBenchmarkMetadata", &ProfilingCaptureRequestBus::Events::CaptureBenchmarkMetadata) @@ -417,6 +458,7 @@ namespace AZ } TimestampSerializer::Reflect(context); + CpuFrameTimeSerializer::Reflect(context); PipelineStatisticsSerializer::Reflect(context); CpuProfilingStatisticsSerializer::Reflect(context); BenchmarkMetadataSerializer::Reflect(context); @@ -484,6 +526,71 @@ namespace AZ return captureStarted; } + bool ProfilingCaptureSystemComponent::CaptureCpuFrameTime(const AZStd::string& outputFilePath) + { + AZ::RHI::RHISystemInterface::Get()->ModifyFrameSchedulerStatisticsFlags( + AZ::RHI::FrameSchedulerStatisticsFlags::GatherCpuTimingStatistics, true + ); + bool wasEnabled = RHI::CpuProfiler::Get()->IsProfilerEnabled(); + if (!wasEnabled) + { + RHI::CpuProfiler::Get()->SetProfilerEnabled(true); + } + + const bool captureStarted = m_cpuFrameTimeStatisticsCapture.StartCapture([this, outputFilePath, wasEnabled]() + { + JsonSerializerSettings serializationSettings; + serializationSettings.m_keepDefaults = true; + + double frameTime = 0.0; + const AZ::RHI::CpuTimingStatistics* stats = AZ::RHI::RHISystemInterface::Get()->GetCpuTimingStatistics(); + if (stats) + { + frameTime = stats->GetFrameToFrameTimeMilliseconds(); + } + else + { + AZStd::string warning = AZStd::string::format("Failed to get Cpu frame time"); + AZ_Warning("ProfilingCaptureSystemComponent", false, warning.c_str()); + } + + CpuFrameTimeSerializer serializer(frameTime); + const auto saveResult = JsonSerializationUtils::SaveObjectToFile(&serializer, + outputFilePath, (CpuFrameTimeSerializer*)nullptr, &serializationSettings); + + AZStd::string captureInfo = outputFilePath; + if (!saveResult.IsSuccess()) + { + captureInfo = AZStd::string::format("Failed to save Cpu frame time to file '%s'. Error: %s", + outputFilePath.c_str(), + saveResult.GetError().c_str()); + AZ_Warning("ProfilingCaptureSystemComponent", false, captureInfo.c_str()); + } + + // Disable the profiler again + if (!wasEnabled) + { + RHI::CpuProfiler::Get()->SetProfilerEnabled(false); + } + AZ::RHI::RHISystemInterface::Get()->ModifyFrameSchedulerStatisticsFlags( + AZ::RHI::FrameSchedulerStatisticsFlags::GatherCpuTimingStatistics, false + ); + + // Notify listeners that the Cpu frame time statistics capture has finished. + ProfilingCaptureNotificationBus::Broadcast(&ProfilingCaptureNotificationBus::Events::OnCaptureCpuFrameTimeFinished, + saveResult.IsSuccess(), + captureInfo); + }); + + // Start the TickBus. + if (captureStarted) + { + TickBus::Handler::BusConnect(); + } + + return captureStarted; + } + bool ProfilingCaptureSystemComponent::CapturePassPipelineStatistics(const AZStd::string& outputFilePath) { // Find the root pass. @@ -666,12 +773,13 @@ namespace AZ { // Update the delayed captures m_timestampCapture.UpdateCapture(); + m_cpuFrameTimeStatisticsCapture.UpdateCapture(); m_pipelineStatisticsCapture.UpdateCapture(); m_cpuProfilingStatisticsCapture.UpdateCapture(); m_benchmarkMetadataCapture.UpdateCapture(); // Disconnect from the TickBus if all capture states are set to idle. - if (m_timestampCapture.IsIdle() && m_pipelineStatisticsCapture.IsIdle() && m_cpuProfilingStatisticsCapture.IsIdle() && m_benchmarkMetadataCapture.IsIdle()) + if (m_timestampCapture.IsIdle() && m_pipelineStatisticsCapture.IsIdle() && m_cpuProfilingStatisticsCapture.IsIdle() && m_benchmarkMetadataCapture.IsIdle() && m_cpuFrameTimeStatisticsCapture.IsIdle()) { TickBus::Handler::BusDisconnect(); } diff --git a/Gems/Atom/Feature/Common/Code/Source/ProfilingCaptureSystemComponent.h b/Gems/Atom/Feature/Common/Code/Source/ProfilingCaptureSystemComponent.h index 6703076c6e..c401d27f30 100644 --- a/Gems/Atom/Feature/Common/Code/Source/ProfilingCaptureSystemComponent.h +++ b/Gems/Atom/Feature/Common/Code/Source/ProfilingCaptureSystemComponent.h @@ -68,6 +68,7 @@ namespace AZ // ProfilingCaptureRequestBus overrides... bool CapturePassTimestamp(const AZStd::string& outputFilePath) override; + bool CaptureCpuFrameTime(const AZStd::string& outputFilePath) override; bool CapturePassPipelineStatistics(const AZStd::string& outputFilePath) override; bool CaptureCpuProfilingStatistics(const AZStd::string& outputFilePath) override; bool CaptureBenchmarkMetadata(const AZStd::string& benchmarkName, const AZStd::string& outputFilePath) override; @@ -81,6 +82,7 @@ namespace AZ AZStd::vector FindPasses(AZStd::vector&& passHierarchy) const; DelayedQueryCaptureHelper m_timestampCapture; + DelayedQueryCaptureHelper m_cpuFrameTimeStatisticsCapture; DelayedQueryCaptureHelper m_pipelineStatisticsCapture; DelayedQueryCaptureHelper m_cpuProfilingStatisticsCapture; DelayedQueryCaptureHelper m_benchmarkMetadataCapture; diff --git a/Tools/LyTestTools/ly_test_tools/benchmark/data_aggregator.py b/Tools/LyTestTools/ly_test_tools/benchmark/data_aggregator.py index 12681450de..0ac8c12f9b 100644 --- a/Tools/LyTestTools/ly_test_tools/benchmark/data_aggregator.py +++ b/Tools/LyTestTools/ly_test_tools/benchmark/data_aggregator.py @@ -18,31 +18,77 @@ class BenchmarkPathException(Exception): """Custom Exception class for invalid benchmark file paths.""" pass +class RunningStatistics(object): + def __init__(self): + ''' + Initializes a helper class for calculating running statstics. + ''' + self.count = 0 + self.total = 0 + self.max = 0 + self.min = float('inf') + + def update(self, value): + ''' + Updates the statistics with a new value. + + :param value: The new value to update the statistics with. + ''' + self.total += value + self.count += 1 + self.max = max(value, self.max) + self.min = min(value, self.min) + + def getAvg(self): + ''' + Returns the average of the running values. + ''' + return self.total / self.count + + def getMax(self): + ''' + Returns the maximum of the running values. + ''' + return self.max + + def getMin(self): + ''' + Returns the minimum of the running values. + ''' + return self.min + + def getCount(self): + return self.count + class BenchmarkDataAggregator(object): def __init__(self, workspace, logger, test_suite): + ''' + Initializes an aggregator for benchmark data. + + :param workspace: Workspace of the test suite the benchmark was run in + :param logger: Logger used by the test suite the benchmark was run in + :param test_suite: Name of the test suite the benchmark was run in + ''' self.build_dir = workspace.paths.build_directory() self.results_dir = Path(workspace.paths.project(), 'user/Scripts/PerformanceBenchmarks') self.test_suite = test_suite if os.environ.get('BUILD_NUMBER') else 'local' self.filebeat_client = FilebeatClient(logger) - def _update_pass(self, pass_stats, entry): + def _update_pass(self, gpu_pass_stats, entry): ''' - Modifies pass_stats dict keyed by pass name with the time recorded in a pass timestamp entry. + Modifies gpu_pass_stats dict keyed by pass name with the time recorded in a pass timestamp entry. - :param pass_stats: dict aggregating statistics from each pass (key: pass name, value: dict with stats) + :param gpu_pass_stats: dict aggregating statistics from each pass (key: pass name, value: dict with stats) :param entry: dict representing the timestamp entry of a pass :return: Time (in nanoseconds) recorded by this pass ''' name = entry['passName'] time_ns = entry['timestampResultInNanoseconds'] - pass_entry = pass_stats.get(name, { 'totalTime': 0, 'maxTime': 0 }) - - pass_entry['maxTime'] = max(time_ns, pass_entry['maxTime']) - pass_entry['totalTime'] += time_ns - pass_stats[name] = pass_entry + pass_entry = gpu_pass_stats.get(name, RunningStatistics()) + pass_entry.update(time_ns) + gpu_pass_stats[name] = pass_entry return time_ns - def _process_benchmark(self, benchmark_dir, benchmark_metadata): ''' Aggregates data from results from a single benchmark contained in a subdirectory of self.results_dir. @@ -50,8 +96,8 @@ class BenchmarkDataAggregator(object): :param benchmark_dir: Path of directory containing the benchmark results :param benchmark_metadata: Dict with benchmark metadata mutated with additional info from metadata file :return: Tuple with two indexes: - [0]: Dict aggregating statistics from frame times (key: stat name) - [1]: Dict aggregating statistics from pass times (key: pass name, value: dict with stats) + [0]: RunningStatistics for GPU frame times + [1]: Dict aggregating statistics from GPU pass times (key: pass name, value: RunningStatistics) ''' # Parse benchmark metadata metadata_file = benchmark_dir / 'benchmark_metadata.json' @@ -62,39 +108,47 @@ class BenchmarkDataAggregator(object): raise BenchmarkPathException(f'Metadata file could not be found at {metadata_file}') # data structures aggregating statistics from timestamp logs - frame_stats = { 'count': 0, 'totalTime': 0, 'maxTime': 0, 'minTime': float('inf') } - pass_stats = {} # key: pass name, value: dict with totalTime and maxTime keys + gpu_frame_stats = RunningStatistics() + cpu_frame_stats = RunningStatistics() + gpu_pass_stats = {} # key: pass name, value: RunningStatistics # this allows us to add additional data if necessary, e.g. frame_test_timestamps.json is_timestamp_file = lambda file: file.name.startswith('frame') and file.name.endswith('_timestamps.json') + is_frame_time_file = lambda file: file.name.startswith('cpu_frame') and file.name.endswith('_time.json') # parse benchmark files for file in benchmark_dir.iterdir(): - if file.is_dir() or not is_timestamp_file(file): + if file.is_dir(): continue - data = json.loads(file.read_text()) - entries = data['ClassData']['timestampEntries'] + if is_timestamp_file(file): + data = json.loads(file.read_text()) + entries = data['ClassData']['timestampEntries'] + + frame_time = sum(self._update_pass(gpu_pass_stats, entry) for entry in entries) + gpu_frame_stats.update(frame_time) - frame_time = sum(self._update_pass(pass_stats, entry) for entry in entries) + if is_frame_time_file(file): + data = json.loads(file.read_text()) + frame_time = data['ClassData']['frameTime'] + cpu_frame_stats.update(frame_time) - frame_stats['totalTime'] += frame_time - frame_stats['maxTime'] = max(frame_time, frame_stats['maxTime']) - frame_stats['minTime'] = min(frame_time, frame_stats['minTime']) - frame_stats['count'] += 1 + if gpu_frame_stats.getCount() < 1: + raise BenchmarkPathException(f'No GPU frame timestamp logs were found in {benchmark_dir}') - if frame_stats['count'] < 1: - raise BenchmarkPathException(f'No frame timestamp logs were found in {benchmark_dir}') + if cpu_frame_stats.getCount() < 1: + raise BenchmarkPathException(f'No CPU frame times were found in {benchmark_dir}') - return frame_stats, pass_stats + return gpu_frame_stats, gpu_pass_stats, cpu_frame_stats - def _generate_payloads(self, benchmark_metadata, frame_stats, pass_stats): + def _generate_payloads(self, benchmark_metadata, gpu_frame_stats, gpu_pass_stats, cpu_frame_stats): ''' Generates payloads to send to Filebeat based on aggregated stats and metadata. :param benchmark_metadata: Dict of benchmark metadata - :param frame_stats: Dict of aggregated frame statistics - :param pass_stats: Dict of aggregated pass statistics + :param gpu_frame_stats: RunningStatistics for GPU frame data + :param gpu_pass_stats: Dict of aggregated pass RunningStatistics + :param cpu_frame_stats: RunningStatistics for CPU frame data :return payloads: List of tuples, each with two indexes: [0]: Elasticsearch index suffix associated with the payload [1]: Payload dict to deliver to Filebeat @@ -103,33 +157,38 @@ class BenchmarkDataAggregator(object): payloads = [] # calculate statistics based on aggregated frame data - frame_time_avg = frame_stats['totalTime'] / frame_stats['count'] - frame_payload = { + gpu_frame_payload = { + 'frameTime': { + 'avg': ns_to_ms(gpu_frame_stats.getAvg()), + 'max': ns_to_ms(gpu_frame_stats.getMax()), + 'min': ns_to_ms(gpu_frame_stats.getMin()) + } + } + cpu_frame_payload = { 'frameTime': { - 'avg': ns_to_ms(frame_time_avg), - 'max': ns_to_ms(frame_stats['maxTime']), - 'min': ns_to_ms(frame_stats['minTime']) + 'avg': cpu_frame_stats.getAvg(), + 'max': cpu_frame_stats.getMax(), + 'min': cpu_frame_stats.getMin() } } # add benchmark metadata to payload - frame_payload.update(benchmark_metadata) - payloads.append(('frame_data', frame_payload)) + gpu_frame_payload.update(benchmark_metadata) + payloads.append(('gpu.frame_data', gpu_frame_payload)) + cpu_frame_payload.update(benchmark_metadata) + payloads.append(('cpu.frame_data', cpu_frame_payload)) # calculate statistics for each pass - for name, stat in pass_stats.items(): - avg_ms = ns_to_ms(stat['totalTime'] / frame_stats['count']) - max_ms = ns_to_ms(stat['maxTime']) - - pass_payload = { + for name, stat in gpu_pass_stats.items(): + gpu_pass_payload = { 'passName': name, 'passTime': { - 'avg': avg_ms, - 'max': max_ms + 'avg': ns_to_ms(stat.getAvg()), + 'max': ns_to_ms(stat.getMax()) } } # add benchmark metadata to payload - pass_payload.update(benchmark_metadata) - payloads.append(('pass_data', pass_payload)) + gpu_pass_payload.update(benchmark_metadata) + payloads.append(('gpu.pass_data', gpu_pass_payload)) return payloads @@ -153,8 +212,8 @@ class BenchmarkDataAggregator(object): 'gitCommitAndBuildDate': f'{git_commit_hash} {build_date}', 'RHI': rhi } - frame_stats, pass_stats = self._process_benchmark(benchmark_dir, benchmark_metadata) - payloads = self._generate_payloads(benchmark_metadata, frame_stats, pass_stats) + gpu_frame_stats, gpu_pass_stats, cpu_frame_stats = self._process_benchmark(benchmark_dir, benchmark_metadata) + payloads = self._generate_payloads(benchmark_metadata, gpu_frame_stats, gpu_pass_stats, cpu_frame_stats) for index_suffix, payload in payloads: self.filebeat_client.send_event(