0

[Extensions] Emit metric for DispatchOnConnect IPC for frames/workers.

New Metric:
  Extensions.MessagePipeline.OpenChannelWorkerDispatchStatus{DispatchTarget}{ChannelType}

This metric tracks the result of each time the DispatchOnConnect IPC is
sent to a frame or a worker. It tracks whether the message was:
  * received by the browser (acked)
  * channel/port disconnect occurred before the message was acked
  * or none of the above (hung)

Bug: 371011217
Change-Id: I35ef71c9e176feae1c8e1d4856bcec2932f1d94a
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/6065439
Commit-Queue: Justin Lulejian <jlulejian@chromium.org>
Reviewed-by: Devlin Cronin <rdevlin.cronin@chromium.org>
Auto-Submit: Justin Lulejian <jlulejian@chromium.org>
Cr-Commit-Position: refs/heads/main@{#1391446}
This commit is contained in:
Justin Lulejian
2024-12-04 04:15:35 +00:00
committed by Chromium LUCI CQ
parent 2d44793138
commit 744f465da9
6 changed files with 231 additions and 15 deletions
chrome/browser/extensions/api/messaging
extensions/browser
tools/metrics/histograms/metadata/extensions

@ -69,6 +69,7 @@ IN_PROC_BROWSER_TEST_F(MessageTrackerMessagingTest, SendMessageToWorker) {
EXPECT_TRUE(reply_listener.WaitUntilSatisfied());
// Overall channel open metrics expectations.
histogram_tester.ExpectTotalCount(
"Extensions.MessagePipeline.OpenChannelStatus.SendMessageChannel",
/*expected_count=*/1);
@ -87,7 +88,23 @@ IN_PROC_BROWSER_TEST_F(MessageTrackerMessagingTest, SendMessageToWorker) {
"Extensions.MessagePipeline.OpenChannelWorkerWakeUpStatus."
"SendMessageChannel",
/*expected_count=*/1);
// Per connect IPC dispatch metrics expectations.
histogram_tester.ExpectTotalCount(
"Extensions.MessagePipeline.OpenChannelDispatchOnConnectStatus.ForWorker",
/*expected_count=*/1);
histogram_tester.ExpectTotalCount(
"Extensions.MessagePipeline.OpenChannelDispatchOnConnectStatus.ForWorker."
"SendMessageChannel",
/*expected_count=*/1);
histogram_tester.ExpectTotalCount(
"Extensions.MessagePipeline.OpenChannelDispatchOnConnectStatus.ForFrame",
/*expected_count=*/0);
histogram_tester.ExpectTotalCount(
"Extensions.MessagePipeline.OpenChannelDispatchOnConnectStatus.ForFrame."
"SendMessageChannel",
/*expected_count=*/0);
// Overall channel open metrics expectations.
histogram_tester.ExpectBucketCount(
"Extensions.MessagePipeline.OpenChannelStatus.SendMessageChannel",
/*sample=*/MessageTracker::OpenChannelMessagePipelineResult::kOpened,
@ -108,6 +125,18 @@ IN_PROC_BROWSER_TEST_F(MessageTrackerMessagingTest, SendMessageToWorker) {
/*sample=*/
MessageTracker::OpenChannelMessagePipelineResult::kWorkerStarted,
/*expected_count=*/1);
// Per connect IPC dispatch metrics expectations.
histogram_tester.ExpectBucketCount(
"Extensions.MessagePipeline.OpenChannelDispatchOnConnectStatus.ForWorker",
/*sample=*/
MessageTracker::OpenChannelMessagePipelineResult::kOpenChannelAcked,
/*expected_count=*/1);
histogram_tester.ExpectBucketCount(
"Extensions.MessagePipeline.OpenChannelDispatchOnConnectStatus.ForWorker."
"SendMessageChannel",
/*sample=*/
MessageTracker::OpenChannelMessagePipelineResult::kOpenChannelAcked,
/*expected_count=*/1);
}
class MessageTrackerMessagingTestNonWorker
@ -185,6 +214,7 @@ IN_PROC_BROWSER_TEST_P(MessageTrackerMessagingTestNonWorker,
EXPECT_TRUE(reply_listener.WaitUntilSatisfied());
// Overall channel open metrics expectations.
histogram_tester.ExpectTotalCount(
"Extensions.MessagePipeline.OpenChannelStatus.SendMessageChannel",
/*expected_count=*/1);
@ -211,7 +241,23 @@ IN_PROC_BROWSER_TEST_P(MessageTrackerMessagingTestNonWorker,
"Extensions.MessagePipeline.OpenChannelWorkerWakeUpStatus."
"SendMessageChannel",
/*expected_count=*/0);
// Per connect IPC dispatch metrics expectations.
histogram_tester.ExpectTotalCount(
"Extensions.MessagePipeline.OpenChannelDispatchOnConnectStatus.ForWorker",
/*expected_count=*/0);
histogram_tester.ExpectTotalCount(
"Extensions.MessagePipeline.OpenChannelDispatchOnConnectStatus.ForWorker."
"SendMessageChannel",
/*expected_count=*/0);
histogram_tester.ExpectTotalCount(
"Extensions.MessagePipeline.OpenChannelDispatchOnConnectStatus.ForFrame",
/*expected_count=*/1);
histogram_tester.ExpectTotalCount(
"Extensions.MessagePipeline.OpenChannelDispatchOnConnectStatus.ForFrame."
"SendMessageChannel",
/*expected_count=*/1);
// Overall channel open metrics expectations.
histogram_tester.ExpectBucketCount(
"Extensions.MessagePipeline.OpenChannelStatus.SendMessageChannel",
/*sample=*/MessageTracker::OpenChannelMessagePipelineResult::kOpened,
@ -221,6 +267,18 @@ IN_PROC_BROWSER_TEST_P(MessageTrackerMessagingTestNonWorker,
"SendMessageChannel",
/*sample=*/MessageTracker::OpenChannelMessagePipelineResult::kOpened,
/*expected_count=*/1);
// Per connect IPC dispatch metrics expectations.
histogram_tester.ExpectBucketCount(
"Extensions.MessagePipeline.OpenChannelDispatchOnConnectStatus.ForFrame",
/*sample=*/
MessageTracker::OpenChannelMessagePipelineResult::kOpenChannelAcked,
/*expected_count=*/1);
histogram_tester.ExpectBucketCount(
"Extensions.MessagePipeline.OpenChannelDispatchOnConnectStatus.ForFrame."
"SendMessageChannel",
/*sample=*/
MessageTracker::OpenChannelMessagePipelineResult::kOpenChannelAcked,
/*expected_count=*/1);
}
INSTANTIATE_TEST_SUITE_P(EventPage,
@ -330,6 +388,7 @@ IN_PROC_BROWSER_TEST_F(MessageTrackerMessagingTest, SendMessageToTabAndWorker) {
ASSERT_TRUE(reply_listener.WaitUntilSatisfied());
ASSERT_TRUE(ext_tab_listener_fired.WaitUntilSatisfied());
// Overall channel open metrics expectations.
histogram_tester.ExpectTotalCount(
"Extensions.MessagePipeline.OpenChannelStatus.SendMessageChannel",
/*expected_count=*/1);
@ -348,7 +407,23 @@ IN_PROC_BROWSER_TEST_F(MessageTrackerMessagingTest, SendMessageToTabAndWorker) {
"Extensions.MessagePipeline.OpenChannelWorkerWakeUpStatus."
"SendMessageChannel",
/*expected_count=*/1);
// Per connect IPC dispatch metrics expectations.
histogram_tester.ExpectTotalCount(
"Extensions.MessagePipeline.OpenChannelDispatchOnConnectStatus.ForWorker",
/*expected_count=*/1);
histogram_tester.ExpectTotalCount(
"Extensions.MessagePipeline.OpenChannelDispatchOnConnectStatus.ForWorker."
"SendMessageChannel",
/*expected_count=*/1);
histogram_tester.ExpectTotalCount(
"Extensions.MessagePipeline.OpenChannelDispatchOnConnectStatus.ForFrame",
/*expected_count=*/1);
histogram_tester.ExpectTotalCount(
"Extensions.MessagePipeline.OpenChannelDispatchOnConnectStatus.ForFrame."
"SendMessageChannel",
/*expected_count=*/1);
// Overall channel open metrics expectations.
histogram_tester.ExpectBucketCount(
"Extensions.MessagePipeline.OpenChannelStatus.SendMessageChannel",
/*sample=*/MessageTracker::OpenChannelMessagePipelineResult::kOpened,
@ -369,6 +444,9 @@ IN_PROC_BROWSER_TEST_F(MessageTrackerMessagingTest, SendMessageToTabAndWorker) {
/*sample=*/
MessageTracker::OpenChannelMessagePipelineResult::kWorkerStarted,
/*expected_count=*/1);
// Per connect IPC dispatch metrics expectations cannot be specified in this
// test because the channel will be closed by the first port responder to the
// IPC and that will can change the value emitted for the other port.
}
// TODO(crbug.com/371011217): Once we start tracking message dispatch metrics

@ -29,6 +29,7 @@
#include "extensions/browser/api/messaging/channel_endpoint.h"
#include "extensions/browser/extension_host.h"
#include "extensions/browser/extension_web_contents_observer.h"
#include "extensions/browser/extensions_browser_client.h"
#include "extensions/browser/message_tracker.h"
#include "extensions/browser/process_manager.h"
#include "extensions/browser/process_manager_observer.h"
@ -251,14 +252,18 @@ std::unique_ptr<ExtensionMessagePort> ExtensionMessagePort::CreateForEndpoint(
receiver.Bind(std::move(message_port));
receiver.set_disconnect_handler(base::BindOnce(&ExtensionMessagePort::Prune,
base::Unretained(port.get()),
endpoint.port_context()));
endpoint.port_context(),
// Unused for endpoints.
base::UnguessableToken()));
} else {
port->frame_tracker_->TrackExtensionProcessFrames();
auto& receiver = port->service_workers_[endpoint.GetWorkerId()];
receiver.Bind(std::move(message_port));
receiver.set_disconnect_handler(base::BindOnce(&ExtensionMessagePort::Prune,
base::Unretained(port.get()),
endpoint.port_context()));
endpoint.port_context(),
// Unused for endpoints.
base::UnguessableToken()));
}
port->AddReceiver(std::move(message_port_host), endpoint.render_process_id(),
endpoint.port_context());
@ -275,9 +280,28 @@ ExtensionMessagePort::ExtensionMessagePort(
extension_id_(extension_id),
browser_context_(browser_context) {}
ExtensionMessagePort::~ExtensionMessagePort() = default;
ExtensionMessagePort::~ExtensionMessagePort() {
// We aren't interested in metrics when the browser is shutting down.
ExtensionsBrowserClient* browser_client = ExtensionsBrowserClient::Get();
if (!browser_client || !browser_client->IsValidContext(browser_context_)) {
return;
}
void ExtensionMessagePort::Prune(const PortContext& port_context) {
// Emit per connect dispatch IPC metric before class is destroyed.
auto* message_tracker = MessageTracker::Get(browser_context_);
for (const auto& tracking_id :
pending_open_channel_connect_dispatch_tracking_ids_) {
message_tracker->StopTrackingMessagingStage(
tracking_id, MessageTracker::OpenChannelMessagePipelineResult::
kOpenChannelClosedBeforeResponse);
}
pending_open_channel_connect_dispatch_tracking_ids_.clear();
}
void ExtensionMessagePort::Prune(
const PortContext& port_context,
const base::UnguessableToken& connect_dispatch_tracking_id) {
std::vector<content::GlobalRenderFrameHostToken> frames_to_unregister;
// Channel metrics tracking.
@ -290,6 +314,14 @@ void ExtensionMessagePort::Prune(const PortContext& port_context) {
kOpenChannelDispatchNoReceivers);
}
// Per channel open connect IPC dispatch metrics tracking.
if (!connect_dispatch_tracking_id.is_empty()) {
ReportOpenChannelConnectDispatchResult(
connect_dispatch_tracking_id,
MessageTracker::OpenChannelMessagePipelineResult::
kOpenChannelPortDisconnectedBeforeResponse);
}
for (auto& frame : frames_) {
if (!frame.second.is_connected()) {
frames_to_unregister.push_back(frame.first);
@ -316,9 +348,12 @@ void ExtensionMessagePort::Prune(const PortContext& port_context) {
void ExtensionMessagePort::ReportOpenChannelResult(
MessageTracker::OpenChannelMessagePipelineResult emit_value) {
// TODO(crbug.com/371011217): Cache this as a member var to avoid fetching it
// in so many places.
auto* message_tracker = MessageTracker::Get(browser_context_);
// MessageTracker ensures the metrics can only emit once (e.g. if
// OnConnectResponse() is called after this)
// another method calls this method again after this).
for (const auto& tracking_id : pending_open_channel_tracking_ids_) {
message_tracker->StopTrackingMessagingStage(tracking_id, emit_value);
}
@ -326,6 +361,18 @@ void ExtensionMessagePort::ReportOpenChannelResult(
pending_open_channel_tracking_ids_.clear();
}
void ExtensionMessagePort::ReportOpenChannelConnectDispatchResult(
const base::UnguessableToken& tracking_id,
MessageTracker::OpenChannelMessagePipelineResult emit_value) {
auto* message_tracker = MessageTracker::Get(browser_context_);
// MessageTracker ensures the metrics can only emit once (e.g. if
// another method calls this method again after this).
message_tracker->StopTrackingMessagingStage(tracking_id, emit_value);
pending_open_channel_connect_dispatch_tracking_ids_.erase(tracking_id);
}
void ExtensionMessagePort::RemoveCommonFrames(const MessagePort& port) {
// This should be called before OnConnect is called.
CHECK(frames_.empty());
@ -437,11 +484,24 @@ void ExtensionMessagePort::DispatchOnConnect(
mojo::PendingAssociatedReceiver<mojom::MessagePort> message_port;
mojo::PendingAssociatedRemote<mojom::MessagePortHost> message_port_host;
// Per channel open connect IPC dispatch metrics to frame.
base::UnguessableToken open_channel_dispatch_for_frame_tracking_id(
base::UnguessableToken::Create());
pending_open_channel_connect_dispatch_tracking_ids_.insert(
open_channel_dispatch_for_frame_tracking_id);
auto* message_tracker = MessageTracker::Get(browser_context_);
message_tracker->StartTrackingMessagingStage(
open_channel_dispatch_for_frame_tracking_id,
"Extensions.MessagePipeline.OpenChannelDispatchOnConnectStatus."
"ForFrame",
channel_type);
PortContext port_context = PortContext::ForFrame(frame->GetRoutingID());
auto& receiver = frames_[frame_token];
receiver.Bind(message_port.InitWithNewEndpointAndPassRemote());
receiver.set_disconnect_handler(base::BindOnce(
&ExtensionMessagePort::Prune, base::Unretained(this), port_context));
&ExtensionMessagePort::Prune, base::Unretained(this), port_context,
open_channel_dispatch_for_frame_tracking_id));
AddReceiver(message_port_host.InitWithNewEndpointAndPassReceiver(),
frame->GetProcess()->GetID(), port_context);
@ -454,7 +514,8 @@ void ExtensionMessagePort::DispatchOnConnect(
port_id_, channel_type, channel_name, source.Clone(), info.Clone(),
std::move(message_port), std::move(message_port_host),
base::BindOnce(&ExtensionMessagePort::OnConnectResponse,
weak_ptr_factory_.GetWeakPtr(), port_context));
weak_ptr_factory_.GetWeakPtr(), port_context,
open_channel_dispatch_for_frame_tracking_id));
}
for (const auto& worker : pending_service_workers_) {
auto* host = ServiceWorkerHost::GetWorkerFor(worker);
@ -466,13 +527,26 @@ void ExtensionMessagePort::DispatchOnConnect(
mojo::PendingAssociatedReceiver<mojom::MessagePort> message_port;
mojo::PendingAssociatedRemote<mojom::MessagePortHost> message_port_host;
// Per channel open connect IPC dispatch metrics to worker.
base::UnguessableToken open_channel_dispatch_for_worker_tracking_id(
base::UnguessableToken::Create());
pending_open_channel_connect_dispatch_tracking_ids_.insert(
open_channel_dispatch_for_worker_tracking_id);
auto* message_tracker = MessageTracker::Get(browser_context_);
message_tracker->StartTrackingMessagingStage(
open_channel_dispatch_for_worker_tracking_id,
"Extensions.MessagePipeline.OpenChannelDispatchOnConnectStatus."
"ForWorker",
channel_type);
PortContext port_context =
PortContext::ForWorker(worker.thread_id, worker.version_id,
worker.render_process_id, worker.extension_id);
auto& receiver = service_workers_[worker];
receiver.Bind(message_port.InitWithNewEndpointAndPassRemote());
receiver.set_disconnect_handler(base::BindOnce(
&ExtensionMessagePort::Prune, base::Unretained(this), port_context));
&ExtensionMessagePort::Prune, base::Unretained(this), port_context,
open_channel_dispatch_for_worker_tracking_id));
AddReceiver(message_port_host.InitWithNewEndpointAndPassReceiver(),
worker.render_process_id, port_context);
@ -482,22 +556,25 @@ void ExtensionMessagePort::DispatchOnConnect(
port_id_, channel_type, channel_name, source.Clone(), info.Clone(),
std::move(message_port), std::move(message_port_host),
base::BindOnce(&ExtensionMessagePort::OnConnectResponse,
weak_ptr_factory_.GetWeakPtr(), port_context));
weak_ptr_factory_.GetWeakPtr(), port_context,
open_channel_dispatch_for_worker_tracking_id));
}
}
pending_frames_.clear();
pending_service_workers_.clear();
}
void ExtensionMessagePort::OnConnectResponse(const PortContext& port_context,
bool success) {
void ExtensionMessagePort::OnConnectResponse(
const PortContext& port_context,
const base::UnguessableToken& connect_dispatch_tracking_id,
bool success) {
// For the unsuccessful case the port will be cleaned up in `Prune` when
// the mojo channels are disconnected.
if (success) {
port_was_created_ = true;
}
// Channel open metrics tracking
// Overall channel open metrics tracking
pending_contexts_to_respond_.erase(port_context);
// Channel is considered opened if one response indicated that the port was
@ -511,6 +588,12 @@ void ExtensionMessagePort::OnConnectResponse(const PortContext& port_context,
: MessageTracker::OpenChannelMessagePipelineResult::
kOpenChannelDispatchNoReceivers);
}
// Per channel open connect IPC dispatch metrics tracking.
ReportOpenChannelConnectDispatchResult(
connect_dispatch_tracking_id,
MessageTracker::OpenChannelMessagePipelineResult::kOpenChannelAcked);
// We'll continue tracking the messaging pipeline in MessageService where
// we'll track each dispatched message for this (now open) channel.
}

