Keep config events in RtcEventLog even if they are old.

webrtc/video/rtc_event_log.cc

Index: webrtc/video/rtc_event_log.cc
diff --git a/webrtc/video/rtc_event_log.cc b/webrtc/video/rtc_event_log.cc
index 476ee2afd79c82b9be6b41feb7424939842d942b..082ba5cf30cc0d1a2fb1102397a60d3c85d66620 100644
--- a/webrtc/video/rtc_event_log.cc
+++ b/webrtc/video/rtc_event_log.cc
@@ -35,6 +35,7 @@ namespace webrtc {
 // No-op implementation if flag is not set.
 class RtcEventLogImpl final : public RtcEventLog {
  public:
+  void SetBufferDuration(int64_t recent_log_duration_us) override {}
   void StartLogging(const std::string& file_name, int duration_ms) override {}
   void StopLogging(void) override {}
   void LogVideoReceiveStreamConfig(
@@ -59,6 +60,7 @@ class RtcEventLogImpl final : public RtcEventLog {
  public:
   RtcEventLogImpl();
 
+  void SetBufferDuration(int64_t recent_log_duration_us) override;
   void StartLogging(const std::string& file_name, int duration_ms) override;
   void StopLogging() override;
   void LogVideoReceiveStreamConfig(
@@ -89,14 +91,14 @@ class RtcEventLogImpl final : public RtcEventLog {
   void AddRecentEvent(const rtclog::Event& 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::CriticalSection crit_;
   rtc::scoped_ptr<FileWrapper> file_ GUARDED_BY(crit_);
   rtclog::EventStream stream_ GUARDED_BY(crit_);
   std::deque<rtclog::Event> recent_log_events_ GUARDED_BY(crit_);
+  std::vector<rtclog::Event> config_events_ GUARDED_BY(crit_);
+
+  // Microseconds to record log events, before starting the actual log.
+  int64_t recent_log_duration_us_ GUARDED_BY(crit_);
   bool currently_logging_ GUARDED_BY(crit_);
   int64_t start_time_us_ GUARDED_BY(crit_);
   int64_t duration_us_ GUARDED_BY(crit_);
@@ -159,12 +161,18 @@ rtclog::MediaType ConvertMediaType(MediaType media_type) {
 RtcEventLogImpl::RtcEventLogImpl()
     : file_(FileWrapper::Create()),
       stream_(),
+      recent_log_duration_us_(10000000),
       currently_logging_(false),
       start_time_us_(0),
       duration_us_(0),
       clock_(Clock::GetRealTimeClock()) {
 }
 
+void RtcEventLogImpl::SetBufferDuration(int64_t recent_log_duration_us) {
+  rtc::CritScope lock(&crit_);
+  recent_log_duration_us_ = recent_log_duration_us;

[ivoc, 2015/08/25 08:03:21]

Shouldn't there be some sort of purging of the buffer in case the new value is
lower than the old value? (i.e. discard events that are too old due to the
buffer change)

[terelius, 2015/08/25 16:41:44]

The old events are purged whenever we add a new event to the queue or when we
call StartLogging.

[ivoc, 2015/08/26 08:15:28]

Acknowledged.

+}
+
 void RtcEventLogImpl::StartLogging(const std::string& file_name,
                                    int duration_ms) {
   rtc::CritScope lock(&crit_);
@@ -177,9 +185,21 @@ void RtcEventLogImpl::StartLogging(const std::string& file_name,
   currently_logging_ = true;
   start_time_us_ = clock_->TimeInMicroseconds();
   duration_us_ = static_cast<int64_t>(duration_ms) * 1000;
-  // Write all the recent events to the log file, ignoring any old events.
+  // Write all old configuration events to the log file.
+  for (auto& event : config_events_) {
+    StoreToFile(&event);
+  }
+  // Write all recent configuration events to the log file, and
+  // write all other recent events to the log file, ignoring any old events.
   for (auto& event : recent_log_events_) {
-    if (event.timestamp_us() >= start_time_us_ - recent_log_duration_us) {
+    if (event.type() == rtclog::Event::VIDEO_RECEIVER_CONFIG_EVENT ||
+        event.type() == rtclog::Event::VIDEO_SENDER_CONFIG_EVENT ||
+        event.type() == rtclog::Event::AUDIO_RECEIVER_CONFIG_EVENT ||
+        event.type() == rtclog::Event::AUDIO_SENDER_CONFIG_EVENT) {
+      StoreToFile(&event);
+      config_events_.push_back(event);
+    } else if (event.timestamp_us() >=
+               start_time_us_ - recent_log_duration_us_) {
       StoreToFile(&event);
     }
   }
@@ -376,7 +396,14 @@ void RtcEventLogImpl::StoreToFile(rtclog::Event* event) {
 void RtcEventLogImpl::AddRecentEvent(const rtclog::Event& event) {
   recent_log_events_.push_back(event);
   while (recent_log_events_.front().timestamp_us() <
-         event.timestamp_us() - recent_log_duration_us) {
+         event.timestamp_us() - recent_log_duration_us_) {
+    rtclog::Event_EventType event_type = recent_log_events_.front().type();
+    if (event_type == rtclog::Event::VIDEO_RECEIVER_CONFIG_EVENT ||
+        event_type == rtclog::Event::VIDEO_SENDER_CONFIG_EVENT ||
+        event_type == rtclog::Event::AUDIO_RECEIVER_CONFIG_EVENT ||
+        event_type == rtclog::Event::AUDIO_SENDER_CONFIG_EVENT) {
+      config_events_.push_back(recent_log_events_.front());

[ivoc, 2015/08/25 08:03:21]

I wonder if we should be checking if any of the config events that are already
stored in config_events_ might become obsolete due to a newer config event. Is
that something that could happen?

[terelius, 2015/08/25 16:41:44]

This is a good point.

I don't think it is possible to reconfigure (video) streams during runtime.
However, it is possible to delete the stream and create a new one with the same
SSRC which would result in two config events for the "same" stream.

It is not clear whether we should resolve those ambiguities while writing the
log or when we read it. Doing the check here would not completely solve the
issue since we could potentially have multiple config events in the
recent_log_events queue.

[ivoc, 2015/08/26 08:15:28]

I think a check here would solve this problem. Even if the recent_events_ queue
contains another config event that will succeed one of the ones from the
config_events_ list, the one that is stored in config_events_ is still valid for
any older packets that are in the recent_events_ queue, and is therefore still
needed. Once the succeeding config event is too old for the recent_events_
queue, it can replace the old one in config_events_ since it is no longer
useful.

I'm not sure if it's better to solve this while writing or reading. I guess it
also depends on how likely it is that this happens. If it happens frequently, it
is not nice if the RtcEventLog starts collecting a whole list of config events
that are no longer valid. If it is rare, then it's probably acceptable to leave
it in. I don't know how often this happens in practice, maybe one of the other
reviewers can comment? If we decide to solve it while reading, I think it would
be good to document this behavior somewhere (maybe in the protobuf, or with the
parsing functions?).

[ivoc, 2015/09/25 15:30:23]

Could you respond to this? I still think it would be better to purge old configs
that are not needed to interpret any packets that appear in the log or in the
recentEvents_queue, and I don't think it would be that complicated to add that
feature (unless I'm missing something). 

[terelius, 2015/10/15 13:28:21]

So what you are proposing is checking whether there exists an older config in
config_events before adding a new config for the same SSRC?

The reason why I am hesitant is that we would add code for a rare event that
wont be tested exhaustively, yet we would not solve the problem completely. (We
could still have unused configurations for streams that are configured but never
receive or send any packets. We could also have two configurations for the
"same" stream if there are packets sent before the reconfiguration. Finally, if
the reconfiguration is done while we are logging then everything would be
written to file directly so there is no way to detect whether we have
unnecessary configurations.)

It is also slightly complicated to solve due to the fact that VideoSendConfig
doesn't have a single SSRC, but a whole vector of them. Handling configurations
with overlapping but nonidentical ssrc vectors will probably be ugly.

[ivoc, 2015/10/15 15:52:06]

Okay, let's stick to the simple solution for now. We can analyze later if there
actually is a problem in practice or if it's a complete non-issue (probably the
latter).

+    }
     recent_log_events_.pop_front();
   }
 }
@@ -403,4 +430,5 @@ bool RtcEventLog::ParseRtcEventLog(const std::string& file_name,
 rtc::scoped_ptr<RtcEventLog> RtcEventLog::Create() {
   return rtc::scoped_ptr<RtcEventLog>(new RtcEventLogImpl());
 }
+
 }  // namespace webrtc