Added more refined benchmarking code for audioproc_f

This CL extends, and partly corrects, the benchmarking
code in audioproc_f to provide statistics for the API
call durations in audioproc_f

Bug: chromium:939791
Change-Id: I4c26c4bb3782335f13dd3e21e6f861842539ea62
Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/129260
Commit-Queue: Per Åhgren <peah@webrtc.org>
Reviewed-by: Sam Zackrisson <saza@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#27443}

modules/audio_processing/BUILD.gn

@@ -608,6 +608,8 @@ if (rtc_include_tests) {
       sources = [
         "test/aec_dump_based_simulator.cc",
         "test/aec_dump_based_simulator.h",
+        "test/api_call_statistics.cc",
+        "test/api_call_statistics.h",
         "test/audio_processing_simulator.cc",
         "test/audio_processing_simulator.h",
         "test/audioproc_float_impl.cc",

modules/audio_processing/test/api_call_statistics.cc

@@ -0,0 +1,94 @@
+/*
+ *  Copyright (c) 2019 The WebRTC project authors. All Rights Reserved.
+ *
+ *  Use of this source code is governed by a BSD-style license
+ *  that can be found in the LICENSE file in the root of the source
+ *  tree. An additional intellectual property rights grant can be found
+ *  in the file PATENTS.  All contributing project authors may
+ *  be found in the AUTHORS file in the root of the source tree.
+ */
+
+#include "modules/audio_processing/test/api_call_statistics.h"
+
+#include <algorithm>
+#include <fstream>
+#include <iostream>
+#include <limits>
+#include <memory>
+
+#include "absl/memory/memory.h"
+#include "rtc_base/time_utils.h"
+
+namespace webrtc {
+namespace test {
+
+void ApiCallStatistics::Add(int64_t duration_nanos, CallType call_type) {
+  calls_.push_back(CallData(duration_nanos, call_type));
+}
+
+void ApiCallStatistics::PrintReport() const {
+  int64_t min_render = std::numeric_limits<int64_t>::max();
+  int64_t min_capture = std::numeric_limits<int64_t>::max();
+  int64_t max_render = 0;
+  int64_t max_capture = 0;
+  int64_t sum_render = 0;
+  int64_t sum_capture = 0;
+  int64_t num_render = 0;
+  int64_t num_capture = 0;
+  int64_t avg_render = 0;
+  int64_t avg_capture = 0;
+
+  for (auto v : calls_) {
+    if (v.call_type == CallType::kRender) {
+      ++num_render;
+      min_render = std::min(min_render, v.duration_nanos);
+      max_render = std::max(max_render, v.duration_nanos);
+      sum_render += v.duration_nanos;
+    } else {
+      ++num_capture;
+      min_capture = std::min(min_capture, v.duration_nanos);
+      max_capture = std::max(max_capture, v.duration_nanos);
+      sum_capture += v.duration_nanos;
+    }
+  }
+  min_render /= rtc::kNumNanosecsPerMicrosec;
+  max_render /= rtc::kNumNanosecsPerMicrosec;
+  sum_render /= rtc::kNumNanosecsPerMicrosec;
+  min_capture /= rtc::kNumNanosecsPerMicrosec;
+  max_capture /= rtc::kNumNanosecsPerMicrosec;
+  sum_capture /= rtc::kNumNanosecsPerMicrosec;
+  avg_render = num_render > 0 ? sum_render / num_render : 0;
+  avg_capture = num_capture > 0 ? sum_capture / num_capture : 0;
+
+  std::cout << std::endl
+            << "Total time: " << (sum_capture + sum_render) * 1e-6 << " s"
+            << std::endl
+            << " Render API calls:" << std::endl
+            << "   min: " << min_render << " us" << std::endl
+            << "   max: " << max_render << " us" << std::endl
+            << "   avg: " << avg_render << " us" << std::endl
+            << " Capture API calls:" << std::endl
+            << "   min: " << min_capture << " us" << std::endl
+            << "   max: " << max_capture << " us" << std::endl
+            << "   avg: " << avg_capture << " us" << std::endl;
+}
+
+void ApiCallStatistics::WriteReportToFile(const std::string& filename) const {
+  std::unique_ptr<std::ofstream> out =
+      absl::make_unique<std::ofstream>(filename);
+  for (auto v : calls_) {
+    if (v.call_type == CallType::kRender) {
+      *out << "render, ";
+    } else {
+      *out << "capture, ";
+    }
+    *out << (v.duration_nanos / rtc::kNumNanosecsPerMicrosec) << std::endl;
+  }
+}
+
+ApiCallStatistics::CallData::CallData(int64_t duration_nanos,
+                                      CallType call_type)
+    : duration_nanos(duration_nanos), call_type(call_type) {}
+
+}  // namespace test
+}  // namespace webrtc

modules/audio_processing/test/api_call_statistics.h

@@ -0,0 +1,46 @@
+/*
+ *  Copyright (c) 2019 The WebRTC project authors. All Rights Reserved.
+ *
+ *  Use of this source code is governed by a BSD-style license
+ *  that can be found in the LICENSE file in the root of the source
+ *  tree. An additional intellectual property rights grant can be found
+ *  in the file PATENTS.  All contributing project authors may
+ *  be found in the AUTHORS file in the root of the source tree.
+ */
+
+#ifndef MODULES_AUDIO_PROCESSING_TEST_API_CALL_STATISTICS_H_
+#define MODULES_AUDIO_PROCESSING_TEST_API_CALL_STATISTICS_H_
+
+#include <string>
+#include <vector>
+
+namespace webrtc {
+namespace test {
+
+// Collects statistics about the API call durations.
+class ApiCallStatistics {
+ public:
+  enum class CallType { kRender, kCapture };
+
+  // Adds a new datapoint.
+  void Add(int64_t duration_nanos, CallType call_type);
+
+  // Prints out a report of the statistics.
+  void PrintReport() const;
+
+  // Writes the call information to a file.
+  void WriteReportToFile(const std::string& filename) const;
+
+ private:
+  struct CallData {
+    CallData(int64_t duration_nanos, CallType call_type);
+    int64_t duration_nanos;
+    CallType call_type;
+  };
+  std::vector<CallData> calls_;
+};
+
+}  // namespace test
+}  // namespace webrtc
+
+#endif  // MODULES_AUDIO_PROCESSING_TEST_API_CALL_STATISTICS_H_

modules/audio_processing/test/audio_processing_simulator.cc

@@ -95,6 +95,27 @@ void WriteEchoLikelihoodGraphFileFooter(std::ofstream* output_file) {
                  << "  plt.show()" << std::endl;
 }
 
+// RAII class for execution time measurement. Updates the provided
+// ApiCallStatistics based on the time between ScopedTimer creation and
+// leaving the enclosing scope.
+class ScopedTimer {
+ public:
+  ScopedTimer(ApiCallStatistics* api_call_statistics_,
+              ApiCallStatistics::CallType call_type)
+      : start_time_(rtc::TimeNanos()),
+        call_type_(call_type),
+        api_call_statistics_(api_call_statistics_) {}
+
+  ~ScopedTimer() {
+    api_call_statistics_->Add(rtc::TimeNanos() - start_time_, call_type_);
+  }
+
+ private:
+  const int64_t start_time_;
+  const ApiCallStatistics::CallType call_type_;
+  ApiCallStatistics* const api_call_statistics_;
+};
+
 }  // namespace
 
 SimulationSettings::SimulationSettings() = default;
@@ -150,13 +171,6 @@ AudioProcessingSimulator::~AudioProcessingSimulator() {
   }
 }
 
