Added support for keeping a buffer of the previous X seconds, to add to an AcmDump.

In addition, timestamps are now absolute instead of relative to LOG_START.

BUG=webrtc:4741
R=henrik.lundin@webrtc.org, kwiberg@webrtc.org, stefan@webrtc.org, terelius@webrtc.org

Review URL: https://codereview.webrtc.org/1209563002.

Cr-Commit-Position: refs/heads/master@{#9509}

webrtc/modules/audio_coding/main/acm2/acm_dump.cc

@@ -10,7 +10,7 @@
 
 #include "webrtc/modules/audio_coding/main/acm2/acm_dump.h"
 
-#include <sstream>
+#include <deque>
 
 #include "webrtc/base/checks.h"
 #include "webrtc/base/thread_annotations.h"
@@ -54,27 +54,35 @@ class AcmDumpImpl final : public AcmDump {
   void LogDebugEvent(DebugEvent event_type) override;
 
  private:
-  // Checks if the logging time has expired, and if so stops the logging.
-  void StopIfNecessary() EXCLUSIVE_LOCKS_REQUIRED(crit_);
-  // Stops logging and clears the stored data and buffers.
-  void Clear() EXCLUSIVE_LOCKS_REQUIRED(crit_);
-  // Returns true if the logging is currently active.
-  bool CurrentlyLogging() const EXCLUSIVE_LOCKS_REQUIRED(crit_) {
-    return active_ &&
-           (clock_->TimeInMicroseconds() <= start_time_us_ + duration_us_);
-  }
   // This function is identical to LogDebugEvent, but requires holding the lock.
   void LogDebugEventLocked(DebugEvent event_type,
                            const std::string& event_message)
       EXCLUSIVE_LOCKS_REQUIRED(crit_);
+  // Stops logging and clears the stored data and buffers.
+  void Clear() EXCLUSIVE_LOCKS_REQUIRED(crit_);
+  // Adds a new event to the logfile if logging is active, or adds it to the
+  // list of recent log events otherwise.
+  void HandleEvent(ACMDumpEvent* event) EXCLUSIVE_LOCKS_REQUIRED(crit_);
+  // Writes the event to the file. Note that this will destroy the state of the
+  // input argument.
+  void StoreToFile(ACMDumpEvent* event) EXCLUSIVE_LOCKS_REQUIRED(crit_);
+  // Adds the event to the list of recent events, and removes any events that
+  // are too old and no longer fall in the time window.
+  void AddRecentEvent(const ACMDumpEvent& event)
+      EXCLUSIVE_LOCKS_REQUIRED(crit_);
+
+  // Amount of time in microseconds to record log events, before starting the
+  // actual log.
+  const int recent_log_duration_us = 10000000;
 
   rtc::scoped_ptr<webrtc::CriticalSectionWrapper> crit_;
   rtc::scoped_ptr<webrtc::FileWrapper> file_ GUARDED_BY(crit_);
   rtc::scoped_ptr<ACMDumpEventStream> stream_ GUARDED_BY(crit_);
-  bool active_ GUARDED_BY(crit_);
+  std::deque<ACMDumpEvent> recent_log_events_ GUARDED_BY(crit_);
+  bool currently_logging_ GUARDED_BY(crit_);
   int64_t start_time_us_ GUARDED_BY(crit_);
   int64_t duration_us_ GUARDED_BY(crit_);
-  const webrtc::Clock* clock_ GUARDED_BY(crit_);
+  const webrtc::Clock* const clock_;
 };
 
 namespace {
@@ -100,7 +108,7 @@ AcmDumpImpl::AcmDumpImpl()
     : crit_(webrtc::CriticalSectionWrapper::CreateCriticalSection()),
       file_(webrtc::FileWrapper::Create()),
       stream_(new webrtc::ACMDumpEventStream()),
-      active_(false),
+      currently_logging_(false),
       start_time_us_(0),
       duration_us_(0),
       clock_(webrtc::Clock::GetRealTimeClock()) {
@@ -112,38 +120,31 @@ void AcmDumpImpl::StartLogging(const std::string& file_name, int duration_ms) {
   if (file_->OpenFile(file_name.c_str(), false) != 0) {
     return;
   }
-  // Add a single object to the stream that is reused at every log event.
+  // Add LOG_START event to the recent event list. This call will also remove
-  stream_->add_stream();
+  // any events that are too old from the recent event list.
-  active_ = true;
+  LogDebugEventLocked(DebugEvent::kLogStart, "");
+  currently_logging_ = true;
   start_time_us_ = clock_->TimeInMicroseconds();
   duration_us_ = static_cast<int64_t>(duration_ms) * 1000;
-  // Log the start event.
+  // Write all the recent events to the log file.
-  std::stringstream log_msg;
+  for (auto&& event : recent_log_events_) {
-  log_msg << "Initial timestamp: " << start_time_us_;
+    StoreToFile(&event);
-  LogDebugEventLocked(DebugEvent::kLogStart, log_msg.str());
+  }
+  recent_log_events_.clear();
 }
 
 void AcmDumpImpl::LogRtpPacket(bool incoming,
                                const uint8_t* packet,
                                size_t length) {
   CriticalSectionScoped lock(crit_.get());
-  if (!CurrentlyLogging()) {
+  ACMDumpEvent rtp_event;
-    StopIfNecessary();
+  const int64_t timestamp = clock_->TimeInMicroseconds();
-    return;
+  rtp_event.set_timestamp_us(timestamp);
-  }
+  rtp_event.set_type(webrtc::ACMDumpEvent::RTP_EVENT);
-  // Reuse the same object at every log event.
+  rtp_event.mutable_packet()->set_direction(
-  auto rtp_event = stream_->mutable_stream(0);
-  rtp_event->clear_debug_event();
-  const int64_t timestamp = clock_->TimeInMicroseconds() - start_time_us_;
-  rtp_event->set_timestamp_us(timestamp);
-  rtp_event->set_type(webrtc::ACMDumpEvent::RTP_EVENT);
-  rtp_event->mutable_packet()->set_direction(
       incoming ? ACMDumpRTPPacket::INCOMING : ACMDumpRTPPacket::OUTGOING);
-  rtp_event->mutable_packet()->set_rtp_data(packet, length);
+  rtp_event.mutable_packet()->set_rtp_data(packet, length);
-  std::string dump_buffer;
+  HandleEvent(&rtp_event);
-  stream_->SerializeToString(&dump_buffer);
-  file_->Write(dump_buffer.data(), dump_buffer.size());
-  file_->Flush();
 }
 
 void AcmDumpImpl::LogDebugEvent(DebugEvent event_type,
@@ -157,43 +158,61 @@ void AcmDumpImpl::LogDebugEvent(DebugEvent event_type) {
   LogDebugEventLocked(event_type, "");
 }
 
-void AcmDumpImpl::StopIfNecessary() {
+void AcmDumpImpl::LogDebugEventLocked(DebugEvent event_type,
-  if (active_) {
+                                      const std::string& event_message) {
-    DCHECK_GT(clock_->TimeInMicroseconds(), start_time_us_ + duration_us_);
+  ACMDumpEvent event;
-    LogDebugEventLocked(DebugEvent::kLogEnd, "");
+  int64_t timestamp = clock_->TimeInMicroseconds();
-    Clear();
+  event.set_timestamp_us(timestamp);
-  }
+  event.set_type(webrtc::ACMDumpEvent::DEBUG_EVENT);
+  auto debug_event = event.mutable_debug_event();
+  debug_event->set_type(convertDebugEvent(event_type));
+  debug_event->set_message(event_message);
+  HandleEvent(&event);
 }
 
 void AcmDumpImpl::Clear() {
-  if (active_ || file_->Open()) {
+  if (file_->Open()) {
     file_->CloseFile();
   }
-  active_ = false;
+  currently_logging_ = false;
   stream_->Clear();
 }
 
-void AcmDumpImpl::LogDebugEventLocked(DebugEvent event_type,
+void AcmDumpImpl::HandleEvent(ACMDumpEvent* event) {
-                                      const std::string& event_message) {
+  if (currently_logging_) {
-  if (!CurrentlyLogging()) {
+    if (clock_->TimeInMicroseconds() < start_time_us_ + duration_us_) {
-    StopIfNecessary();
+      StoreToFile(event);
-    return;
+    } else {
+      LogDebugEventLocked(DebugEvent::kLogEnd, "");
+      Clear();
+      AddRecentEvent(*event);
+    }
+  } else {
+    AddRecentEvent(*event);
   }
+}
 
+void AcmDumpImpl::StoreToFile(ACMDumpEvent* event) {
   // Reuse the same object at every log event.
-  auto event = stream_->mutable_stream(0);
+  if (stream_->stream_size() < 1) {
-  int64_t timestamp = clock_->TimeInMicroseconds() - start_time_us_;
+    stream_->add_stream();
-  event->set_timestamp_us(timestamp);
+  }
-  event->set_type(webrtc::ACMDumpEvent::DEBUG_EVENT);
+  DCHECK_EQ(stream_->stream_size(), 1);
-  event->clear_packet();
+  stream_->mutable_stream(0)->Swap(event);
-  auto debug_event = event->mutable_debug_event();
+
-  debug_event->set_type(convertDebugEvent(event_type));
-  debug_event->set_message(event_message);
   std::string dump_buffer;
   stream_->SerializeToString(&dump_buffer);
   file_->Write(dump_buffer.data(), dump_buffer.size());
 }
 
+void AcmDumpImpl::AddRecentEvent(const ACMDumpEvent& event) {
+  recent_log_events_.push_back(event);
+  while (recent_log_events_.front().timestamp_us() <
+         event.timestamp_us() - recent_log_duration_us) {
+    recent_log_events_.pop_front();
+  }
+}
+
 #endif  // RTC_AUDIOCODING_DEBUG_DUMP
 
 // AcmDump member functions.

webrtc/modules/audio_coding/main/acm2/acm_dump_unittest.cc

@@ -35,12 +35,11 @@ namespace webrtc {
 // back to see if they match.
 class AcmDumpTest : public ::testing::Test {
  public:
-  AcmDumpTest() : log_dumper_(AcmDump::Create()) {}
   void VerifyResults(const ACMDumpEventStream& parsed_stream,
                      size_t packet_size) {
     // Verify the result.
-    EXPECT_EQ(3, parsed_stream.stream_size());
+    EXPECT_EQ(5, parsed_stream.stream_size());
-    const ACMDumpEvent& start_event = parsed_stream.stream(0);
+    const ACMDumpEvent& start_event = parsed_stream.stream(2);
     ASSERT_TRUE(start_event.has_type());
     EXPECT_EQ(ACMDumpEvent::DEBUG_EVENT, start_event.type());
     EXPECT_TRUE(start_event.has_timestamp_us());
@@ -51,7 +50,11 @@ class AcmDumpTest : public ::testing::Test {
     EXPECT_EQ(ACMDumpDebugEvent::LOG_START, start_debug_event.type());
     ASSERT_TRUE(start_debug_event.has_message());
 
-    for (int i = 1; i < parsed_stream.stream_size(); i++) {
+    for (int i = 0; i < parsed_stream.stream_size(); i++) {
+      if (i == 2) {
+        // This is the LOG_START packet that was already verified.
+        continue;
+      }
       const ACMDumpEvent& test_event = parsed_stream.stream(i);
       ASSERT_TRUE(test_event.has_type());
       EXPECT_EQ(ACMDumpEvent::RTP_EVENT, test_event.type());
@@ -60,9 +63,9 @@ class AcmDumpTest : public ::testing::Test {
       ASSERT_TRUE(test_event.has_packet());
       const ACMDumpRTPPacket& test_packet = test_event.packet();
       ASSERT_TRUE(test_packet.has_direction());
-      if (i == 1) {
+      if (i <= 1) {
         EXPECT_EQ(ACMDumpRTPPacket::INCOMING, test_packet.direction());
-      } else if (i == 2) {
+      } else if (i >= 3) {
         EXPECT_EQ(ACMDumpRTPPacket::OUTGOING, test_packet.direction());
       }
       ASSERT_TRUE(test_packet.has_rtp_data());
@@ -88,9 +91,16 @@ class AcmDumpTest : public ::testing::Test {
     const std::string temp_filename =
         test::OutputPath() + test_info->test_case_name() + test_info->name();
 
-    log_dumper_->StartLogging(temp_filename, 10000000);
+    // When log_dumper goes out of scope, it causes the log file to be flushed
-    log_dumper_->LogRtpPacket(true, rtp_packet_.data(), rtp_packet_.size());
+    // to disk.
-    log_dumper_->LogRtpPacket(false, rtp_packet_.data(), rtp_packet_.size());
+    {
+      rtc::scoped_ptr<AcmDump> log_dumper(AcmDump::Create());
+      log_dumper->LogRtpPacket(true, rtp_packet_.data(), rtp_packet_.size());
+      log_dumper->LogRtpPacket(true, rtp_packet_.data(), rtp_packet_.size());
+      log_dumper->StartLogging(temp_filename, 10000000);
+      log_dumper->LogRtpPacket(false, rtp_packet_.data(), rtp_packet_.size());
+      log_dumper->LogRtpPacket(false, rtp_packet_.data(), rtp_packet_.size());
+    }
 
     // Read the generated file from disk.
     ACMDumpEventStream parsed_stream;
@@ -102,14 +112,11 @@ class AcmDumpTest : public ::testing::Test {
     // Clean up temporary file - can be pretty slow.
     remove(temp_filename.c_str());
   }
-
   std::vector<uint8_t> rtp_packet_;
-  rtc::scoped_ptr<AcmDump> log_dumper_;
 };
 
 TEST_F(AcmDumpTest, DumpAndRead) {
   Run(256, 321);
-  Run(256, 123);
 }
 
 }  // namespace webrtc