performance benchmarks: Aggregate and report CPU frame times. (#2939)

* Add CaptureCpuFrameTime method to ProfilingCaptureSystemComponent for monitoring CPU performance. Signed-off-by: Cynthia Lin <cyntlin@amazon.com> * ly_test_tools: Refactor benchmark data aggregator in preparation for CPU frame times. Signed-off-by: Cynthia Lin <cyntlin@amazon.com> * performance benchmarks: Aggregate and report CPU frame times based on JSON data. Signed-off-by: Cynthia Lin <cyntlin@amazon.com> * AutomatedTesting: Capture CPU frame time in AtomFeatureIntegrationBenchmark. Signed-off-by: Cynthia Lin <cyntlin@amazon.com>
2021-08-09 14:57:52 -07:00
parent 54b93d7c25
commit c1a0b5c686
7 changed files with 245 additions and 46 deletions
@@ -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.")
@@ -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]:
@@ -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."
        ]

@@ -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.
@@ -10,6 +10,9 @@

 #include <Atom/RHI/CpuProfiler.h>
 #include <Atom/RHI/RHIUtils.h>
+#include <Atom/RHI/RHISystemInterface.h>
+#include <Atom/RHI.Reflect/CpuTimingStatistics.h>
+#include <AzCore/Statistics/RunningStatistic.h>

 #include <Atom/RPI.Public/GpuQuery/GpuQueryTypes.h>
 #include <Atom/RPI.Public/Pass/ParentPass.h>
@@ -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<TimestampSerializerEntry> 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<AZ::SerializeContext*>(context))
+            {
+                serializeContext->Class<CpuFrameTimeSerializer>()
+                    ->Version(1)
+                    ->Field("frameTime", &CpuFrameTimeSerializer::m_frameTime)
+                    ;
+            }
+        }
+
        // --- PipelineStatisticsSerializer ---

        PipelineStatisticsSerializer::PipelineStatisticsSerializer(AZStd::vector<const RPI::Pass*>&& 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();
            }
@@ -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<AZ::RPI::Pass*> FindPasses(AZStd::vector<AZStd::string>&& passHierarchy) const;

            DelayedQueryCaptureHelper m_timestampCapture;
+            DelayedQueryCaptureHelper m_cpuFrameTimeStatisticsCapture;
            DelayedQueryCaptureHelper m_pipelineStatisticsCapture;
            DelayedQueryCaptureHelper m_cpuProfilingStatisticsCapture;
            DelayedQueryCaptureHelper m_benchmarkMetadataCapture;
@@ -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(pass_stats, entry) for entry in entries)
+                frame_time = sum(self._update_pass(gpu_pass_stats, entry) for entry in entries)
+                gpu_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 is_frame_time_file(file):
+                data = json.loads(file.read_text())
+                frame_time = data['ClassData']['frameTime']
+                cpu_frame_stats.update(frame_time)

-        if frame_stats['count'] < 1:
-            raise BenchmarkPathException(f'No frame timestamp logs were found in {benchmark_dir}')
+        if gpu_frame_stats.getCount() < 1:
+            raise BenchmarkPathException(f'No GPU frame timestamp logs were found in {benchmark_dir}')

-        return frame_stats, pass_stats
+        if cpu_frame_stats.getCount() < 1:
+            raise BenchmarkPathException(f'No CPU frame times were found in {benchmark_dir}')

-    def _generate_payloads(self, benchmark_metadata, frame_stats, pass_stats):
+        return gpu_frame_stats, gpu_pass_stats, cpu_frame_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(frame_time_avg),
-                'max': ns_to_ms(frame_stats['maxTime']),
-                'min': ns_to_ms(frame_stats['minTime'])
+                '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': 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(