-AudioProcessingSimulator::ScopedTimer::~ScopedTimer() {
-  int64_t interval = rtc::TimeNanos() - start_time_;
-  proc_time_->sum += interval;
-  proc_time_->max = std::max(proc_time_->max, interval);
-  proc_time_->min = std::min(proc_time_->min, interval);
-}
-
 void AudioProcessingSimulator::ProcessStream(bool fixed_interface) {
   // Optionally use the fake recording device to simulate analog gain.
   if (settings_.simulate_mic_gain) {
@@ -188,12 +202,14 @@ void AudioProcessingSimulator::ProcessStream(bool fixed_interface) {
   // Process the current audio frame.
   if (fixed_interface) {
     {
-      const auto st = ScopedTimer(mutable_proc_time());
+      const auto st = ScopedTimer(&api_call_statistics_,
+                                  ApiCallStatistics::CallType::kCapture);
       RTC_CHECK_EQ(AudioProcessing::kNoError, ap_->ProcessStream(&fwd_frame_));
     }
     CopyFromAudioFrame(fwd_frame_, out_buf_.get());
   } else {
-    const auto st = ScopedTimer(mutable_proc_time());
+    const auto st = ScopedTimer(&api_call_statistics_,
+                                ApiCallStatistics::CallType::kCapture);
     RTC_CHECK_EQ(AudioProcessing::kNoError,
                  ap_->ProcessStream(in_buf_->channels(), in_config_,
                                     out_config_, out_buf_->channels()));
@@ -222,13 +238,16 @@ void AudioProcessingSimulator::ProcessStream(bool fixed_interface) {
 
 void AudioProcessingSimulator::ProcessReverseStream(bool fixed_interface) {
   if (fixed_interface) {
-    const auto st = ScopedTimer(mutable_proc_time());
-    RTC_CHECK_EQ(AudioProcessing::kNoError,
-                 ap_->ProcessReverseStream(&rev_frame_));
+    {
+      const auto st = ScopedTimer(&api_call_statistics_,
+                                  ApiCallStatistics::CallType::kRender);
+      RTC_CHECK_EQ(AudioProcessing::kNoError,
+                   ap_->ProcessReverseStream(&rev_frame_));
+    }
     CopyFromAudioFrame(rev_frame_, reverse_out_buf_.get());
-
   } else {
-    const auto st = ScopedTimer(mutable_proc_time());
+    const auto st = ScopedTimer(&api_call_statistics_,
+                                ApiCallStatistics::CallType::kRender);
     RTC_CHECK_EQ(AudioProcessing::kNoError,
                  ap_->ProcessReverseStream(
                      reverse_in_buf_->channels(), reverse_in_config_,

modules/audio_processing/test/audio_processing_simulator.h

@@ -20,6 +20,7 @@
 #include "absl/types/optional.h"
 #include "common_audio/channel_buffer.h"
 #include "modules/audio_processing/include/audio_processing.h"
+#include "modules/audio_processing/test/api_call_statistics.h"
 #include "modules/audio_processing/test/fake_recording_device.h"
 #include "modules/audio_processing/test/test_utils.h"
 #include "rtc_base/constructor_magic.h"
@@ -85,6 +86,7 @@ struct SimulationSettings {
   bool simulate_mic_gain = false;
   absl::optional<int> simulated_mic_kind;
   bool report_performance = false;
+  absl::optional<std::string> performance_report_output_filename;
   bool report_bitexactness = false;
   bool use_verbose_logging = false;
   bool use_quiet_output = false;
@@ -101,14 +103,6 @@ struct SimulationSettings {
   absl::optional<std::string> aec_settings_filename;
 };
 
-// Holds a few statistics about a series of TickIntervals.
-struct TickIntervalStats {
-  TickIntervalStats() : min(std::numeric_limits<int64_t>::max()) {}
-  int64_t sum;
-  int64_t max;
-  int64_t min;
-};
-
 // Copies samples present in a ChannelBuffer into an AudioFrame.
 void CopyToAudioFrame(const ChannelBuffer<float>& src, AudioFrame* dest);
 
@@ -124,8 +118,10 @@ class AudioProcessingSimulator {
   // Processes the data in the input.
   virtual void Process() = 0;
 
-  // Returns the execution time of all AudioProcessing calls.
-  const TickIntervalStats& proc_time() const { return proc_time_; }
+  // Returns the execution times of all AudioProcessing calls.
+  const ApiCallStatistics& GetApiCallStatistics() const {
+    return api_call_statistics_;
+  }
 
   // Reports whether the processed recording was bitexact.
   bool OutputWasBitexact() { return bitexact_output_; }
@@ -136,22 +132,6 @@ class AudioProcessingSimulator {
   }
 
  protected:
-  // RAII class for execution time measurement. Updates the provided
-  // TickIntervalStats based on the time between ScopedTimer creation and
-  // leaving the enclosing scope.
-  class ScopedTimer {
-   public:
-    explicit ScopedTimer(TickIntervalStats* proc_time)
-        : proc_time_(proc_time), start_time_(rtc::TimeNanos()) {}
-
-    ~ScopedTimer();
-
-   private:
-    TickIntervalStats* const proc_time_;
-    int64_t start_time_;
-  };
-
-  TickIntervalStats* mutable_proc_time() { return &proc_time_; }
   void ProcessStream(bool fixed_interface);
   void ProcessReverseStream(bool fixed_interface);
   void CreateAudioProcessor();
@@ -194,7 +174,7 @@ class AudioProcessingSimulator {
   size_t num_reverse_process_stream_calls_ = 0;
   std::unique_ptr<ChannelBufferWavWriter> buffer_writer_;
   std::unique_ptr<ChannelBufferWavWriter> reverse_buffer_writer_;
-  TickIntervalStats proc_time_;
+  ApiCallStatistics api_call_statistics_;
   std::ofstream residual_echo_likelihood_graph_writer_;
   int analog_mic_level_;
   FakeRecordingDevice fake_recording_device_;

modules/audio_processing/test/audioproc_float_impl.cc

@@ -190,6 +190,10 @@ WEBRTC_DEFINE_int(
     kParameterNotSpecifiedValue,
     "Specify which microphone kind to use for microphone simulation");
 WEBRTC_DEFINE_bool(performance_report, false, "Report the APM performance ");
+WEBRTC_DEFINE_string(performance_report_output_file,
+                     "",
+                     "Generate a CSV file with the API call durations");
+
 WEBRTC_DEFINE_bool(verbose, false, "Produce verbose output");
 WEBRTC_DEFINE_bool(quiet,
                    false,
@@ -351,6 +355,8 @@ SimulationSettings CreateSettings() {
   settings.simulate_mic_gain = FLAG_simulate_mic_gain;
   SetSettingIfSpecified(FLAG_simulated_mic_kind, &settings.simulated_mic_kind);
   settings.report_performance = FLAG_performance_report;
+  SetSettingIfSpecified(FLAG_performance_report_output_file,
+                        &settings.performance_report_output_filename);
   settings.use_verbose_logging = FLAG_verbose;
   settings.use_quiet_output = FLAG_quiet;
   settings.report_bitexactness = FLAG_bitexactness_report;
@@ -555,18 +561,11 @@ int AudioprocFloatImpl(std::unique_ptr<AudioProcessingBuilder> ap_builder,
   processor->Process();
 
   if (settings.report_performance) {
-    const auto& proc_time = processor->proc_time();
-    int64_t exec_time_us = proc_time.sum / rtc::kNumNanosecsPerMicrosec;
-    std::cout << std::endl
-              << "Execution time: " << exec_time_us * 1e-6 << " s, File time: "
-              << processor->get_num_process_stream_calls() * 1.f /
-                     AudioProcessingSimulator::kChunksPerSecond
-              << std::endl
-              << "Time per fwd stream chunk (mean, max, min): " << std::endl
-              << exec_time_us * 1.f / processor->get_num_process_stream_calls()
-              << " us, " << 1.f * proc_time.max / rtc::kNumNanosecsPerMicrosec
-              << " us, " << 1.f * proc_time.min / rtc::kNumNanosecsPerMicrosec
-              << " us" << std::endl;
+    processor->GetApiCallStatistics().PrintReport();
+  }
+  if (settings.performance_report_output_filename) {
+    processor->GetApiCallStatistics().WriteReportToFile(
+        *settings.performance_report_output_filename);
   }
 
   if (settings.report_bitexactness && settings.aec_dump_input_filename) {