0

[tracing] Plumb event id between histogram samples, slices and triggers.

This CL adds a histogram scoper to connect flow id to observers,
to links histogram samples to semantically related events in tracing.
This is more robust and extensible than the previous solution
based on hashing histogram names.

Bug: 40257548
Change-Id: Ib1d5d5da42c84ff548a16b622f8932eb5dd206ba
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/6233616
Reviewed-by: Gabriel Charette <gab@chromium.org>
Reviewed-by: Dave Tapuska <dtapuska@chromium.org>
Commit-Queue: Etienne Pierre-Doray <etiennep@chromium.org>
Reviewed-by: Giovanni Ortuno Urquidi <ortuno@chromium.org>
Cr-Commit-Position: refs/heads/main@{#1418857}
This commit is contained in:
Etienne Pierre-doray
2025-02-11 12:51:21 -08:00
committed by Chromium LUCI CQ
parent af3c4fb362
commit 226632b457
21 changed files with 215 additions and 125 deletions

@ -872,6 +872,8 @@ component("base") {
"trace_event/heap_profiler_allocation_context.h",
"trace_event/heap_profiler_allocation_context_tracker.cc",
"trace_event/heap_profiler_allocation_context_tracker.h",
"trace_event/histogram_scope.cc",
"trace_event/histogram_scope.h",
"trace_event/memory_allocator_dump_guid.cc",
"trace_event/memory_allocator_dump_guid.h",
"trace_event/named_trigger.cc",

@ -0,0 +1,31 @@
// Copyright 2025 The Chromium Authors
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.
#include "base/trace_event/histogram_scope.h"
namespace base::trace_event {
namespace {
thread_local uint64_t g_histogram_flow_id = 0;
}
HistogramScope::HistogramScope(uint64_t flow_id) : flow_id_(flow_id) {
DCHECK_EQ(g_histogram_flow_id, 0U);
g_histogram_flow_id = flow_id_;
}
HistogramScope::~HistogramScope() {
DCHECK_EQ(g_histogram_flow_id, flow_id_);
g_histogram_flow_id = 0;
}
std::optional<uint64_t> HistogramScope::GetFlowId() {
if (g_histogram_flow_id == 0) {
return std::nullopt;
}
return g_histogram_flow_id;
}
} // namespace base::trace_event

@ -0,0 +1,34 @@
// Copyright 2025 The Chromium Authors
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.
#ifndef BASE_TRACE_EVENT_HISTOGRAM_SCOPE_H_
#define BASE_TRACE_EVENT_HISTOGRAM_SCOPE_H_
#include <stdint.h>
#include <optional>
#include <string>
#include "base/base_export.h"
#include "base/trace_event/base_tracing.h"
namespace base::trace_event {
// Associates histograms in this scope with a `flow_id` in traces.
class BASE_EXPORT HistogramScope {
public:
explicit HistogramScope(uint64_t flow_id);
HistogramScope(const HistogramScope&) = delete;
HistogramScope& operator=(const HistogramScope&) = delete;
~HistogramScope();
static std::optional<uint64_t> GetFlowId();
private:
uint64_t flow_id_;
};
} // namespace base::trace_event
#endif // BASE_TRACE_EVENT_HISTOGRAM_SCOPE_H_

@ -7,16 +7,23 @@
#include "base/check.h"
#include "base/hash/hash.h"
#include "base/strings/strcat.h"
#include "base/trace_event/trace_id_helper.h"
namespace base::trace_event {
namespace {
// |g_named_trigger_manager| is intentionally leaked on shutdown.
NamedTriggerManager* g_named_trigger_manager = nullptr;
} // namespace
bool EmitNamedTrigger(const std::string& trigger_name,
std::optional<int32_t> value) {
std::optional<int32_t> value,
std::optional<uint64_t> flow_id) {
if (g_named_trigger_manager) {
return g_named_trigger_manager->DoEmitNamedTrigger(trigger_name, value);
return g_named_trigger_manager->DoEmitNamedTrigger(
trigger_name, value,
flow_id.value_or(base::trace_event::GetNextGlobalTraceId()));
}
return false;
}
@ -26,15 +33,4 @@ void NamedTriggerManager::SetInstance(NamedTriggerManager* manager) {
g_named_trigger_manager = manager;
}
uint64_t TriggerFlowId(const std::string_view& name,
std::optional<int32_t> value) {
size_t name_hash = base::FastHash(name);
return base::HashInts(name_hash, static_cast<uint32_t>(value.value_or(0)));
}
perfetto::Flow TriggerFlow(const std::string_view& name,
std::optional<int32_t> value) {
return perfetto::Flow::Global(TriggerFlowId(name, value));
}
} // namespace base::trace_event

@ -21,28 +21,22 @@ inline constexpr char kStartupTracingTriggerName[] = "startup";
// trigger caused a scenario to either begin recording or finalize the trace
// depending on the config, or false if the trigger had no effect. If the
// trigger specified isn't active in the config, this will do nothing.
BASE_EXPORT bool EmitNamedTrigger(const std::string& trigger_name,
std::optional<int32_t> value = std::nullopt);
BASE_EXPORT bool EmitNamedTrigger(
const std::string& trigger_name,
std::optional<int32_t> value = std::nullopt,
std::optional<uint64_t> flow_id = std::nullopt);
class NamedTriggerManager {
public:
virtual bool DoEmitNamedTrigger(const std::string& trigger_name,
std::optional<int32_t> value) = 0;
std::optional<int32_t> value,
uint64_t flow_id) = 0;
protected:
// Sets the instance returns by GetInstance() globally to |manager|.
BASE_EXPORT static void SetInstance(NamedTriggerManager* manager);
};
// Returns a flow id that connects to a background tracing trigger.
BASE_EXPORT uint64_t TriggerFlowId(const std::string_view& name,
std::optional<int32_t> value = std::nullopt);
// Returns a perfetto flow that connects to a background tracing trigger.
BASE_EXPORT perfetto::Flow TriggerFlow(
const std::string_view& name,
std::optional<int32_t> value = std::nullopt);
} // namespace base::trace_event
#endif // BASE_TRACE_EVENT_NAMED_TRIGGER_H_

