[bfcache] Update IPC hash setting functionality in mojo and add unit tests + browser test for IPC tracking to frames in cache

Currently, IPC hash isn't set for tasks posted on the IO thread; adding IPC to SimpleWatcher when tasks are posted allows for the task posted on the IO thread to be annotated with an IPC hash, so that it can then be tracked in the histograms. ScopedSetIpcHash changes are to allow for tracking of IPCs posted from remote mojo objects. However, calculating the MD5 hash of a char* on every posted task is expensive, so we have also introduced storage of the IPC interface name. The IPC interface name can be used to calculate IPC hash on an as-needed basis (i.e. only in cases where IPC is posted to cached frames/documents).

Also includes histogram testing to ensure metrics are recorded. and how ScopedSetIpcHash is set.

Bug: 1110344
Change-Id: I26da160b65145f06639c33679ff03872f686e4af
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2345673
Commit-Queue: Harkiran Bolaria <hbolaria@google.com>
Reviewed-by: François Doray <fdoray@chromium.org>
Reviewed-by: Ken Rockot <rockot@google.com>
Reviewed-by: Kentaro Hara <haraken@chromium.org>
Reviewed-by: Alexander Timin <altimin@chromium.org>
Cr-Commit-Position: refs/heads/master@{#807106}

base/pending_task.h

@@ -61,12 +61,12 @@ struct BASE_EXPORT PendingTask {
   // The context of the IPC message that was being handled when this task was
   // posted. This is a hash of the IPC message name that is set within the scope
   // of an IPC handler and when symbolized uniquely identifies the message being
-  // processed. This property is also propagated from one PendingTask to the
+  // processed. This property is not propagated from one PendingTask to the
   // next. For example, if pending task A was posted while handling an IPC,
   // and pending task B was posted from within pending task A, then pending task
-  // B will inherit the |ipc_hash| of pending task A. In some sense this can be
-  // interpreted as a "root" task backtrace frame.
+  // B will not inherit the |ipc_hash| of pending task A.
   uint32_t ipc_hash = 0;
+  const char* ipc_interface_name = nullptr;
 
   // Secondary sort key for run time.
   int sequence_num = 0;

base/task/common/task_annotator.cc

@@ -6,9 +6,12 @@
 
 #include <array>
 
+#include "base/check_op.h"
 #include "base/debug/activity_tracker.h"
 #include "base/debug/alias.h"
+#include "base/hash/md5.h"
 #include "base/no_destructor.h"
+#include "base/sys_byteorder.h"
 #include "base/threading/thread_local.h"
 #include "base/trace_event/base_tracing.h"
 
@@ -30,6 +33,17 @@ ThreadLocalPointer<PendingTask>* GetTLSForCurrentPendingTask() {
   return instance.get();
 }
 
+// Returns the TLS slot that stores scoped IPC-related data (IPC hash and/or
+// IPC interface name). IPC hash or interface name can be known before the
+// associated task object is created; store in the TLS so that this data can be
+// affixed to the associated task.
+ThreadLocalPointer<TaskAnnotator::ScopedSetIpcHash>*
+GetTLSForCurrentScopedIpcHash() {
+  static NoDestructor<ThreadLocalPointer<TaskAnnotator::ScopedSetIpcHash>>
+      instance;
+  return instance.get();
+}
+
 // Determines whether or not the given |task| is a dummy pending task that has
 // been injected by ScopedSetIpcHash solely for the purposes of
 // tracking IPC context.
@@ -49,7 +63,7 @@ const PendingTask* TaskAnnotator::CurrentTaskForThread() {
 
   // Don't return "dummy" current tasks that are only used for storing IPC
   // context.
-  if (current_task && IsDummyPendingTask(current_task))
+  if (!current_task || (current_task && IsDummyPendingTask(current_task)))
     return nullptr;
   return current_task;
 }
@@ -74,11 +88,18 @@ void TaskAnnotator::WillQueueTask(const char* trace_event_name,
   if (pending_task->task_backtrace[0])
     return;
 
+  DCHECK(!pending_task->ipc_interface_name);
+  DCHECK(!pending_task->ipc_hash);
+  auto* current_ipc_hash = GetTLSForCurrentScopedIpcHash()->Get();
+  if (current_ipc_hash) {
+    pending_task->ipc_interface_name = current_ipc_hash->GetIpcInterfaceName();
+    pending_task->ipc_hash = current_ipc_hash->GetIpcHash();
+  }
+
   const auto* parent_task = CurrentTaskForThread();
   if (!parent_task)
     return;
 
-  pending_task->ipc_hash = parent_task->ipc_hash;
   pending_task->task_backtrace[0] = parent_task->posted_from.program_counter();
   std::copy(parent_task->task_backtrace.begin(),
             parent_task->task_backtrace.end() - 1,
@@ -170,31 +191,42 @@ void TaskAnnotator::ClearObserverForTesting() {
   g_task_annotator_observer = nullptr;
 }
 
-TaskAnnotator::ScopedSetIpcHash::ScopedSetIpcHash(uint32_t ipc_hash) {
-  // We store the IPC context in the currently running task. If there is none
-  // then introduce a dummy task.
-  auto* tls = GetTLSForCurrentPendingTask();
-  auto* current_task = tls->Get();
-  if (!current_task) {
-    dummy_pending_task_ = std::make_unique<PendingTask>();
-    dummy_pending_task_->sequence_num = kSentinelSequenceNum;
-    current_task = dummy_pending_task_.get();
-    tls->Set(current_task);
-  }
+TaskAnnotator::ScopedSetIpcHash::ScopedSetIpcHash(uint32_t ipc_hash)
+    : ScopedSetIpcHash(ipc_hash, nullptr) {}
 
-  old_ipc_hash_ = current_task->ipc_hash;
-  current_task->ipc_hash = ipc_hash;
+TaskAnnotator::ScopedSetIpcHash::ScopedSetIpcHash(
+    const char* ipc_interface_name)
+    : ScopedSetIpcHash(0, ipc_interface_name) {}
+
+TaskAnnotator::ScopedSetIpcHash::ScopedSetIpcHash(
+    uint32_t ipc_hash,
+    const char* ipc_interface_name) {
+  TRACE_EVENT_BEGIN2("base", "ScopedSetIpcHash", "ipc_hash", ipc_hash,
+                     "ipc_interface_name", ipc_interface_name);
+  auto* tls_ipc_hash = GetTLSForCurrentScopedIpcHash();
+  auto* current_ipc_hash = tls_ipc_hash->Get();
+  old_scoped_ipc_hash_ = current_ipc_hash;
+  ipc_hash_ = ipc_hash;
+  ipc_interface_name_ = ipc_interface_name;
+  tls_ipc_hash->Set(this);
+}
+
+// Static
+uint32_t TaskAnnotator::ScopedSetIpcHash::MD5HashMetricName(
+    base::StringPiece name) {
+  base::MD5Digest digest;
+  base::MD5Sum(name.data(), name.size(), &digest);
+  uint32_t value;
+  DCHECK_GE(sizeof(digest.a), sizeof(value));
+  memcpy(&value, digest.a, sizeof(value));
+  return base::NetToHost32(value);
 }
 
 TaskAnnotator::ScopedSetIpcHash::~ScopedSetIpcHash() {
-  auto* tls = GetTLSForCurrentPendingTask();
-  auto* current_task = tls->Get();
-  DCHECK(current_task);
-  if (current_task == dummy_pending_task_.get()) {
-    tls->Set(nullptr);
-  } else {
-    current_task->ipc_hash = old_ipc_hash_;
-  }
+  auto* tls_ipc_hash = GetTLSForCurrentScopedIpcHash();
+  DCHECK_EQ(this, tls_ipc_hash->Get());
+  tls_ipc_hash->Set(old_scoped_ipc_hash_);
+  TRACE_EVENT_END0("base", "ScopedSetIpcHash");
 }
 
 }  // namespace base

base/task/common/task_annotator.h

@@ -13,6 +13,7 @@
 #include "base/compiler_specific.h"
 #include "base/macros.h"
 #include "base/pending_task.h"
+#include "base/strings/string_piece.h"
 
 namespace base {
 
@@ -71,11 +72,22 @@ class BASE_EXPORT TaskAnnotator {
 class BASE_EXPORT TaskAnnotator::ScopedSetIpcHash {
  public:
   explicit ScopedSetIpcHash(uint32_t ipc_hash);
+
+  // Compile-time-const string identifying the current IPC context. Not always
+  // available due to binary size constraints, so IPC hash might be set instead.
+  explicit ScopedSetIpcHash(const char* ipc_interface_name);
   ~ScopedSetIpcHash();
 
+  uint32_t GetIpcHash() const { return ipc_hash_; }
+  const char* GetIpcInterfaceName() const { return ipc_interface_name_; }
+
+  static uint32_t MD5HashMetricName(base::StringPiece name);
+
  private:
-  std::unique_ptr<PendingTask> dummy_pending_task_;
-  uint32_t old_ipc_hash_ = 0;
+  ScopedSetIpcHash(uint32_t ipc_hash, const char* ipc_interface_name);
+  ScopedSetIpcHash* old_scoped_ipc_hash_ = nullptr;
+  uint32_t ipc_hash_ = 0;
+  const char* ipc_interface_name_ = nullptr;
 
   DISALLOW_COPY_AND_ASSIGN(ScopedSetIpcHash);
 };

base/task/common/task_annotator_unittest.cc

@@ -165,7 +165,8 @@ TEST_F(TaskAnnotatorBacktraceIntegrationTest, SingleThreadedSimple) {
   RunLoop run_loop;
 
   // Task 0 executes with no IPC context. Task 1 executes under an explicitly
-  // set IPC context, and tasks 2-5 inherit that context.
+  // set IPC context. Tasks 2-5 don't necessarily inherit that context, as
+  // IPCs may spawn subtasks that aren't necessarily IPCs themselves.
 
   // Task 5 has tasks 4/3/2/1 as parents (task 0 isn't visible as only the
   // last 4 parents are kept).
@@ -174,7 +175,7 @@ TEST_F(TaskAnnotatorBacktraceIntegrationTest, SingleThreadedSimple) {
       Unretained(this), ThreadTaskRunnerHandle::Get(), location5, FROM_HERE,
       ExpectedTrace({location4.program_counter(), location3.program_counter(),
                      location2.program_counter(), location1.program_counter()}),
-      dummy_ipc_hash, run_loop.QuitClosure());
+      0, run_loop.QuitClosure());
 
   // Task i=4/3/2/1/0 have tasks [0,i) as parents.
   OnceClosure task4 = BindOnce(
@@ -182,13 +183,13 @@ TEST_F(TaskAnnotatorBacktraceIntegrationTest, SingleThreadedSimple) {
       Unretained(this), ThreadTaskRunnerHandle::Get(), location4, location5,
       ExpectedTrace({location3.program_counter(), location2.program_counter(),
                      location1.program_counter(), location0.program_counter()}),
-      dummy_ipc_hash, std::move(task5));
+      0, std::move(task5));
   OnceClosure task3 = BindOnce(
       &TaskAnnotatorBacktraceIntegrationTest::VerifyTraceAndPost,
       Unretained(this), ThreadTaskRunnerHandle::Get(), location3, location4,
       ExpectedTrace({location2.program_counter(), location1.program_counter(),
                      location0.program_counter()}),
-      dummy_ipc_hash, std::move(task4));
+      0, std::move(task4));
   OnceClosure task2 = BindOnce(
       &TaskAnnotatorBacktraceIntegrationTest::VerifyTraceAndPost,
       Unretained(this), ThreadTaskRunnerHandle::Get(), location2, location3,
@@ -359,19 +360,19 @@ TEST_F(TaskAnnotatorBacktraceIntegrationTest, SingleThreadedNested) {
       Unretained(this), ThreadTaskRunnerHandle::Get(), location5, FROM_HERE,
       ExpectedTrace({location4.program_counter(), location3.program_counter(),
                      location2.program_counter(), location1.program_counter()}),
-      dummy_ipc_hash, run_loop.QuitClosure());
+      0, run_loop.QuitClosure());
   OnceClosure task4 = BindOnce(
       &TaskAnnotatorBacktraceIntegrationTest::VerifyTraceAndPost,
       Unretained(this), ThreadTaskRunnerHandle::Get(), location4, location5,
       ExpectedTrace({location3.program_counter(), location2.program_counter(),
                      location1.program_counter(), location0.program_counter()}),
-      dummy_ipc_hash, std::move(task5));
+      0, std::move(task5));
   OnceClosure task3 = BindOnce(
       &TaskAnnotatorBacktraceIntegrationTest::VerifyTraceAndPost,
       Unretained(this), ThreadTaskRunnerHandle::Get(), location3, location4,
       ExpectedTrace({location2.program_counter(), location1.program_counter(),
                      location0.program_counter()}),
-      dummy_ipc_hash, std::move(task4));
+      0, std::move(task4));
 
   OnceClosure run_task_3_then_quit_nested_loop1 =
       BindOnce(&TaskAnnotatorBacktraceIntegrationTest::RunTwo, std::move(task3),
@@ -381,7 +382,7 @@ TEST_F(TaskAnnotatorBacktraceIntegrationTest, SingleThreadedNested) {
       &TaskAnnotatorBacktraceIntegrationTest::VerifyTraceAndPost,
       Unretained(this), ThreadTaskRunnerHandle::Get(), location2, location3,
       ExpectedTrace({location1.program_counter(), location0.program_counter()}),
-      dummy_ipc_hash, std::move(run_task_3_then_quit_nested_loop1));
+      0, std::move(run_task_3_then_quit_nested_loop1));
 
   // Task 1 is custom. It enters another nested RunLoop, has it do work and exit
   // before posting the next task. This confirms that |task1| is restored as the

content/browser/back_forward_cache_browsertest.cc

@@ -15,6 +15,7 @@
 #include "base/run_loop.h"
 #include "base/strings/string_piece_forward.h"
 #include "base/system/sys_info.h"
+#include "base/task/common/task_annotator.h"
 #include "base/task/post_task.h"
 #include "base/test/bind_test_util.h"
 #include "base/test/scoped_feature_list.h"
@@ -78,6 +79,7 @@
 #include "services/device/public/mojom/vibration_manager.mojom.h"
 #include "services/service_manager/public/cpp/interface_provider.h"
 #include "testing/gmock/include/gmock/gmock.h"
+#include "third_party/blink/public/common/features.h"
 #include "third_party/blink/public/common/scheduler/web_scheduler_tracked_feature.h"
 #include "third_party/blink/public/mojom/app_banner/app_banner.mojom.h"
 
@@ -152,6 +154,9 @@ class BackForwardCacheBrowserTest : public ContentBrowserTest,
     EnableFeatureAndSetParams(
         features::kBackForwardCache, "skip_same_site_if_unload_exists",
         skip_same_site_if_unload_exists_ ? "true" : "false");
+    EnableFeatureAndSetParams(
+        blink::features::kLogUnexpectedIPCPostedToBackForwardCachedDocuments,
+        "delay_before_tracking_ms", "0");
 #if defined(OS_ANDROID)
     EnableFeatureAndSetParams(features::kBackForwardCache,
                               "process_binding_strength", "NORMAL");
@@ -2332,6 +2337,46 @@ IN_PROC_BROWSER_TEST_F(BackForwardCacheBrowserTest,
       blink::scheduler::WebSchedulerTrackedFeature::kKeyboardLock, FROM_HERE);
 }
 
+IN_PROC_BROWSER_TEST_F(BackForwardCacheBrowserTest, LogIpcPostedToCachedFrame) {
+  ASSERT_TRUE(embedded_test_server()->Start());
+
+  // 1) Navigate to a page.
+  GURL url(embedded_test_server()->GetURL("/title1.html"));
+  EXPECT_TRUE(NavigateToURL(shell(), url));
+  RenderFrameHostImpl* rfh_a = current_frame_host();
+
+  // 2) Navigate away. The first page should be in the cache.
+  EXPECT_TRUE(NavigateToURL(
+      shell(), embedded_test_server()->GetURL("b.com", "/title1.html")));
+
+  // 3) Post IPC tasks to the page, testing both mojo remote and associated
+  // remote objects.
+
+  // TODO(hbolaria) - implement non-frame-associated tracking, which will be
+  // used by the code below.
+
+  // Post a non-associated interface. Will be routed to a frame-specific task
+  // queue with IPC set in SimpleWatcher.
+  base::RunLoop run_loop;
+  rfh_a->GetHighPriorityLocalFrame()->DispatchBeforeUnload(
+      false,
+      base::BindOnce([](base::RepeatingClosure quit_closure, bool proceed,
+                        base::TimeTicks start_time,
+                        base::TimeTicks end_time) { quit_closure.Run(); },
+                     run_loop.QuitClosure()));
+  run_loop.Run();
+
+  // 4) Check the histogram.
+  FetchHistogramsFromChildProcesses();
+  base::HistogramBase::Sample sample = base::HistogramBase::Sample(
+      base::TaskAnnotator::ScopedSetIpcHash::MD5HashMetricName(
+          "blink.mojom.HighPriorityLocalFrame"));
+  histogram_tester_.ExpectUniqueSample(
+      "BackForwardCache.Experimental."
+      "UnexpectedIPCMessagePostedToCachedFrame.MethodHash",
+      sample, 1);
+}
+
 class MockAppBannerService : public blink::mojom::AppBannerService {
  public:
   MockAppBannerService() = default;

ipc/ipc_mojo_bootstrap.cc

@@ -165,15 +165,14 @@ class ChannelAssociatedGroupController
     DCHECK(thread_checker_.CalledOnValidThread());
     DCHECK(task_runner_->BelongsToCurrentThread());
 
-    connector_.reset(new mojo::Connector(
-        std::move(handle), mojo::Connector::SINGLE_THREADED_SEND,
-        task_runner_));
+    connector_ = std::make_unique<mojo::Connector>(
+        std::move(handle), mojo::Connector::SINGLE_THREADED_SEND, task_runner_,
+        "IPC Channel");
     connector_->set_incoming_receiver(&dispatcher_);
     connector_->set_connection_error_handler(
         base::BindOnce(&ChannelAssociatedGroupController::OnPipeError,
                        base::Unretained(this)));
     connector_->set_enforce_errors_from_incoming_receiver(false);
-    connector_->SetWatcherHeapProfilerTag("IPC Channel");
     if (quota_checker_)
       connector_->SetMessageQuotaChecker(quota_checker_);
 

mojo/public/cpp/bindings/connector.h

@@ -84,7 +84,8 @@ class COMPONENT_EXPORT(MOJO_CPP_BINDINGS) Connector : public MessageReceiver {
   // The Connector takes ownership of |message_pipe|.
   Connector(ScopedMessagePipeHandle message_pipe,
             ConnectorConfig config,
-            scoped_refptr<base::SequencedTaskRunner> runner);
+            scoped_refptr<base::SequencedTaskRunner> runner,
+            const char* heap_profiler_tag = "unknown interface");
   ~Connector() override;
 
   // Sets outgoing serialization mode.
@@ -193,10 +194,6 @@ class COMPONENT_EXPORT(MOJO_CPP_BINDINGS) Connector : public MessageReceiver {
 
   base::SequencedTaskRunner* task_runner() const { return task_runner_.get(); }
 
-  // Sets the tag used by the heap profiler.
-  // |tag| must be a const string literal.
-  void SetWatcherHeapProfilerTag(const char* tag);
-
   // Sets the quota checker.
   void SetMessageQuotaChecker(
       scoped_refptr<internal::MessageQuotaChecker> checker);

mojo/public/cpp/bindings/lib/binding_state.cc

@@ -120,8 +120,7 @@ void BindingStateBase::BindInternal(
                  ? MultiplexRouter::SINGLE_INTERFACE_WITH_SYNC_METHODS
                  : MultiplexRouter::SINGLE_INTERFACE);
   router_ = new MultiplexRouter(std::move(receiver_state->pipe), config, false,
-                                sequenced_runner);
-  router_->SetPrimaryInterfaceName(interface_name);
+                                sequenced_runner, interface_name);
   router_->SetConnectionGroup(std::move(receiver_state->connection_group));
 
   endpoint_client_.reset(new InterfaceEndpointClient(

mojo/public/cpp/bindings/lib/connector.cc

@@ -144,13 +144,15 @@ void Connector::ActiveDispatchTracker::NotifyBeginNesting() {
 
 Connector::Connector(ScopedMessagePipeHandle message_pipe,
                      ConnectorConfig config,
-                     scoped_refptr<base::SequencedTaskRunner> runner)
+                     scoped_refptr<base::SequencedTaskRunner> runner,
+                     const char* heap_profiler_tag)
     : message_pipe_(std::move(message_pipe)),
       task_runner_(std::move(runner)),
       error_(false),
       force_immediate_dispatch_(!EnableTaskPerMessage()),
       outgoing_serialization_mode_(g_default_outgoing_serialization_mode),
       incoming_serialization_mode_(g_default_incoming_serialization_mode),
+      heap_profiler_tag_(heap_profiler_tag),
       nesting_observer_(RunLoopNestingObserver::GetForThread()) {
   if (config == MULTI_THREADED_SEND)
     lock_.emplace();
@@ -351,14 +353,6 @@ void Connector::AllowWokenUpBySyncWatchOnSameThread() {
   sync_watcher_->AllowWokenUpBySyncWatchOnSameThread();
 }
 
-void Connector::SetWatcherHeapProfilerTag(const char* tag) {
-  if (tag) {
-    heap_profiler_tag_ = tag;
-    if (handle_watcher_)
-      handle_watcher_->set_heap_profiler_tag(tag);
-  }
-}
-
 void Connector::SetMessageQuotaChecker(
     scoped_refptr<internal::MessageQuotaChecker> checker) {
   DCHECK(checker && !quota_checker_);
@@ -414,9 +408,9 @@ void Connector::WaitToReadMore() {
   DCHECK(!handle_watcher_);
 
   DCHECK(task_runner_->RunsTasksInCurrentSequence());
-  handle_watcher_.reset(new SimpleWatcher(
-      FROM_HERE, SimpleWatcher::ArmingPolicy::MANUAL, task_runner_));
-  handle_watcher_->set_heap_profiler_tag(heap_profiler_tag_);
+  handle_watcher_ = std::make_unique<SimpleWatcher>(
+      FROM_HERE, SimpleWatcher::ArmingPolicy::MANUAL, task_runner_,
+      heap_profiler_tag_);
   MojoResult rv = handle_watcher_->Watch(
       message_pipe_.get(), MOJO_HANDLE_SIGNAL_READABLE,
       base::BindRepeating(&Connector::OnWatcherHandleReady,

mojo/public/cpp/bindings/lib/interface_ptr_state.cc

@@ -90,13 +90,14 @@ bool InterfacePtrStateBase::InitializeEndpointClient(
                  ? MultiplexRouter::SINGLE_INTERFACE_WITH_SYNC_METHODS
                  : MultiplexRouter::SINGLE_INTERFACE);
   DCHECK(runner_->RunsTasksInCurrentSequence());
-  router_ = new MultiplexRouter(std::move(handle_), config, true, runner_);
-  endpoint_client_.reset(new InterfaceEndpointClient(
+  router_ = new MultiplexRouter(std::move(handle_), config, true, runner_,
+                                interface_name);
+  endpoint_client_ = std::make_unique<InterfaceEndpointClient>(
       router_->CreateLocalEndpointHandle(kPrimaryInterfaceId), nullptr,
       std::move(payload_validator), false, std::move(runner_),
       // The version is only queried from the client so the value passed here
       // will not be used.
-      0u, interface_name));
+      0u, interface_name);
   return true;
 }
 

mojo/public/cpp/bindings/lib/interface_ptr_state.h

@@ -260,7 +260,6 @@ class InterfacePtrState : public InterfacePtrStateBase {
             Interface::PassesAssociatedKinds_, Interface::HasSyncMethods_,
             std::make_unique<typename Interface::ResponseValidator_>(),
             Interface::Name_)) {
-      router()->SetPrimaryInterfaceName(Interface::Name_);
       proxy_ = std::make_unique<Proxy>(endpoint_client());
     }
   }

mojo/public/cpp/bindings/lib/multiplex_router.cc

@@ -14,6 +14,7 @@
 #include "base/memory/ptr_util.h"
 #include "base/sequenced_task_runner.h"
 #include "base/stl_util.h"
+#include "base/strings/string_util.h"
 #include "base/synchronization/waitable_event.h"
 #include "mojo/public/cpp/bindings/interface_endpoint_client.h"
 #include "mojo/public/cpp/bindings/interface_endpoint_controller.h"
@@ -315,14 +316,16 @@ MultiplexRouter::MultiplexRouter(
     ScopedMessagePipeHandle message_pipe,
     Config config,
     bool set_interface_id_namespace_bit,
-    scoped_refptr<base::SequencedTaskRunner> runner)
+    scoped_refptr<base::SequencedTaskRunner> runner,
+    const char* primary_interface_name)
     : set_interface_id_namespace_bit_(set_interface_id_namespace_bit),
       task_runner_(runner),
       dispatcher_(this),
       connector_(std::move(message_pipe),
                  config == MULTI_INTERFACE ? Connector::MULTI_THREADED_SEND
                                            : Connector::SINGLE_THREADED_SEND,
-                 std::move(runner)),
+                 std::move(runner),
+                 primary_interface_name),
       control_message_handler_(this),
       control_message_proxy_(&connector_) {
   DCHECK(task_runner_->RunsTasksInCurrentSequence());
@@ -352,6 +355,14 @@ MultiplexRouter::MultiplexRouter(
       std::make_unique<MessageHeaderValidator>();
   header_validator_ = header_validator.get();
   dispatcher_.SetValidator(std::move(header_validator));
+
+  if (primary_interface_name) {
+    DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
+    header_validator_->SetDescription(base::JoinString(
+        {primary_interface_name, "[primary] MessageHeaderValidator"}, " "));
+    control_message_handler_.SetDescription(base::JoinString(
+        {primary_interface_name, "[primary] PipeControlMessageHandler"}, " "));
+  }
 }
 
 MultiplexRouter::~MultiplexRouter() {
@@ -369,15 +380,6 @@ void MultiplexRouter::SetIncomingMessageFilter(
   dispatcher_.SetFilter(std::move(filter));
 }
 
-void MultiplexRouter::SetPrimaryInterfaceName(const char* name) {
-  DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
-  header_validator_->SetDescription(std::string(name) +
-                                    " [primary] MessageHeaderValidator");
-  control_message_handler_.SetDescription(
-      std::string(name) + " [primary] PipeControlMessageHandler");
-  connector_.SetWatcherHeapProfilerTag(name);
-}
-
 void MultiplexRouter::SetConnectionGroup(ConnectionGroup::Ref ref) {
   connector_.SetConnectionGroup(std::move(ref));
 }

mojo/public/cpp/bindings/lib/multiplex_router.h

@@ -79,17 +79,13 @@ class COMPONENT_EXPORT(MOJO_CPP_BINDINGS) MultiplexRouter
   MultiplexRouter(ScopedMessagePipeHandle message_pipe,
                   Config config,
                   bool set_interface_id_namespace_bit,
-                  scoped_refptr<base::SequencedTaskRunner> runner);
+                  scoped_refptr<base::SequencedTaskRunner> runner,
+                  const char* primary_interface_name = "unknown interface");
 
   // Sets a MessageReceiver which can filter a message after validation but
   // before dispatch.
   void SetIncomingMessageFilter(std::unique_ptr<MessageFilter> filter);
 
-  // Sets the primary interface name for this router. Only used when reporting
-  // message header or control message validation errors.
-  // |name| must be a string literal.
-  void SetPrimaryInterfaceName(const char* name);
-
   // Adds this object to a ConnectionGroup identified by |ref|. All receiving
   // pipe endpoints decoded from inbound messages on this MultiplexRouter will
   // be added to the same group.

mojo/public/cpp/system/simple_watcher.cc

@@ -9,6 +9,7 @@
 #include "base/memory/ptr_util.h"
 #include "base/sequenced_task_runner.h"
 #include "base/synchronization/lock.h"
+#include "base/task/common/task_annotator.h"
 #include "base/threading/thread_task_runner_handle.h"
 #include "base/trace_event/heap_profiler.h"
 #include "base/trace_event/trace_event.h"
@@ -30,9 +31,10 @@ class SimpleWatcher::Context : public base::RefCountedThreadSafe<Context> {
       MojoHandleSignals signals,
       MojoTriggerCondition condition,
       int watch_id,
-      MojoResult* result) {
+      MojoResult* result,
+      const char* heap_profiler_tag) {
     scoped_refptr<Context> context =
-        new Context(watcher, task_runner, watch_id);
+        new Context(watcher, task_runner, watch_id, heap_profiler_tag);
 
     // If MojoAddTrigger succeeds, it effectively assumes ownership of a
     // reference to |context|. In that case, this reference is balanced in
@@ -67,10 +69,12 @@ class SimpleWatcher::Context : public base::RefCountedThreadSafe<Context> {
 
   Context(base::WeakPtr<SimpleWatcher> weak_watcher,
           scoped_refptr<base::SequencedTaskRunner> task_runner,
-          int watch_id)
+          int watch_id,
+          const char* heap_profiler_tag)
       : weak_watcher_(weak_watcher),
         task_runner_(task_runner),
-        watch_id_(watch_id) {}
+        watch_id_(watch_id),
+        heap_profiler_tag_(heap_profiler_tag) {}
 
   ~Context() = default;
 
@@ -87,28 +91,37 @@ class SimpleWatcher::Context : public base::RefCountedThreadSafe<Context> {
       // the default task runner for the IO thread.
       weak_watcher_->OnHandleReady(watch_id_, result, state);
     } else {
-      task_runner_->PostTask(
-          FROM_HERE, base::BindOnce(&SimpleWatcher::OnHandleReady,
-                                    weak_watcher_, watch_id_, result, state));
+      {
+        // Annotate the posted task with |heap_profiler_tag_| as the IPC
+        // interface.
+        base::TaskAnnotator::ScopedSetIpcHash scoped_set_ipc_hash(
+            heap_profiler_tag_);
+        task_runner_->PostTask(
+            FROM_HERE, base::BindOnce(&SimpleWatcher::OnHandleReady,
+                                      weak_watcher_, watch_id_, result, state));
+      }
     }
   }
 
   const base::WeakPtr<SimpleWatcher> weak_watcher_;
   const scoped_refptr<base::SequencedTaskRunner> task_runner_;
   const int watch_id_;
+  const char* heap_profiler_tag_ = nullptr;
 
   DISALLOW_COPY_AND_ASSIGN(Context);
 };
 
 SimpleWatcher::SimpleWatcher(const base::Location& from_here,
                              ArmingPolicy arming_policy,
-                             scoped_refptr<base::SequencedTaskRunner> runner)
+                             scoped_refptr<base::SequencedTaskRunner> runner,
+                             const char* heap_profiler_tag)
     : arming_policy_(arming_policy),
       task_runner_(std::move(runner)),
       is_default_task_runner_(base::ThreadTaskRunnerHandle::IsSet() &&
                               task_runner_ ==
                                   base::ThreadTaskRunnerHandle::Get()),
-      heap_profiler_tag_(from_here.file_name()) {
+      heap_profiler_tag_(heap_profiler_tag ? heap_profiler_tag
+                                           : from_here.file_name()) {
   MojoResult rv = CreateTrap(&Context::CallNotify, &trap_handle_);
   DCHECK_EQ(MOJO_RESULT_OK, rv);
   DCHECK(task_runner_->RunsTasksInCurrentSequence());
@@ -139,7 +152,7 @@ MojoResult SimpleWatcher::Watch(Handle handle,
   MojoResult result = MOJO_RESULT_UNKNOWN;
   context_ = Context::Create(weak_factory_.GetWeakPtr(), task_runner_,
                              trap_handle_.get(), handle_, signals, condition,
-                             watch_id_, &result);
+                             watch_id_, &result, heap_profiler_tag_);
   if (!context_) {
     handle_.set_value(kInvalidHandleValue);
     callback_.Reset();
@@ -216,10 +229,15 @@ void SimpleWatcher::ArmOrNotify() {
     return;
 
   DCHECK_EQ(MOJO_RESULT_FAILED_PRECONDITION, rv);
-  task_runner_->PostTask(
-      FROM_HERE,
-      base::BindOnce(&SimpleWatcher::OnHandleReady, weak_factory_.GetWeakPtr(),
-                     watch_id_, ready_result, ready_state));
+  {
+    // Annotate the posted task with |heap_profiler_tag_| as the IPC interface.
+    base::TaskAnnotator::ScopedSetIpcHash scoped_set_ipc_hash(
+        heap_profiler_tag_);
+    task_runner_->PostTask(FROM_HERE,
+                           base::BindOnce(&SimpleWatcher::OnHandleReady,
+                                          weak_factory_.GetWeakPtr(), watch_id_,
+                                          ready_result, ready_state));
+  }
 }
 
 void SimpleWatcher::OnHandleReady(int watch_id,
@@ -263,5 +281,4 @@ void SimpleWatcher::OnHandleReady(int watch_id,
       ArmOrNotify();
   }
 }
-
 }  // namespace mojo

mojo/public/cpp/system/simple_watcher.h

@@ -89,7 +89,8 @@ class MOJO_CPP_SYSTEM_EXPORT SimpleWatcher {
   SimpleWatcher(const base::Location& from_here,
                 ArmingPolicy arming_policy,
                 scoped_refptr<base::SequencedTaskRunner> runner =
-                    base::SequencedTaskRunnerHandle::Get());
+                    base::SequencedTaskRunnerHandle::Get(),
+                const char* heap_profiler_tag = nullptr);
   ~SimpleWatcher();
 
   // Indicates if the SimpleWatcher is currently watching a handle.
@@ -179,12 +180,6 @@ class MOJO_CPP_SYSTEM_EXPORT SimpleWatcher {
   Handle handle() const { return handle_; }
   ReadyCallbackWithState ready_callback() const { return callback_; }
 
-  // Sets the tag used by the heap profiler.
-  // |tag| must be a const string literal.
-  void set_heap_profiler_tag(const char* heap_profiler_tag) {
-    heap_profiler_tag_ = heap_profiler_tag;
-  }
-
  private:
   class Context;
 

third_party/blink/common/features.cc

@@ -771,5 +771,8 @@ const char kBackForwardCacheABExperimentGroup[] =
 const base::Feature kPreferCompositingToLCDText = {
     "PreferCompositingToLCDText", base::FEATURE_DISABLED_BY_DEFAULT};
 
+const base::Feature kLogUnexpectedIPCPostedToBackForwardCachedDocuments{
+    "LogUnexpectedIPCPostedToBackForwardCachedDocuments",
+    base::FEATURE_ENABLED_BY_DEFAULT};
 }  // namespace features
 }  // namespace blink

third_party/blink/public/common/features.h

@@ -315,6 +315,8 @@ extern const char kBackForwardCacheABExperimentGroup[];
 
 BLINK_COMMON_EXPORT extern const base::Feature kPreferCompositingToLCDText;
 
+BLINK_COMMON_EXPORT extern const base::Feature
+    kLogUnexpectedIPCPostedToBackForwardCachedDocuments;
 }  // namespace features
 }  // namespace blink
 

third_party/blink/renderer/platform/scheduler/DEPS

@@ -37,6 +37,7 @@ include_rules = [
   "+base/synchronization/cancellation_flag.h",
   "+base/synchronization/lock.h",
   "+base/task/common/scoped_defer_task_posting.h",
+  "+base/task/common/task_annotator.h",
   "+base/task/sequence_manager/lazy_now.h",
   "+base/task/sequence_manager/sequence_manager.h",
   "+base/task/sequence_manager/task_queue.h",

third_party/blink/renderer/platform/scheduler/main_thread/frame_scheduler_impl.cc

@@ -10,6 +10,7 @@
 #include "base/metrics/histogram_functions.h"
 #include "base/metrics/histogram_macros.h"
 #include "base/task/common/scoped_defer_task_posting.h"
+#include "base/task/common/task_annotator.h"
 #include "base/task/sequence_manager/lazy_now.h"
 #include "base/time/time.h"
 #include "base/trace_event/blame_context.h"
@@ -718,7 +719,7 @@ void FrameSchedulerImpl::ReportActiveSchedulerTrackedFeatures() {
 }
 
 base::WeakPtr<FrameSchedulerImpl>
-FrameSchedulerImpl::GetInvalidingOnBFCacheRestoreWeakPtr() {
+FrameSchedulerImpl::GetInvalidatingOnBFCacheRestoreWeakPtr() {
   return invalidating_on_bfcache_restore_weak_factory_.GetWeakPtr();
 }
 
@@ -1228,18 +1229,18 @@ void FrameSchedulerImpl::SetOnIPCTaskPostedWhileInBackForwardCacheHandler() {
           // Only log IPC tasks. IPC tasks are only logged currently as IPC
           // hash can be mapped back to a function name, and IPC tasks may
           // potentially post sensitive information.
-          if (!task.ipc_hash) {
+          if (!task.ipc_hash && !task.ipc_interface_name) {
             return;
           }
           base::ScopedDeferTaskPosting::PostOrDefer(
               task_runner, FROM_HERE,
               base::BindOnce(
                   &FrameSchedulerImpl::OnIPCTaskPostedWhileInBackForwardCache,
-                  frame_scheduler, task.ipc_hash, task.posted_from),
+                  frame_scheduler, task.ipc_hash, task.ipc_interface_name),
               base::TimeDelta());
         },
         main_thread_scheduler_->DefaultTaskRunner(),
-        GetInvalidingOnBFCacheRestoreWeakPtr()));
+        GetInvalidatingOnBFCacheRestoreWeakPtr()));
   }
 }
 
