Add UTC time to init event in AEC debug dump.

Bug: webrtc:9616
Change-Id: I1350212f0b8835fb64427483269da96d51670c01
Reviewed-on: https://webrtc-review.googlesource.com/92620
Reviewed-by: Mirko Bonadei <mbonadei@webrtc.org>
Reviewed-by: Minyue Li <minyue@webrtc.org>
Reviewed-by: Per Åhgren <peah@webrtc.org>
Reviewed-by: Henrik Lundin <henrik.lundin@webrtc.org>
Reviewed-by: Per Kjellander <perkj@webrtc.org>
Reviewed-by: Alex Loiko <aleloi@webrtc.org>
Commit-Queue: Minyue Li <minyue@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#24267}

modules/audio_processing/BUILD.gn

@@ -442,6 +442,7 @@ if (rtc_include_tests) {
         ":audioproc_test_utils",
         ":audioproc_unittest_proto",
         "../../api/audio:audio_frame_api",
+        "../../rtc_base:rtc_base_tests_utils",
         "../../rtc_base:rtc_task_queue",
         "aec_dump",
         "aec_dump:aec_dump_unittests",

modules/audio_processing/aec_dump/aec_dump_impl.cc

@@ -74,7 +74,8 @@ AecDumpImpl::~AecDumpImpl() {
   thread_sync_event.Wait(rtc::Event::kForever);
 }
 
-void AecDumpImpl::WriteInitMessage(const ProcessingConfig& api_format) {
+void AecDumpImpl::WriteInitMessage(const ProcessingConfig& api_format,
+                                   int64_t time_now_ms) {
   auto task = CreateWriteToFileTask();
   auto* event = task->GetEvent();
   event->set_type(audioproc::Event::INIT);
@@ -95,6 +96,7 @@ void AecDumpImpl::WriteInitMessage(const ProcessingConfig& api_format) {
       static_cast<int32_t>(api_format.reverse_input_stream().num_channels()));
   msg->set_num_reverse_output_channels(
       api_format.reverse_output_stream().num_channels());
+  msg->set_timestamp_ms(time_now_ms);
 
   worker_queue_->PostTask(std::unique_ptr<rtc::QueuedTask>(std::move(task)));
 }

modules/audio_processing/aec_dump/aec_dump_impl.h

@@ -52,8 +52,8 @@ class AecDumpImpl : public AecDump {
 
   ~AecDumpImpl() override;
 
-  void WriteInitMessage(const ProcessingConfig& api_format) override;
-
+  void WriteInitMessage(const ProcessingConfig& api_format,
+                        int64_t time_now_ms) override;
   void AddCaptureStreamInput(const AudioFrameView<const float>& src) override;
   void AddCaptureStreamOutput(const AudioFrameView<const float>& src) override;
   void AddCaptureStreamInput(const AudioFrame& frame) override;

modules/audio_processing/aec_dump/aec_dump_integration_test.cc

@@ -33,7 +33,7 @@ std::unique_ptr<webrtc::test::MockAecDump> CreateMockAecDump() {
   auto mock_aec_dump =
       absl::make_unique<testing::StrictMock<webrtc::test::MockAecDump>>();
   EXPECT_CALL(*mock_aec_dump.get(), WriteConfig(_)).Times(AtLeast(1));
-  EXPECT_CALL(*mock_aec_dump.get(), WriteInitMessage(_)).Times(AtLeast(1));
+  EXPECT_CALL(*mock_aec_dump.get(), WriteInitMessage(_, _)).Times(AtLeast(1));
   return std::unique_ptr<webrtc::test::MockAecDump>(std::move(mock_aec_dump));
 }
 

modules/audio_processing/aec_dump/aec_dump_unittest.cc

@@ -40,7 +40,8 @@ TEST(AecDumper, APICallsDoNotCrash) {
     aec_dump->WriteConfig(apm_config);
 
     webrtc::ProcessingConfig api_format;
-    aec_dump->WriteInitMessage(api_format);
+    constexpr int64_t kTimeNowMs = 123456789ll;
+    aec_dump->WriteInitMessage(api_format, kTimeNowMs);
   }
   // Remove file after the AecDump d-tor has finished.
   ASSERT_EQ(0, remove(filename.c_str()));

modules/audio_processing/aec_dump/mock_aec_dump.h

@@ -25,7 +25,8 @@ class MockAecDump : public AecDump {
   MockAecDump();
   virtual ~MockAecDump();
 
-  MOCK_METHOD1(WriteInitMessage, void(const ProcessingConfig& api_format));
+  MOCK_METHOD2(WriteInitMessage,
+               void(const ProcessingConfig& api_format, int64_t time_now_ms));
 
   MOCK_METHOD1(AddCaptureStreamInput,
                void(const AudioFrameView<const float>& src));

modules/audio_processing/audio_processing_impl.cc

@@ -34,6 +34,7 @@
 #include "rtc_base/platform_file.h"
 #include "rtc_base/refcountedobject.h"
 #include "rtc_base/system/arch.h"
+#include "rtc_base/timeutils.h"
 #include "rtc_base/trace_event.h"
 #if WEBRTC_INTELLIGIBILITY_ENHANCER
 #include "modules/audio_processing/intelligibility/intelligibility_enhancer.h"
@@ -572,7 +573,7 @@ int AudioProcessingImpl::InitializeLocked() {
   InitializePreProcessor();
 
   if (aec_dump_) {
-    aec_dump_->WriteInitMessage(formats_.api_format);
+    aec_dump_->WriteInitMessage(formats_.api_format, rtc::TimeUTCMillis());
   }
   return kNoError;
 }
@@ -1575,7 +1576,7 @@ void AudioProcessingImpl::AttachAecDump(std::unique_ptr<AecDump> aec_dump) {
   // 'aec_dump' parameter, which is after locks are released.
   aec_dump_.swap(aec_dump);
   WriteAecDumpConfigMessage(true);
-  aec_dump_->WriteInitMessage(formats_.api_format);
+  aec_dump_->WriteInitMessage(formats_.api_format, rtc::TimeUTCMillis());
 }
 
 void AudioProcessingImpl::DetachAecDump() {

modules/audio_processing/audio_processing_unittest.cc

@@ -28,6 +28,7 @@
 #include "modules/audio_processing/test/test_utils.h"
 #include "rtc_base/arraysize.h"
 #include "rtc_base/checks.h"
+#include "rtc_base/fakeclock.h"
 #include "rtc_base/gtest_prod_util.h"
 #include "rtc_base/ignore_wundef.h"
 #include "rtc_base/numerics/safe_conversions.h"
@@ -1730,6 +1731,7 @@ void ApmTest::ProcessDebugDump(const std::string& in_filename,
 }
 
 void ApmTest::VerifyDebugDumpTest(Format format) {
+  rtc::ScopedFakeClock fake_clock;
   const std::string in_filename = test::ResourcePath("ref03", "aecdump");
   std::string format_string;
   switch (format) {

modules/audio_processing/debug.proto

@@ -14,6 +14,7 @@ message Init {
   optional int32 output_sample_rate = 7;
   optional int32 reverse_output_sample_rate = 8;
   optional int32 num_reverse_output_channels = 9;
+  optional int64 timestamp_ms = 10;
 }
 
 // May contain interleaved or deinterleaved data, but don't store both formats.

modules/audio_processing/include/aec_dump.h

@@ -76,7 +76,11 @@ class AecDump {
   virtual ~AecDump() = default;
 
   // Logs Event::Type INIT message.
-  virtual void WriteInitMessage(const ProcessingConfig& api_format) = 0;
+  virtual void WriteInitMessage(const ProcessingConfig& api_format,
+                                int64_t time_now_ms) = 0;
+  RTC_DEPRECATED void WriteInitMessage(const ProcessingConfig& api_format) {
+    WriteInitMessage(api_format, 0);
+  }
 
   // Logs Event::Type STREAM message. To log an input/output pair,
   // call the AddCapture* and AddAudioProcessingState methods followed

pc/statscollector.cc

@@ -446,8 +446,7 @@ StatsCollector::~StatsCollector() {
 
 // Wallclock time in ms.
 double StatsCollector::GetTimeNow() {
-  return rtc::TimeUTCMicros() /
-         static_cast<double>(rtc::kNumMicrosecsPerMillisec);
+  return static_cast<double>(rtc::TimeUTCMillis());
 }
 
 // Adds a MediaStream with tracks that can be used as a |selector| in a call

rtc_base/timeutils.cc

@@ -201,6 +201,9 @@ int64_t TmToSeconds(const std::tm& tm) {
 }
 
 int64_t TimeUTCMicros() {
+  if (g_clock) {
+    return g_clock->TimeNanos() / kNumNanosecsPerMicrosec;
+  }
 #if defined(WEBRTC_POSIX)
   struct timeval time;
   gettimeofday(&time, nullptr);
@@ -217,4 +220,8 @@ int64_t TimeUTCMicros() {
 #endif
 }
 
+int64_t TimeUTCMillis() {
+  return TimeUTCMicros() / kNumMicrosecsPerMillisec;
+}
+
 }  // namespace rtc

rtc_base/timeutils.h

@@ -126,6 +126,10 @@ int64_t TmToSeconds(const std::tm& tm);
 // measuring time intervals and timeouts.
 int64_t TimeUTCMicros();
 
+// Return the number of milliseconds since January 1, 1970, UTC.
+// See above.
+int64_t TimeUTCMillis();
+
 // Interval of time from the range [min, max] inclusive.
 class IntervalRange {
  public:

rtc_tools/unpack_aecdump/unpack.cc

@@ -322,6 +322,11 @@ int do_main(int argc, char* argv[]) {
       num_reverse_channels = msg.num_reverse_channels();
       fprintf(settings_file, "  Reverse channels: %" PRIuS "\n",
               num_reverse_channels);
+      if (msg.has_timestamp_ms()) {
+        const int64_t timestamp = msg.timestamp_ms();
+        fprintf(settings_file, "  Timestamp in millisecond: %" PRId64 "\n",
+                timestamp);
+      }
 
       fprintf(settings_file, "\n");