@ -9,8 +9,9 @@
#include <utility>
#include "base/functional/bind.h"
#include "base/metrics/histogram_functions.h"
#include "base/metrics/histogram_macros.h"
#include "base/trace_event/named_trigger.h"
#include "base/trace_event/histogram_scope.h"
#include "base/trace_event/trace_event.h"
#include "build/build_config.h"
#include "content/public/browser/browser_thread.h"
@ -170,27 +171,30 @@ void Calculator::OnFirstIdle() {
void Calculator::EmitResponsiveness(CongestionType congestion_type,
size_t num_congested_slices,
StartupStage startup_stage) {
StartupStage startup_stage,
uint64_t event_id) {
DCHECK_CURRENTLY_ON(BrowserThread::UI);
static constexpr size_t kMaxCongestedSlices =
kMeasurementPeriod / kCongestionThreshold;
static constexpr size_t kBucketCount = 50;
DCHECK_LE(num_congested_slices, kMaxCongestedSlices);
base::trace_event::HistogramScope scoped_event(event_id);
switch (congestion_type) {
case CongestionType::kExecutionOnly: {
UMA_HISTOGRAM_COUNTS_1000("Browser.MainThreadsCongestion.RunningOnly",
num_congested_slices);
base::UmaHistogramCustomCounts(
"Browser.MainThreadsCongestion.RunningOnly", num_congested_slices, 1,
1000, kBucketCount);
// Only kFirstInterval and kPeriodic are reported with a suffix, stages
// in between are only part of the unsuffixed histogram.
if (startup_stage_ == StartupStage::kFirstInterval) {
UMA_HISTOGRAM_COUNTS_1000(
base::UmaHistogramCustomCounts(
"Browser.MainThreadsCongestion.RunningOnly.Initial",
num_congested_slices);
num_congested_slices, 1, 1000, kBucketCount);
} else if (startup_stage_ == StartupStage::kPeriodic) {
UMA_HISTOGRAM_COUNTS_1000(
base::UmaHistogramCustomCounts(
"Browser.MainThreadsCongestion.RunningOnly.Periodic",
num_congested_slices);
num_congested_slices, 1, 1000, kBucketCount);
}
break;
}
@ -200,21 +204,21 @@ void Calculator::EmitResponsiveness(CongestionType congestion_type,
startup_stage_ == StartupStage::kFirstIntervalDoneWithoutFirstIdle) {
break;
}
UMA_HISTOGRAM_CUSTOM_COUNTS("Browser.MainThreadsCongestion",
num_congested_slices, 1, kMaxCongestedSlices,
kBucketCount);
base::UmaHistogramCustomCounts("Browser.MainThreadsCongestion",
num_congested_slices, 1,
kMaxCongestedSlices, kBucketCount);
if (delegate_) {
delegate_->OnResponsivenessEmitted(num_congested_slices, 1,
kMaxCongestedSlices, kBucketCount);
}
if (startup_stage_ == StartupStage::kFirstIntervalAfterFirstIdle) {
UMA_HISTOGRAM_CUSTOM_COUNTS("Browser.MainThreadsCongestion.Initial",
num_congested_slices, 1,
kMaxCongestedSlices, kBucketCount);
base::UmaHistogramCustomCounts("Browser.MainThreadsCongestion.Initial",
num_congested_slices, 1,
kMaxCongestedSlices, kBucketCount);
} else if (startup_stage_ == StartupStage::kPeriodic) {
UMA_HISTOGRAM_CUSTOM_COUNTS("Browser.MainThreadsCongestion.Periodic",
num_congested_slices, 1,
kMaxCongestedSlices, kBucketCount);
base::UmaHistogramCustomCounts("Browser.MainThreadsCongestion.Periodic",
num_congested_slices, 1,
kMaxCongestedSlices, kBucketCount);
}
break;
}
@ -226,7 +230,8 @@ void Calculator::EmitResponsivenessTraceEvents(
StartupStage startup_stage,
base::TimeTicks start_time,
base::TimeTicks end_time,
const std::set<int>& congested_slices) {
const std::set<int>& congested_slices,
uint64_t event_id) {
// Only output kCongestedIntervalsMeasurementEvent event when there are
// congested slices during the measurement.
if (congested_slices.empty()) {
@ -237,7 +242,7 @@ void Calculator::EmitResponsivenessTraceEvents(
// measurement.
if (congestion_type == CongestionType::kQueueAndExecution) {
EmitCongestedIntervalsMeasurementTraceEvent(
startup_stage, start_time, end_time, congested_slices.size());
startup_stage, start_time, end_time, congested_slices.size(), event_id);
// Since a lot of startup tasks are queue and then released, queuing
// congestion is very noisy and thus ignored before OnFirstIdle().
if (startup_stage == StartupStage::kFirstInterval ||
@ -276,16 +281,13 @@ void Calculator::EmitCongestedIntervalsMeasurementTraceEvent(
StartupStage startup_stage,
base::TimeTicks start_time,
base::TimeTicks end_time,
size_t num_congested_slices) {
size_t num_congested_slices,
uint64_t event_id) {
TRACE_EVENT_BEGIN(kLatencyEventCategory,
GetCongestedIntervalsMeasurementEvent(startup_stage),
congestion_track_, start_time);
TRACE_EVENT_END(
kLatencyEventCategory, congestion_track_, end_time,
base::trace_event::TriggerFlow("Browser.MainThreadsCongestion",
num_congested_slices),
base::trace_event::TriggerFlow(
"Browser.MainThreadsCongestion.RunningOnly", num_congested_slices));
TRACE_EVENT_END(kLatencyEventCategory, congestion_track_, end_time,
perfetto::Flow::Global(event_id));
}
void Calculator::EmitCongestedIntervalTraceEvent(CongestionType congestion_type,
@ -418,8 +420,9 @@ void Calculator::CalculateResponsiveness(
}
}
EmitResponsiveness(congestion_type, congested_slices.size(),
startup_stage_);
uint64_t event_id = base::trace_event::GetNextGlobalTraceId();
EmitResponsiveness(congestion_type, congested_slices.size(), startup_stage_,
event_id);
// If the 'latency' tracing category is enabled and we are ready to observe
// queuing times (past first idle), emit trace events for the measurement
@ -429,8 +432,8 @@ void Calculator::CalculateResponsiveness(
&latency_category_enabled);
if (latency_category_enabled) {
EmitResponsivenessTraceEvents(congestion_type, startup_stage_, start_time,
current_interval_end_time,
congested_slices);
current_interval_end_time, congested_slices,
event_id);
}
start_time = current_interval_end_time;

@ -98,7 +98,8 @@ class CONTENT_EXPORT Calculator {
// Exposed for testing.
virtual void EmitResponsiveness(CongestionType congestion_type,
size_t num_congested_slices,
StartupStage startup_stage);
StartupStage startup_stage,
uint64_t event_id);
// Emits trace events for responsiveness metric. A trace event is emitted for
// the whole duration of the metric interval and sub events are emitted for
@ -108,14 +109,16 @@ class CONTENT_EXPORT Calculator {
StartupStage startup_stage,
base::TimeTicks start_time,
base::TimeTicks end_time,
const std::set<int>& congested_slices);
const std::set<int>& congested_slices,
uint64_t event_id);
// Exposed for testing.
virtual void EmitCongestedIntervalsMeasurementTraceEvent(
StartupStage startup_stage,
base::TimeTicks start_time,
base::TimeTicks end_time,
size_t num_congested_slices);
size_t num_congested_slices,
uint64_t event_id);
// Exposed for testing.
virtual void EmitCongestedIntervalTraceEvent(CongestionType congestion_type,

@ -37,18 +37,20 @@ class FakeCalculator : public Calculator {
void EmitResponsiveness(CongestionType congestion_type,
size_t congested_slices,
StartupStage startup_stage) override {
StartupStage startup_stage,
uint64_t event_id) override {
EmitResponsivenessMock(congestion_type, congested_slices, startup_stage);
// Emit the histograms anyways for verification in some tests.
Calculator::EmitResponsiveness(congestion_type, congested_slices,
startup_stage);
startup_stage, event_id);
}
MOCK_METHOD4(EmitCongestedIntervalsMeasurementTraceEvent,
MOCK_METHOD5(EmitCongestedIntervalsMeasurementTraceEvent,
void(StartupStage startup_stage,
base::TimeTicks start_time,
base::TimeTicks end_time,
size_t num_congested_slices));
size_t num_congested_slices,
uint64_t event_id));
MOCK_METHOD3(EmitCongestedIntervalTraceEvent,
void(CongestionType congestion_type,
@ -752,13 +754,14 @@ TEST_F(ResponsivenessCalculatorTest, EmitResponsivenessTraceEventsEmpty) {
kStartTime + base::Milliseconds(kMeasurementIntervalInMs);
const std::set<int> congested_slices;
uint64_t event_id = 42;
EXPECT_CALL(*calculator_, EmitCongestedIntervalsMeasurementTraceEvent(
StartupStage::kPeriodic, _, _, _))
StartupStage::kPeriodic, _, _, _, event_id))
.Times(0);
calculator_->EmitResponsivenessTraceEvents(
CongestionType::kQueueAndExecution, StartupStage::kPeriodic, kStartTime,
kFinishTime, congested_slices);
kFinishTime, congested_slices, event_id);
}
TEST_F(ResponsivenessCalculatorTest,
@ -770,8 +773,9 @@ TEST_F(ResponsivenessCalculatorTest,
kStartTime + base::Milliseconds(kMeasurementIntervalInMs);
const std::set<int> congested_slices = {1};
uint64_t event_id = 42;
EXPECT_CALL(*calculator_, EmitCongestedIntervalsMeasurementTraceEvent(
StartupStage::kPeriodic, _, _, _))
StartupStage::kPeriodic, _, _, _, event_id))
.Times(0);
EXPECT_CALL(*calculator_,
@ -781,7 +785,7 @@ TEST_F(ResponsivenessCalculatorTest,
calculator_->EmitResponsivenessTraceEvents(
CongestionType::kExecutionOnly, StartupStage::kPeriodic, kStartTime,
kFinishTime, congested_slices);
kFinishTime, congested_slices, event_id);
}
TEST_F(ResponsivenessCalculatorTest, EmitResponsivenessTraceEvents) {
@ -793,9 +797,10 @@ TEST_F(ResponsivenessCalculatorTest, EmitResponsivenessTraceEvents) {
const std::set<int> congested_slices = {3, 4, 5, 12, 15};
uint64_t event_id = 42;
EXPECT_CALL(*calculator_,
EmitCongestedIntervalsMeasurementTraceEvent(
StartupStage::kPeriodic, kStartTime, kFinishTime, 5));
StartupStage::kPeriodic, kStartTime, kFinishTime, 5, 42));
EXPECT_CALL(*calculator_, EmitCongestedIntervalTraceEvent(
CongestionType::kQueueAndExecution,
@ -812,7 +817,7 @@ TEST_F(ResponsivenessCalculatorTest, EmitResponsivenessTraceEvents) {
calculator_->EmitResponsivenessTraceEvents(
CongestionType::kQueueAndExecution, StartupStage::kPeriodic, kStartTime,
kFinishTime, congested_slices);
kFinishTime, congested_slices, event_id);
}
TEST_F(ResponsivenessCalculatorTest, Delegate) {

@ -44,8 +44,9 @@ void BackgroundTracingAgentClientImpl::OnInitialized() {
void BackgroundTracingAgentClientImpl::OnTriggerBackgroundTrace(
tracing::mojom::BackgroundTracingRulePtr rule,
std::optional<int32_t> histogram_value) {
base::trace_event::EmitNamedTrigger(rule->rule_id, histogram_value);
std::optional<int32_t> histogram_value,
uint64_t flow_id) {
base::trace_event::EmitNamedTrigger(rule->rule_id, histogram_value, flow_id);
}
BackgroundTracingAgentClientImpl::BackgroundTracingAgentClientImpl(

@ -27,9 +27,9 @@ class BackgroundTracingAgentClientImpl
// tracing::mojom::BackgroundTracingAgentClient methods:
void OnInitialized() override;
void OnTriggerBackgroundTrace(
tracing::mojom::BackgroundTracingRulePtr rule,
std::optional<int32_t> histogram_value) override;
void OnTriggerBackgroundTrace(tracing::mojom::BackgroundTracingRulePtr rule,
std::optional<int32_t> histogram_value,
uint64_t flow_id) override;
private:
explicit BackgroundTracingAgentClientImpl(

@ -981,7 +981,8 @@ void BackgroundTracingManagerImpl::RemoveNamedTriggerObserver(
bool BackgroundTracingManagerImpl::DoEmitNamedTrigger(
const std::string& trigger_name,
std::optional<int32_t> value) {
std::optional<int32_t> value,
uint64_t flow_id) {
DCHECK_CURRENTLY_ON(BrowserThread::UI);
auto it = named_trigger_observers_.find(trigger_name);
@ -989,9 +990,9 @@ bool BackgroundTracingManagerImpl::DoEmitNamedTrigger(
return false;
}
for (BackgroundTracingRule& obs : it->second) {
if (obs.OnRuleTriggered(value)) {
TRACE_EVENT_INSTANT("toplevel", "NamedTrigger",
base::trace_event::TriggerFlow(trigger_name, value));
if (obs.OnRuleTriggered(value, flow_id)) {
TRACE_EVENT_INSTANT("toplevel,latency", "NamedTrigger",
perfetto::Flow::Global(flow_id));
return true;
}
}

@ -237,7 +237,8 @@ class BackgroundTracingManagerImpl
// Named triggers
bool DoEmitNamedTrigger(const std::string& trigger_name,
std::optional<int32_t>) override;
std::optional<int32_t>,
uint64_t) override;
void OnScenarioAborted();
static void AddPendingAgent(

@ -18,6 +18,7 @@
#include "base/strings/strcat.h"
#include "base/time/time.h"
#include "base/timer/timer.h"
#include "base/trace_event/histogram_scope.h"
#include "base/trace_event/trace_event.h"
#include "base/trace_event/trace_id_helper.h"
#include "components/variations/hashing.h"
@ -60,7 +61,8 @@ void BackgroundTracingRule::Uninstall() {
DoUninstall();
}
bool BackgroundTracingRule::OnRuleTriggered(std::optional<int32_t> value) {
bool BackgroundTracingRule::OnRuleTriggered(std::optional<int32_t> value,
uint64_t flow_id) {
if (!installed()) {
return false;
}
@ -69,6 +71,7 @@ bool BackgroundTracingRule::OnRuleTriggered(std::optional<int32_t> value) {
return false;
}
triggered_value_ = value;
flow_id_ = flow_id;
if (delay_) {
trigger_timer_.Start(FROM_HERE, *delay_,
base::BindOnce(base::IgnoreResult(trigger_callback_),
@ -79,11 +82,6 @@ bool BackgroundTracingRule::OnRuleTriggered(std::optional<int32_t> value) {
}
}
uint64_t BackgroundTracingRule::GetFlowId() const {
return base::trace_event::TriggerFlowId(GetDefaultRuleName(),
triggered_value_);
}
std::string BackgroundTracingRule::GetDefaultRuleName() const {
return "trigger";
}
@ -265,30 +263,34 @@ class HistogramRule : public BackgroundTracingRule,
tracing::mojom::BackgroundTracingRule::New(rule_name()));
}
void OnHistogramChangedCallback(base::Histogram::Sample32 reference_lower_value,
base::Histogram::Sample32 reference_upper_value,
const char* histogram_name,
uint64_t name_hash,
base::Histogram::Sample32 actual_value) {
void OnHistogramChangedCallback(
base::Histogram::Sample32 reference_lower_value,
base::Histogram::Sample32 reference_upper_value,
const char* histogram_name,
uint64_t name_hash,
base::Histogram::Sample32 actual_value) {
DCHECK_EQ(histogram_name, histogram_name_);
if (reference_lower_value > actual_value ||
reference_upper_value < actual_value) {
return;
}
uint64_t flow_id = base::trace_event::HistogramScope::GetFlowId().value_or(
base::trace_event::GetNextGlobalTraceId());
// Add the histogram name and its corresponding value to the trace.
const auto trace_details = [&](perfetto::EventContext& ctx) {
perfetto::protos::pbzero::ChromeHistogramSample* new_sample =
ctx.event()->set_chrome_histogram_sample();
new_sample->set_name_hash(base::HashMetricName(histogram_name));
new_sample->set_sample(actual_value);
perfetto::Flow::Global(GetFlowId())(ctx);
perfetto::Flow::Global(flow_id)(ctx);
};
TRACE_EVENT_INSTANT(
"toplevel,latency", "HistogramSampleTrigger",
perfetto::Track::FromPointer(this, perfetto::ProcessTrack::Current()),
base::TimeTicks::Now(), trace_details);
OnRuleTriggered(actual_value);
OnRuleTriggered(actual_value, flow_id);
}
protected:
@ -312,7 +314,9 @@ class TimerRule : public BackgroundTracingRule {
return base::WrapUnique<TimerRule>(new TimerRule());
}
void DoInstall() override { OnRuleTriggered(std::nullopt); }
void DoInstall() override {
OnRuleTriggered(std::nullopt, base::trace_event::GetNextGlobalTraceId());
}
void DoUninstall() override {}
void GenerateMetadataProto(
@ -416,7 +420,7 @@ class RepeatingIntervalRule : public BackgroundTracingRule {
}
void OnTick() {
OnRuleTriggered(std::nullopt);
OnRuleTriggered(std::nullopt, base::trace_event::GetNextGlobalTraceId());
ScheduleNextTick();
}

@ -49,11 +49,11 @@ class CONTENT_EXPORT BackgroundTracingRule : public base::CheckedObserver {
const std::string& rule_name() const { return rule_name_; }
std::optional<int32_t> triggered_value() const { return triggered_value_; }
uint64_t GetFlowId() const;
uint64_t flow_id() const { return flow_id_; }
bool is_crash() const { return is_crash_; }
bool OnRuleTriggered(std::optional<int32_t> value);
bool OnRuleTriggered(std::optional<int32_t> value, uint64_t flow_id);
protected:
virtual std::string GetDefaultRuleName() const;
@ -75,6 +75,7 @@ class CONTENT_EXPORT BackgroundTracingRule : public base::CheckedObserver {
base::OneShotTimer activation_timer_;
std::string rule_name_;
std::optional<int32_t> triggered_value_;
uint64_t flow_id_;
bool is_crash_ = false;
};

@ -29,7 +29,7 @@ void TriggersDataSource::EmitTrigger(
trigger->set_trigger_name(triggered_rule->rule_name());
trigger->set_trigger_name_hash(
base::HashFieldTrialName(triggered_rule->rule_name()));
trigger->set_flow_id(triggered_rule->GetFlowId());
trigger->set_flow_id(triggered_rule->flow_id());
});
}

@ -8,6 +8,7 @@
#include "base/metrics/metrics_hashes.h"
#include "base/metrics/statistics_recorder.h"
#include "base/trace_event/histogram_scope.h"
#include "base/trace_event/trace_event.h"
#include "mojo/public/cpp/bindings/self_owned_receiver.h"
#include "services/tracing/public/cpp/perfetto/macros.h"
@ -51,25 +52,28 @@ void BackgroundTracingAgentImpl::ClearUMACallback(
bool BackgroundTracingAgentImpl::DoEmitNamedTrigger(
const std::string& trigger_name,
std::optional<int32_t> value) {
std::optional<int32_t> value,
uint64_t flow_id) {
TRACE_EVENT_INSTANT("latency", "NamedTrigger",
base::trace_event::TriggerFlow(trigger_name, value));
DoEmitNamedTriggerImpl(trigger_name, value);
perfetto::Flow::Global(flow_id));
DoEmitNamedTriggerImpl(trigger_name, value, flow_id);
return true;
}
void BackgroundTracingAgentImpl::DoEmitNamedTriggerImpl(
const std::string& trigger_name,
std::optional<int32_t> value) {
std::optional<int32_t> value,
uint64_t flow_id) {
if (!task_runner_->RunsTasksInCurrentSequence()) {
task_runner_->PostTask(
FROM_HERE,
base::BindOnce(&BackgroundTracingAgentImpl::DoEmitNamedTriggerImpl,
weak_factory_.GetWeakPtr(), trigger_name, value));
weak_factory_.GetWeakPtr(), trigger_name, value,
flow_id));
return;
}
client_->OnTriggerBackgroundTrace(
tracing::mojom::BackgroundTracingRule::New(trigger_name), value);
tracing::mojom::BackgroundTracingRule::New(trigger_name), value, flow_id);
}
void BackgroundTracingAgentImpl::OnHistogramChanged(
@ -83,18 +87,22 @@ void BackgroundTracingAgentImpl::OnHistogramChanged(
actual_value > histogram_upper_value) {
return;
}
uint64_t flow_id = base::trace_event::HistogramScope::GetFlowId().value_or(
base::trace_event::GetNextGlobalTraceId());
TRACE_EVENT("toplevel,latency", "HistogramSampleTrigger",
[&](perfetto::EventContext ctx) {
perfetto::protos::pbzero::ChromeHistogramSample* new_sample =
ctx.event()->set_chrome_histogram_sample();
new_sample->set_name_hash(name_hash);
new_sample->set_sample(actual_value);
base::trace_event::TriggerFlow(histogram_name,
actual_value)(ctx);
perfetto::Flow::Global(flow_id)(ctx);
});
client_->OnTriggerBackgroundTrace(
tracing::mojom::BackgroundTracingRule::New(rule_id), actual_value);
tracing::mojom::BackgroundTracingRule::New(rule_id), actual_value,
flow_id);
}
} // namespace tracing

@ -42,7 +42,8 @@ class COMPONENT_EXPORT(BACKGROUND_TRACING_CPP) BackgroundTracingAgentImpl
// base::trace_event::NamedTriggerManager
bool DoEmitNamedTrigger(const std::string& trigger_name,
std::optional<int32_t> value) override;
std::optional<int32_t> value,
uint64_t flow_id) override;
private:
void OnHistogramChanged(const std::string& rule_id,
@ -53,7 +54,8 @@ class COMPONENT_EXPORT(BACKGROUND_TRACING_CPP) BackgroundTracingAgentImpl
base::Histogram::Sample32 actual_value);
void DoEmitNamedTriggerImpl(const std::string& trigger_name,
std::optional<int32_t> value);
std::optional<int32_t> value,
uint64_t flow_id);
mojo::Remote<mojom::BackgroundTracingAgentClient> client_;
base::Time histogram_last_changed_;

@ -24,7 +24,8 @@ class BackgroundTracingAgentClientRecorder
void OnInitialized() override { ++on_initialized_count_; }
void OnTriggerBackgroundTrace(tracing::mojom::BackgroundTracingRulePtr rule,
std::optional<int32_t> value) override {
std::optional<int32_t> value,
uint64_t flow_id) override {
++on_trigger_background_trace_count_;
on_trigger_background_trace_rule_id_ = rule->rule_id;
}

@ -15,7 +15,9 @@ interface BackgroundTracingAgentClient {
OnInitialized();
// Called when a monitored histogram trigger is hit. Histograms are monitored
// by calling BackgroundTracingAgent::SetUMACallback().
OnTriggerBackgroundTrace(BackgroundTracingRule rule, int32? histogram_value);
OnTriggerBackgroundTrace(BackgroundTracingRule rule,
int32? histogram_value,
uint64 flow_id);
};
// This interface is used to allow clients (the browser process) to monitor for

@ -10,7 +10,7 @@
#include "base/metrics/histogram_functions.h"
#include "base/strings/strcat.h"
#include "base/time/time.h"
#include "base/trace_event/named_trigger.h"
#include "base/trace_event/histogram_scope.h"
#include "base/trace_event/trace_id_helper.h"
#include "base/trace_event/typed_macros.h"
#include "base/tracing/protos/chrome_track_event.pbzero.h"
@ -62,7 +62,8 @@ void RecordTabSwitchTraceEvent(base::TimeTicks start_time,
base::TimeTicks end_time,
TabSwitchResult result,
bool has_saved_frames,
bool destination_is_loaded) {
bool destination_is_loaded,
uint64_t flow_id) {
if (!IsLatencyTraceCategoryEnabled()) {
return;
}
@ -71,9 +72,7 @@ void RecordTabSwitchTraceEvent(base::TimeTicks start_time,
DCHECK_GE(end_time, start_time);
const auto track =
perfetto::Track::Global(base::trace_event::GetNextGlobalTraceId());
const auto duration = end_time - start_time;
const auto flow = base::trace_event::TriggerFlow(
"Browser.Tabs.TotalSwitchDuration3", duration.InMilliseconds());
const auto flow = perfetto::Flow::Global(flow_id);
TRACE_EVENT_BEGIN(
"latency", "TabSwitching::Latency", track, start_time,
[&](perfetto::EventContext ctx) {
@ -238,16 +237,18 @@ void ContentToVisibleTimeReporter::RecordHistogramsAndTraceEvents(
return;
}
RecordTabSwitchTraceEvent(tab_switch_start_state_->event_start_time,
presentation_timestamp, tab_switch_result,
has_saved_frames_,
tab_switch_start_state_->destination_is_loaded);
uint64_t event_id = base::trace_event::GetNextGlobalTraceId();
RecordTabSwitchTraceEvent(
tab_switch_start_state_->event_start_time, presentation_timestamp,
tab_switch_result, has_saved_frames_,
tab_switch_start_state_->destination_is_loaded, event_id);
const auto tab_switch_duration =
presentation_timestamp - tab_switch_start_state_->event_start_time;
const char* suffix =
GetHistogramSuffix(has_saved_frames_, *tab_switch_start_state_);
base::trace_event::HistogramScope scoped_event(event_id);
// Record result histogram.
base::UmaHistogramEnumeration("Browser.Tabs.TabSwitchResult3",

@ -10,7 +10,7 @@
#include "base/rand_util.h"
#include "base/strings/strcat.h"
#include "base/time/time.h"
#include "base/trace_event/named_trigger.h"
#include "base/trace_event/histogram_scope.h"
#include "base/trace_event/trace_event.h"
#include "base/trace_event/trace_id_helper.h"
#include "services/metrics/public/cpp/ukm_builders.h"
@ -85,17 +85,15 @@ enum ClickInteractionEvents {
// LINT.ThenChange(/tools/metrics/histograms/enums.xml:EventTimingClickInteractionEvents)
void EmitSlowInteractionToNextPaintTraceEvent(
const ResponsivenessMetrics::EventTimestamps& event) {
const ResponsivenessMetrics::EventTimestamps& event,
uint64_t event_id) {
auto track =
perfetto::Track::Global(base::trace_event::GetNextGlobalTraceId());
auto flow = base::trace_event::TriggerFlow(
base::StrCat({kHistogramMaxEventDuration, kHistogramAllTypes}),
event.duration().InMilliseconds());
TRACE_EVENT_BEGIN(kSlowInteractionToNextPaintTraceEventCategory,
kSlowInteractionToNextPaintTraceEventName, track,
event.creation_time);
TRACE_EVENT_END(kSlowInteractionToNextPaintTraceEventCategory, track,
event.end_time, flow);
event.end_time, perfetto::Flow::Global(event_id));
}
// Returns the longest event in `timestamps`.
@ -220,12 +218,14 @@ void ResponsivenessMetrics::RecordUserInteractionUKM(
// Emit a trace event when "interaction to next paint" is considered "slow"
// according to RAIL guidelines (web.dev/rail).
uint64_t event_id = base::trace_event::GetNextGlobalTraceId();
constexpr base::TimeDelta kSlowInteractionToNextPaintThreshold =
base::Milliseconds(100);
if (longest_event.duration() > kSlowInteractionToNextPaintThreshold) {
EmitSlowInteractionToNextPaintTraceEvent(longest_event);
EmitSlowInteractionToNextPaintTraceEvent(longest_event, event_id);
}
base::trace_event::HistogramScope scoped_event(event_id);
LogResponsivenessHistogram(max_event_duration, kHistogramAllTypes);
if (is_pointer_event) {
LogResponsivenessHistogram(max_event_duration, kHistogramTapOrClick);