@@ -1254,7 +1255,20 @@ void FrameSchedulerImpl::DetachOnIPCTaskPostedWhileInBackForwardCacheHandler() {
 
 void FrameSchedulerImpl::OnIPCTaskPostedWhileInBackForwardCache(
     uint32_t ipc_hash,
-    const base::Location& task_from) {
+    const char* ipc_interface_name) {
+  // IPC tasks may have an IPC interface name in addition to, or instead of an
+  // IPC hash. IPC hash is known from the mojo Accept method. When IPC hash is
+  // 0, then the IPC hash must be calculated from the IPC interface name
+  // instead.
+  if (!ipc_hash) {
+    // base::HashMetricName produces a uint64; however, the MD5 hash calculation
+    // for an IPC interface name is always calculated as uint32; the IPC hash on
+    // a task is also a uint32. The calculation here is meant to mimic the
+    // calculation used in base::MD5Hash32Constexpr.
+    ipc_hash = base::TaskAnnotator::ScopedSetIpcHash::MD5HashMetricName(
+        ipc_interface_name);
+  }
+
   DCHECK(parent_page_scheduler_->IsStoredInBackForwardCache());
   base::UmaHistogramSparse(
       "BackForwardCache.Experimental.UnexpectedIPCMessagePostedToCachedFrame."

third_party/blink/renderer/platform/scheduler/main_thread/frame_scheduler_impl.h

@@ -142,7 +142,7 @@ class PLATFORM_EXPORT FrameSchedulerImpl : public FrameScheduler,
 
   base::WeakPtr<FrameScheduler> GetWeakPtr() override;
   base::WeakPtr<const FrameSchedulerImpl> GetWeakPtr() const;
-  base::WeakPtr<FrameSchedulerImpl> GetInvalidingOnBFCacheRestoreWeakPtr();
+  base::WeakPtr<FrameSchedulerImpl> GetInvalidatingOnBFCacheRestoreWeakPtr();
 
   void ReportActiveSchedulerTrackedFeatures() override;
 
@@ -184,7 +184,7 @@ class PLATFORM_EXPORT FrameSchedulerImpl : public FrameScheduler,
   void SetOnIPCTaskPostedWhileInBackForwardCacheHandler();
   void DetachOnIPCTaskPostedWhileInBackForwardCacheHandler();
   void OnIPCTaskPostedWhileInBackForwardCache(uint32_t ipc_hash,
-                                              const base::Location& task_from);
+                                              const char* ipc_interface_name);
 
   // Returns the list of active features which currently tracked by the
   // scheduler for back-forward cache metrics.

third_party/blink/renderer/platform/scheduler/main_thread/frame_scheduler_impl_unittest.cc

@@ -1263,6 +1263,58 @@ TEST_F(FrameSchedulerImplTest, SubesourceLoadingPaused) {
       worker_throttled_count, worker_stopped_count);
 }
 
+TEST_F(FrameSchedulerImplTest, LogIpcsPostedToFramesInBackForwardCache) {
+  base::HistogramTester histogram_tester;
+
+  // Create the task queue implicitly.
+  const scoped_refptr<base::SingleThreadTaskRunner> task_runner =
+      frame_scheduler_->GetTaskRunner(TaskType::kInternalTest);
+
+  StorePageInBackForwardCache();
+
+  // Run the tasks so that they are recorded in the histogram
+  task_environment_.FastForwardBy(base::TimeDelta::FromHours(1));
+
+  // Post IPC tasks, accounting for delay for when tracking starts.
+  {
+    base::TaskAnnotator::ScopedSetIpcHash scoped_set_ipc_hash(1);
+    task_runner->PostTask(FROM_HERE, base::DoNothing());
+  }
+  {
+    base::TaskAnnotator::ScopedSetIpcHash scoped_set_ipc_hash_2(2);
+    task_runner->PostTask(FROM_HERE, base::DoNothing());
+  }
+  task_environment_.RunUntilIdle();
+
+  // Once the page is restored from the cache, IPCs should no longer be
+  // recorded.
+  RestorePageFromBackForwardCache();
+
+  // Start posting tasks immediately - will not be recorded
+  {
+    base::TaskAnnotator::ScopedSetIpcHash scoped_set_ipc_hash_3(3);
+    task_runner->PostTask(FROM_HERE, base::DoNothing());
+  }
+  {
+    base::TaskAnnotator::ScopedSetIpcHash scoped_set_ipc_hash_4(4);
+    task_runner->PostTask(FROM_HERE, base::DoNothing());
+  }
+
+  EXPECT_THAT(
+      histogram_tester.GetAllSamples(
+          "BackForwardCache.Experimental."
+          "UnexpectedIPCMessagePostedToCachedFrame.MethodHash"),
+      testing::UnorderedElementsAre(base::Bucket(1, 1), base::Bucket(2, 1)));
+
+  // TimeUntilIPCReceived should have values in the 300000 bucket corresponding
+  // with the hour delay in task_environment_.FastForwardBy.
+  EXPECT_THAT(
+      histogram_tester.GetAllSamples(
+          "BackForwardCache.Experimental."
+          "UnexpectedIPCMessagePostedToCachedFrame.TimeUntilIPCReceived"),
+      testing::UnorderedElementsAre(base::Bucket(300000, 2)));
+}
+
 TEST_F(FrameSchedulerImplTest,
        LogIpcsFromMultipleThreadsPostedToFramesInBackForwardCache) {
   base::HistogramTester histogram_tester;
@@ -1282,7 +1334,7 @@ TEST_F(FrameSchedulerImplTest,
       base::BindOnce(
           [](scoped_refptr<base::SingleThreadTaskRunner> task_runner) {
             base::TaskAnnotator::ScopedSetIpcHash scoped_set_ipc_hash(1);
-            task_runner->PostTask(FROM_HERE, base::BindOnce([]() {}));
+            task_runner->PostTask(FROM_HERE, base::DoNothing());
           },
           task_runner));
   task_environment_.RunUntilIdle();
@@ -1298,7 +1350,7 @@ TEST_F(FrameSchedulerImplTest,
              base::RepeatingClosure restore_from_cache_callback) {
             {
               base::TaskAnnotator::ScopedSetIpcHash scoped_set_ipc_hash(2);
-              task_runner->PostTask(FROM_HERE, base::BindOnce([]() {}));
+              task_runner->PostTask(FROM_HERE, base::DoNothing());
             }
             {
               // Once the page is restored from the cache, ensure that the IPC
@@ -1308,7 +1360,7 @@ TEST_F(FrameSchedulerImplTest,
             }
             {
               base::TaskAnnotator::ScopedSetIpcHash scoped_set_ipc_hash(4);
-              task_runner->PostTask(FROM_HERE, base::BindOnce([]() {}));
+              task_runner->PostTask(FROM_HERE, base::DoNothing());
             }
           },
           task_runner, restore_from_cache_callback));
@@ -1320,7 +1372,7 @@ TEST_F(FrameSchedulerImplTest,
       base::BindOnce(
           [](scoped_refptr<base::SingleThreadTaskRunner> task_runner) {
             base::TaskAnnotator::ScopedSetIpcHash scoped_set_ipc_hash(5);
-            task_runner->PostTask(FROM_HERE, base::BindOnce([]() {}));
+            task_runner->PostTask(FROM_HERE, base::DoNothing());
           },
           task_runner));
   task_environment_.RunUntilIdle();
@@ -1330,16 +1382,16 @@ TEST_F(FrameSchedulerImplTest,
       base::BindOnce(
           [](scoped_refptr<base::SingleThreadTaskRunner> task_runner) {
             base::TaskAnnotator::ScopedSetIpcHash scoped_set_ipc_hash(6);
-            task_runner->PostTask(FROM_HERE, base::BindOnce([]() {}));
+            task_runner->PostTask(FROM_HERE, base::DoNothing());
           },
           task_runner));
   task_environment_.RunUntilIdle();
 
-  EXPECT_THAT(histogram_tester.GetAllSamples(
-                  "BackForwardCache.Experimental."
-                  "UnexpectedIPCMessagePostedToCachedFrame.MethodHash"),
-              testing::UnorderedElementsAreArray(
-                  {base::Bucket(1, 1), base::Bucket(2, 1)}));
+  EXPECT_THAT(
+      histogram_tester.GetAllSamples(
+          "BackForwardCache.Experimental."
+          "UnexpectedIPCMessagePostedToCachedFrame.MethodHash"),
+      testing::UnorderedElementsAre(base::Bucket(1, 1), base::Bucket(2, 1)));
 }
 
 // TODO(farahcharab) Move priority testing to MainThreadTaskQueueTest after