@ -147,12 +147,20 @@ class ExtensionMessagePort : public MessagePort {
bool ShouldSkipFrameForBFCache(content::RenderFrameHost* render_frame_host);
void OnConnectResponse(const PortContext& port_context, bool success);
void Prune(const PortContext& port_context);
void OnConnectResponse(
const PortContext& port_context,
const base::UnguessableToken& connect_dispatch_tracking_id,
bool success);
void Prune(const PortContext& port_context,
const base::UnguessableToken& connect_dispatch_tracking_id);
void ReportOpenChannelResult(
MessageTracker::OpenChannelMessagePipelineResult emit_value);
void ReportOpenChannelConnectDispatchResult(
const base::UnguessableToken& tracking_id,
MessageTracker::OpenChannelMessagePipelineResult emit_value);
ExtensionId extension_id_;
raw_ptr<content::BrowserContext> browser_context_ = nullptr;
@ -206,6 +214,10 @@ class ExtensionMessagePort : public MessagePort {
// Tracking ID to every metric to emit once the result of the channel opening
// is determined.
std::set<base::UnguessableToken> pending_open_channel_tracking_ids_;
// Tracking ID to every metric to emit if the channel (this class) closes
// (destructs) before each port has responded to DispatchOnConnect IPC.
std::set<base::UnguessableToken>
pending_open_channel_connect_dispatch_tracking_ids_;
base::WeakPtrFactory<ExtensionMessagePort> weak_ptr_factory_{this};
};

@ -30,8 +30,16 @@ class MessageTracker : public KeyedService {
public:
enum class OpenChannelMessagePipelineResult {
kUnknown = 0,
// At least one endpoint accepted the connection and the channel was opened.
kOpened = 1,
// Multi-use value meaning that the stage did not occur before
// stage_timeout_ was reached.
kHung = 2,
// The channel was not opened due to one of theses issues. See enums.xml for
// more details.
kNoReceivers = 3,
kOpenChannelToNonEnabledExtension = 4,
kNotExternallyConnectable = 5,
@ -39,7 +47,16 @@ class MessageTracker : public KeyedService {
kWillNotOpenChannel = 7,
kOpenChannelReceiverInvalidPort = 8,
kOpenChannelDispatchNoReceivers = 9,
kMaxValue = kOpenChannelDispatchNoReceivers,
// The DispatchConnect IPC was acknowledged back to the browser.
kOpenChannelAcked = 10,
// The DispatchConnect IPC was not acknowledged because the remote
// (renderer) was disconnected.
kOpenChannelPortDisconnectedBeforeResponse = 11,
// The DispatchConnect IPC was not acknowledged because the channel closed.
kOpenChannelClosedBeforeResponse = 12,
kMaxValue = kOpenChannelClosedBeforeResponse,
};
class TestObserver {

@ -3386,6 +3386,9 @@ Called by update_extension_permission.py.-->
<int value="8" label="Channel not opened (receiver port isn't valid)"/>
<int value="9"
label="Channel not opened (dispatched connect, but no port created)"/>
<int value="10" label="Open channel acked"/>
<int value="11" label="Port disconnected before response"/>
<int value="12" label="Channel closed before response"/>
</enum>
<enum name="ReadDynamicRulesJSONStatus">

@ -3936,6 +3936,29 @@ This is emitted for two scenarios when a worker may be unregistered:
<token key="ManifestLocation" variants="ManifestLocationGroupWithCombos"/>
</histogram>
<histogram
name="Extensions.MessagePipeline.OpenChannelDispatchOnConnectStatus{DispatchTarget}{ChannelType}"
enum="OpenChannelMessagePipelineResult" expires_after="2025-04-25">
<owner>jlulejian@chromium.org</owner>
<owner>extensions-core@chromium.org</owner>
<summary>
Tracks that for every IPC we dispatch to create a port for a messaging
channel in the renderer whether it responded, or if the channel or port
closed before the ack could be received.
Emitted each time a (LocalFrame::|ServiceWorker::)DispatchOnConnect IPC is
dispatched to a {DispatchTarget}. This occurs once for every available frame
and worker in the extension when a channel is opened to an extension.
It is permuted by channel type (message type). {ChannelType}.
</summary>
<token key="DispatchTarget">
<variant name="ForFrame" summary="frame"/>
<variant name="ForWorker" summary="worker"/>
</token>
<token key="ChannelType" variants="ChannelType"/>
</histogram>
<histogram
name="Extensions.MessagePipeline.OpenChannelStatus{WorkerStatus}{ChannelType}"
enum="OpenChannelMessagePipelineResult" expires_after="2025-04-25">