Limit MediaLog rate to the maximum cache size.

Logs exceeding these limits are just dropped on the remote side,
so there's no reason to send them in the first place.

This removes the UnlimitedSize workaround and fixes a test which
was generating a ton of log events due to misconfiguration.

R=dcheng, tmathmeyer

Bug: 1141985
Change-Id: I178a2214005ca82f1f253bb7d59f43f0a79396a9
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2518208
Commit-Queue: Dale Curtis <dalecurtis@chromium.org>
Reviewed-by: Ted Meyer <tmathmeyer@chromium.org>
Reviewed-by: Daniel Cheng <dcheng@chromium.org>
Auto-Submit: Dale Curtis <dalecurtis@chromium.org>
Cr-Commit-Position: refs/heads/master@{#823868}

content/browser/media/media_internals.cc

@@ -642,19 +642,9 @@ void MediaInternals::SendUpdate(const base::string16& update) {
 void MediaInternals::SaveEvent(int process_id,
                                const media::MediaLogRecord& event) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
-
-// Save the event and limit the total number per renderer. At the time of
-// writing, 512 events of the kind: { "property": value } together consume
-// ~88kb of memory on linux.
-#if defined(OS_ANDROID)
-  const size_t kEventLimit = 128;
-#else
-  const size_t kEventLimit = 512;
-#endif
-
   auto& saved_events = saved_events_by_process_[process_id];
   saved_events.push_back(event);
-  if (saved_events.size() > kEventLimit) {
+  if (saved_events.size() > media::MediaLog::kLogLimit) {
     // Remove all events for a given player as soon as we have to remove a
     // single event for that player to avoid showing incomplete players.
     const int id_to_remove = saved_events.front().id;

content/common/media/media_log_records.mojom

@@ -10,9 +10,5 @@ import "media/mojo/mojom/media_types.mojom";
 // media pipeline. It sends media event logs from renderer to browser.
 interface MediaInternalLogRecords {
   // Sends batched media logs to MediaInternalLogRecordsImpl::Log
-  //
-  // TODO(crbug.com/1141985): Investigate whether we can avoid degenerate cases
-  // leading to the very large messages which necessitate [UnlimitedSize].
-  [UnlimitedSize]
   Log(array<media.mojom.MediaLogRecord> events);
 };

content/renderer/media/batching_media_log.cc

@@ -22,21 +22,21 @@ namespace {
 
 // Keep the JSON conversion in one function to prevent LOG and DVLOG calls
 // from unnecessarily converting it.
-std::string ToJSON(const media::MediaLogRecord* event) {
+std::string ToJSON(const media::MediaLogRecord& event) {
   std::string params_json;
-  base::JSONWriter::Write(event->params, &params_json);
+  base::JSONWriter::Write(event.params, &params_json);
   return params_json;
 }
 
 // Print an event to the chromium log.
 // TODO(tmathmeyer) replace this with a log-only EventHandler.
-void Log(media::MediaLogRecord* event) {
-  if (event->type == media::MediaLogRecord::Type::kMediaStatus) {
+void Log(const media::MediaLogRecord& event) {
+  if (event.type == media::MediaLogRecord::Type::kMediaStatus) {
     DVLOG(1) << "MediaEvent: " << ToJSON(event);
-  } else if (event->type == media::MediaLogRecord::Type::kMessage &&
-             event->params.HasKey("error")) {
+  } else if (event.type == media::MediaLogRecord::Type::kMessage &&
+             event.params.HasKey("error")) {
     DVLOG(1) << "MediaEvent: " << ToJSON(event);
-  } else if (event->type != media::MediaLogRecord::Type::kMediaPropertyChange) {
+  } else if (event.type != media::MediaLogRecord::Type::kMediaPropertyChange) {
     DVLOG(1) << "MediaEvent: " << ToJSON(event);
   }
 }
@@ -58,7 +58,8 @@ BatchingMediaLog::BatchingMediaLog(
       event_handlers_(std::move(event_handlers)),
       tick_clock_(base::DefaultTickClock::GetInstance()),
       last_ipc_send_time_(tick_clock_->NowTicks()),
-      ipc_send_pending_(false) {
+      ipc_send_pending_(false),
+      logged_rate_limit_warning_(false) {
   DCHECK(RenderThread::Get())
       << "BatchingMediaLog must be constructed on the render thread";
   // Pre-bind the WeakPtr on the right thread since we'll receive calls from
@@ -86,7 +87,7 @@ void BatchingMediaLog::OnWebMediaPlayerDestroyedLocked() {
 
 void BatchingMediaLog::AddLogRecordLocked(
     std::unique_ptr<media::MediaLogRecord> event) {
-  Log(event.get());
+  Log(*event);
 
   // For enforcing delay until it's been a second since the last ipc message was
   // sent.
@@ -97,8 +98,8 @@ void BatchingMediaLog::AddLogRecordLocked(
       // Hold onto the most recent PIPELINE_ERROR and the first, if any,
       // MEDIA_LOG_ERROR_ENTRY for use in GetErrorMessage().
       case media::MediaLogRecord::Type::kMediaStatus:
-        queued_media_events_.push_back(*event);
-        last_pipeline_error_.swap(event);
+        last_pipeline_error_ = *event;
+        MaybeQueueEvent_Locked(std::move(event));
         break;
 
       case media::MediaLogRecord::Type::kMediaEventTriggered: {
@@ -107,28 +108,27 @@ void BatchingMediaLog::AddLogRecordLocked(
             event->params.FindStringKey(MediaLog::kEventKey);
         if (*event_key == kDurationChangedMessage) {
           // This may fire many times for badly muxed media; only keep the last.
-          last_duration_changed_event_.swap(event);
+          last_duration_changed_event_ = *event;
         } else if (*event_key == kBufferingStateChangedMessage) {
           // This may fire many times on poor networks; only keep the last.
-          last_buffering_state_event_.swap(event);
+          last_buffering_state_event_ = *event;
         } else {
-          queued_media_events_.push_back(*std::move(event));
+          MaybeQueueEvent_Locked(std::move(event));
         }
         break;
       }
 
       case media::MediaLogRecord::Type::kMessage:
-        queued_media_events_.push_back(*event);
         if (event->params.HasKey(media::MediaLogMessageLevelToString(
                 media::MediaLogMessageLevel::kERROR)) &&
             !cached_media_error_for_message_) {
-          cached_media_error_for_message_ = std::move(event);
+          cached_media_error_for_message_ = *event;
         }
+        MaybeQueueEvent_Locked(std::move(event));
         break;
 
-      // Just enqueue all other event types for throttled transmission.
       default:
-        queued_media_events_.push_back(*event);
+        MaybeQueueEvent_Locked(std::move(event));
     }
 
     if (ipc_send_pending_)
@@ -238,4 +238,32 @@ void BatchingMediaLog::SetTickClockForTesting(
   last_ipc_send_time_ = tick_clock_->NowTicks();
 }
 
+void BatchingMediaLog::MaybeQueueEvent_Locked(
+    std::unique_ptr<media::MediaLogRecord> event) {
+  lock_.AssertAcquired();
+  if (queued_media_events_.size() < media::MediaLog::kLogLimit) {
+    queued_media_events_.emplace_back(*event);
+    return;
+  }
+
+  if (logged_rate_limit_warning_)
+    return;
+
+  logged_rate_limit_warning_ = true;
+
+  auto message = "Log rate exceeds " +
+                 base::NumberToString(media::MediaLog::kLogLimit) +
+                 " messages per second. Futher entries will be dropped.";
+  DLOG(WARNING) << message;
+
+  queued_media_events_.emplace_back();
+  queued_media_events_.back().id = event->id;
+  queued_media_events_.back().type = media::MediaLogRecord::Type::kMessage;
+  queued_media_events_.back().time = base::TimeTicks::Now();
+  queued_media_events_.back().params.SetStringPath(
+      media::MediaLogMessageLevelToString(
+          media::MediaLogMessageLevel::kWARNING),
+      message);
+}
+
 }  // namespace content

content/renderer/media/batching_media_log.h

@@ -57,6 +57,8 @@ class CONTENT_EXPORT BatchingMediaLog : public media::MediaLog {
   // frequency.
   void SendQueuedMediaEvents();
 
+  void MaybeQueueEvent_Locked(std::unique_ptr<media::MediaLogRecord> event);
+
   std::string MediaEventToMessageString(const media::MediaLogRecord& event);
 
   scoped_refptr<base::SingleThreadTaskRunner> task_runner_;
@@ -78,19 +80,22 @@ class CONTENT_EXPORT BatchingMediaLog : public media::MediaLog {
   // For enforcing max 1 pending send.
   bool ipc_send_pending_;
 
+  // True if we've logged a warning message about exceeding rate limits.
+  bool logged_rate_limit_warning_;
+
   // Limits the number of events we send over IPC to one.
-  std::unique_ptr<media::MediaLogRecord> last_duration_changed_event_;
-  std::unique_ptr<media::MediaLogRecord> last_buffering_state_event_;
+  base::Optional<media::MediaLogRecord> last_duration_changed_event_;
+  base::Optional<media::MediaLogRecord> last_buffering_state_event_;
 
   // Holds the earliest MEDIA_ERROR_LOG_ENTRY event added to this log. This is
   // most likely to contain the most specific information available describing
   // any eventual fatal error.
   // TODO(wolenetz): Introduce a reset method to clear this in cases like
   // non-fatal error recovery like decoder fallback.
-  std::unique_ptr<media::MediaLogRecord> cached_media_error_for_message_;
+  base::Optional<media::MediaLogRecord> cached_media_error_for_message_;
 
   // Holds a copy of the most recent PIPELINE_ERROR, if any.
-  std::unique_ptr<media::MediaLogRecord> last_pipeline_error_;
+  base::Optional<media::MediaLogRecord> last_pipeline_error_;
 
   base::WeakPtr<BatchingMediaLog> weak_this_;
   base::WeakPtrFactory<BatchingMediaLog> weak_factory_{this};

content/renderer/media/batching_media_log_unittest.cc

@@ -121,6 +121,17 @@ TEST_F(BatchingMediaLogTest, ThrottleSendingEvents) {
   EXPECT_EQ(1, message_count());
 }
 
+TEST_F(BatchingMediaLogTest, LimitEvents) {
+  // Add 2x the log limit in play/pause messages.
+  for (size_t i = 0; i < media::MediaLog::kLogLimit; ++i) {
+    AddEvent<media::MediaLogEvent::kPlay>();
+    AddEvent<media::MediaLogEvent::kPause>();
+  }
+
+  Advance(base::TimeDelta::FromMilliseconds(1100));
+  EXPECT_EQ(media::MediaLog::kLogLimit + 1, GetMediaLogRecords().size());
+}
+
 TEST_F(BatchingMediaLogTest, EventSentWithoutDelayAfterIpcInterval) {
   AddEvent<media::MediaLogEvent::kPlay>();
   Advance(base::TimeDelta::FromMilliseconds(1000));

media/base/media_log.h

@@ -17,6 +17,7 @@
 #include "base/macros.h"
 #include "base/memory/ref_counted.h"
 #include "base/thread_annotations.h"
+#include "build/build_config.h"
 #include "media/base/buffering_state.h"
 #include "media/base/media_export.h"
 #include "media/base/media_log_events.h"
@@ -43,6 +44,15 @@ class MEDIA_EXPORT MediaLog {
   static const char kEventKey[];
   static const char kStatusText[];
 
+// Maximum limit for the total number of logs kept per renderer. At the time of
+// writing, 512 events of the kind: { "property": value } together consume ~88kb
+// of memory on linux.
+#if defined(OS_ANDROID)
+  static constexpr size_t kLogLimit = 128;
+#else
+  static constexpr size_t kLogLimit = 512;
+#endif
+
   // Constructor is protected, see below.
   virtual ~MediaLog();
 

third_party/blink/web_tests/media/video-replaces-poster.html

@@ -2,16 +2,17 @@
 <title>Test that video frame replaces poster on seeking.</title>
 <script>
 function doSetup() {
-    // TODO(srirama.m): convert this test to reference test.
     var video = document.querySelector("video");
-    video.src = "content/test.ogv";
-    video.addEventListener("canplaythrough", function () {
+    function seekVideo() {
+        video.removeEventListener("canplaythrough", seekVideo);
         video.currentTime = 1;  // so the snapshot always has the same frame.
-    });
-    testRunner.waitUntilDone();
+    }
+    video.addEventListener("canplaythrough", seekVideo);
     video.addEventListener("seeked", function() {
         testRunner.notifyDone();
     });
+    video.src = "content/test.ogv";
+    testRunner.waitUntilDone();
 }
 window.addEventListener("load", doSetup, false);
 </script>