third_party/blink/renderer/platform/scheduler/main_thread/page_scheduler_impl.cc

@@ -68,6 +68,9 @@ constexpr base::TimeDelta kDefaultDelayForBackgroundAndNetworkIdleTabFreezing =
 constexpr base::TimeDelta kThrottledWakeUpDuration =
     base::TimeDelta::FromMilliseconds(3);
 
+constexpr base::TimeDelta kDefaultDelayForTrackingIPCsPostedToCachedFrames =
+    base::TimeDelta::FromSeconds(15);
+
 // Values coming from the field trial config are interpreted as follows:
 //   -1 is "not set". Scheduler should use a reasonable default.
 //   0 corresponds to base::nullopt.
@@ -145,6 +148,21 @@ base::TimeDelta GetDelayForBackgroundAndNetworkIdleTabFreezing() {
       kDelayForBackgroundAndNetworkIdleTabFreezingMillis.Get());
 }
 
+base::TimeDelta GetTimeToDelayIPCTrackingWhileStoredInBackForwardCache() {
+  if (base::FeatureList::IsEnabled(
+          features::kLogUnexpectedIPCPostedToBackForwardCachedDocuments)) {
+    static const base::FeatureParam<int>
+        kDelayForLoggingUnexpectedIPCPostedToBckForwardCacheMillis{
+            &features::kLogUnexpectedIPCPostedToBackForwardCachedDocuments,
+            "delay_before_tracking_ms",
+            static_cast<int>(kDefaultDelayForTrackingIPCsPostedToCachedFrames
+                                 .InMilliseconds())};
+    return base::TimeDelta::FromMilliseconds(
+        kDelayForLoggingUnexpectedIPCPostedToBckForwardCacheMillis.Get());
+  }
+  return kDefaultDelayForTrackingIPCsPostedToCachedFrames;
+}
+
 }  // namespace
 
 constexpr base::TimeDelta PageSchedulerImpl::kDefaultThrottledWakeUpInterval;
@@ -340,7 +358,7 @@ void PageSchedulerImpl::SetPageBackForwardCached(
         *main_thread_scheduler_->ControlTaskRunner(), FROM_HERE,
         base::BindRepeating(&PageSchedulerImpl::SetUpIPCTaskDetection,
                             GetWeakPtr()),
-        base::TimeDelta::FromSeconds(15));
+        GetTimeToDelayIPCTrackingWhileStoredInBackForwardCache());
   }
 }