Commit 989724c3 authored by Giovanni Ortuño Urquidi's avatar Giovanni Ortuño Urquidi Committed by Commit Bot

Revert "[tracing] Remove special handling of task execution and log events"

This reverts commit f79b1513.

Reason for revert: Breaks WebKit Linux MSAN

The following tests started failing since this landed:

* http/tests/devtools/tracing.js
* http/tests/devtools/tracing/decode-resize.js
* http/tests/devtools/tracing/timeline-paint/update-layer-tree.js
* http/tests/devtools/tracing/timeline-style/parse-author-style-sheet.js
* http/tests/devtools/tracing/tracing-record-input-events.js
* http/tests/devtools/tracing/user-timing.js
* http/tests/devtools/tracing/worker-events.js
* http/tests/devtools/tracing/worker-js-frames.js
* inspector-protocol/sessions/tracing-start.js
* inspector-protocol/timeline/tracing-proto-format.js

First run that failed, also the run where the CL landed:
https://ci.chromium.org/p/chromium/builders/ci/WebKit%20Linux%20MSAN/7830

Original change's description:
> [tracing] Remove special handling of task execution and log events
>
> The task execution and log events are handled specially for writing
> proto arguments because we did not have the support for typed events in
> base and interning support for the event macros. Now these events can
> use the new client library API.
> The events have to be migrated together because the source location
> interning index is common for all events in the API and does not
> account for the special handling in event sink.
>
> BUG=1136635
> TBR=chirantan@chromium.org
>
> Change-Id: I381e8c90e49c3fbd9ce4d8fb2e9db3d166b9b06d
> Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2462636
> Reviewed-by: ssid <ssid@chromium.org>
> Reviewed-by: Sami Kyöstilä <skyostil@chromium.org>
> Reviewed-by: danakj <danakj@chromium.org>
> Reviewed-by: Erik Chen <erikchen@chromium.org>
> Reviewed-by: Eric Seckler <eseckler@chromium.org>
> Commit-Queue: ssid <ssid@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#815911}

TBR=danakj@chromium.org,chirantan@chromium.org,erikchen@chromium.org,skyostil@chromium.org,ssid@chromium.org,eseckler@chromium.org

# Not skipping CQ checks because original CL landed > 1 day ago.

Bug: 1136635
Change-Id: I7a84356400bbdcae3144fd65afdcab7a4407dcd9
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2462895Reviewed-by: default avatarGiovanni Ortuño Urquidi <ortuno@chromium.org>
Commit-Queue: Giovanni Ortuño Urquidi <ortuno@chromium.org>
Cr-Commit-Position: refs/heads/master@{#816069}
parent 2f484dc1
......@@ -2135,7 +2135,6 @@ component("base") {
"trace_event/optional_trace_event.h",
"trace_event/process_memory_dump.cc",
"trace_event/process_memory_dump.h",
"trace_event/task_execution_macros.h",
"trace_event/thread_instruction_count.cc",
"trace_event/thread_instruction_count.h",
"trace_event/trace_arguments.cc",
......
......@@ -16,10 +16,8 @@
// Update the check in //base/PRESUBMIT.py when adding new headers here.
// TODO(crbug/1006541): Switch to perfetto for trace event implementation.
#include "base/trace_event/blame_context.h"
#include "base/trace_event/heap_profiler.h"
#include "base/trace_event/memory_allocator_dump_guid.h"
#include "base/trace_event/memory_dump_provider.h"
#include "base/trace_event/task_execution_macros.h"
#include "base/trace_event/trace_event.h"
#include "base/trace_event/traced_value.h"
#include "base/trace_event/typed_macros.h"
......
......@@ -969,7 +969,6 @@
#define TRACE_TASK_EXECUTION(run_function, task) \
INTERNAL_TRACE_TASK_EXECUTION(run_function, task)
// Special trace event macro to trace log messages.
#define TRACE_LOG_MESSAGE(file, message, line) \
INTERNAL_TRACE_LOG_MESSAGE(file, message, line)
......
// Copyright 2020 The Chromium Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.
#ifndef BASE_TRACE_EVENT_TASK_EXECUTION_MACROS_H_
#define BASE_TRACE_EVENT_TASK_EXECUTION_MACROS_H_
#include "base/location.h"
#include "base/trace_event/heap_profiler.h"
#include "base/trace_event/typed_macros.h"
#include "third_party/perfetto/include/perfetto/tracing/track_event_interned_data_index.h"
#include "third_party/perfetto/protos/perfetto/trace/interned_data/interned_data.pbzero.h"
#include "third_party/perfetto/protos/perfetto/trace/track_event/log_message.pbzero.h"
#include "third_party/perfetto/protos/perfetto/trace/track_event/source_location.pbzero.h"
#include "third_party/perfetto/protos/perfetto/trace/track_event/task_execution.pbzero.h"
namespace {
// TrackEventInternedDataIndex expects the same data structure to be used for
// all interned fields with the same field number. We can't use base::Location
// for log event's location since base::Location uses program counter based
// location.
struct TraceSourceLocation {
const char* function_name = nullptr;
const char* file_name = nullptr;
int line_number = 0;
bool operator==(const TraceSourceLocation& other) const {
return file_name == other.file_name &&
function_name == other.function_name &&
line_number == other.line_number;
}
};
} // namespace
namespace std {
template <>
struct ::std::hash<TraceSourceLocation> {
std::size_t operator()(const TraceSourceLocation& loc) const {
return base::FastHash(base::as_bytes(base::make_span(&loc, 1)));
}
};
} // namespace std
namespace {
struct InternedSourceLocation
: public perfetto::TrackEventInternedDataIndex<
InternedSourceLocation,
perfetto::protos::pbzero::InternedData::kSourceLocationsFieldNumber,
TraceSourceLocation> {
static void Add(perfetto::protos::pbzero::InternedData* interned_data,
size_t iid,
const TraceSourceLocation& location) {
auto* msg = interned_data->add_source_locations();
msg->set_iid(iid);
if (location.file_name != nullptr)
msg->set_file_name(location.file_name);
if (location.function_name != nullptr)
msg->set_function_name(location.function_name);
// TODO(ssid): Add line number once it is whitelisted in internal proto.
// TODO(ssid): Add program counter to the proto fields when
// !BUILDFLAG(ENABLE_LOCATION_SOURCE).
// TODO(http://crbug.com760702) remove file name and just pass the program
// counter to the heap profiler macro.
// TODO(ssid): Consider writing the program counter of the current task
// (from the callback function pointer) instead of location that posted the
// task.
}
};
struct InternedLogMessage
: public perfetto::TrackEventInternedDataIndex<
InternedLogMessage,
perfetto::protos::pbzero::InternedData::kLogMessageBodyFieldNumber,
std::string> {
static void Add(perfetto::protos::pbzero::InternedData* interned_data,
size_t iid,
const std::string& log_message) {
auto* msg = interned_data->add_log_message_body();
msg->set_iid(iid);
msg->set_body(log_message);
}
};
} // namespace
// Implementation detail: internal macro to trace a task execution with the
// location where it was posted from.
#define INTERNAL_TRACE_TASK_EXECUTION(run_function, task) \
TRACE_EVENT("toplevel", run_function, [&](perfetto::EventContext ctx) { \
ctx.event()->set_task_execution()->set_posted_from_iid( \
InternedSourceLocation::Get(&ctx, \
{(task).posted_from.function_name(), \
(task).posted_from.file_name(), \
(task).posted_from.line_number()})); \
}); \
TRACE_HEAP_PROFILER_API_SCOPED_TASK_EXECUTION INTERNAL_TRACE_EVENT_UID( \
task_event)((task).posted_from.file_name()); \
TRACE_HEAP_PROFILER_API_SCOPED_WITH_PROGRAM_COUNTER \
INTERNAL_TRACE_EVENT_UID(task_pc_event) \
((task).posted_from.program_counter());
// Implementation detail: internal macro to trace a log message, with the source
// location of the log statement.
#define INTERNAL_TRACE_LOG_MESSAGE(file, message, line) \
TRACE_EVENT_INSTANT( \
"log", "LogMessage", TRACE_EVENT_SCOPE_THREAD, \
[&](perfetto::EventContext ctx) { \
perfetto::protos::pbzero::LogMessage* log = \
ctx.event()->set_log_message(); \
log->set_source_location_iid(InternedSourceLocation::Get( \
&ctx, \
TraceSourceLocation{/*function_name=*/nullptr, file, line})); \
log->set_body_iid(InternedLogMessage::Get(&ctx, message.as_string())); \
});
#endif // BASE_TRACE_EVENT_TASK_EXECUTION_MACROS_H_
......@@ -22,6 +22,7 @@
#include "base/time/time_override.h"
#include "base/trace_event/builtin_categories.h"
#include "base/trace_event/common/trace_event_common.h"
#include "base/trace_event/heap_profiler.h"
#include "base/trace_event/log_message.h"
#include "base/trace_event/thread_instruction_count.h"
#include "base/trace_event/trace_arguments.h"
......@@ -389,6 +390,45 @@
} \
} while (0)
#define INTERNAL_TRACE_LOG_MESSAGE(file, message, line) \
TRACE_EVENT_INSTANT1( \
"log", "LogMessage", \
TRACE_EVENT_FLAG_TYPED_PROTO_ARGS | TRACE_EVENT_SCOPE_THREAD, "message", \
std::make_unique<base::trace_event::LogMessage>(file, message, line))
#if BUILDFLAG(ENABLE_LOCATION_SOURCE)
// Implementation detail: internal macro to trace a task execution with the
// location where it was posted from.
//
// This implementation is for when location sources are available.
// TODO(ssid): The program counter of the current task should be added here.
#define INTERNAL_TRACE_TASK_EXECUTION(run_function, task) \
INTERNAL_TRACE_EVENT_ADD_SCOPED_WITH_FLAGS( \
"toplevel", run_function, TRACE_EVENT_FLAG_TYPED_PROTO_ARGS, "src_file", \
(task).posted_from.file_name(), "src_func", \
(task).posted_from.function_name()); \
TRACE_HEAP_PROFILER_API_SCOPED_TASK_EXECUTION INTERNAL_TRACE_EVENT_UID( \
task_event)((task).posted_from.file_name()); \
TRACE_HEAP_PROFILER_API_SCOPED_WITH_PROGRAM_COUNTER \
INTERNAL_TRACE_EVENT_UID(task_pc_event)((task).posted_from.program_counter());
#else
// TODO(http://crbug.com760702) remove file name and just pass the program
// counter to the heap profiler macro.
// TODO(ssid): The program counter of the current task should be added here.
#define INTERNAL_TRACE_TASK_EXECUTION(run_function, task) \
INTERNAL_TRACE_EVENT_ADD_SCOPED_WITH_FLAGS( \
"toplevel", run_function, TRACE_EVENT_FLAG_TYPED_PROTO_ARGS, "src", \
(task).posted_from.ToString()) \
TRACE_HEAP_PROFILER_API_SCOPED_TASK_EXECUTION INTERNAL_TRACE_EVENT_UID( \
task_event)((task).posted_from.file_name()); \
TRACE_HEAP_PROFILER_API_SCOPED_WITH_PROGRAM_COUNTER \
INTERNAL_TRACE_EVENT_UID(task_pc_event)((task).posted_from.program_counter());
#endif
namespace trace_event_internal {
// Specify these values when the corresponding argument of AddTraceEvent is not
......
......@@ -10,7 +10,6 @@
#include <utility>
#include "base/threading/simple_thread.h"
#include "base/trace_event/heap_profiler.h"
#include "base/trace_event/trace_event.h"
namespace cc {
......
......@@ -17,7 +17,6 @@
#include "base/stl_util.h"
#include "base/test/bind_test_util.h"
#include "base/threading/platform_thread.h"
#include "base/trace_event/heap_profiler.h"
#include "base/trace_event/heap_profiler_event_filter.h"
#include "base/values.h"
#include "build/build_config.h"
......
......@@ -14,7 +14,6 @@
#include "base/sampling_heap_profiler/sampling_heap_profiler.h"
#include "base/task/post_task.h"
#include "base/task/thread_pool.h"
#include "base/trace_event/heap_profiler_allocation_context_tracker.h"
#include "base/trace_event/heap_profiler_event_filter.h"
#include "base/trace_event/malloc_dump_provider.h"
#include "base/trace_event/memory_dump_manager.h"
......
......@@ -17,7 +17,6 @@
#include "base/memory/ptr_util.h"
#include "base/pending_task.h"
#include "base/task/common/task_annotator.h"
#include "base/trace_event/task_execution_macros.h"
#include "base/trace_event/trace_event.h"
namespace timers {
......
......@@ -11,7 +11,6 @@
#include "base/run_loop.h"
#include "base/test/task_environment.h"
#include "base/threading/thread.h"
#include "base/trace_event/task_execution_macros.h"
#include "base/trace_event/trace_event.h"
#include "base/trace_event/traced_value.h"
#include "perf_test_helpers.h"
......
......@@ -26,7 +26,6 @@
#include "base/threading/thread_id_name_manager.h"
#include "base/threading/thread_restrictions.h"
#include "base/time/time.h"
#include "base/trace_event/task_execution_macros.h"
#include "base/trace_event/thread_instruction_count.h"
#include "base/trace_event/trace_event.h"
#include "base/trace_event/trace_log.h"
......@@ -1019,17 +1018,20 @@ TEST_F(TraceEventDataSourceTest, EventWithConvertableArgs) {
TEST_F(TraceEventDataSourceTest, TaskExecutionEvent) {
CreateTraceEventDataSource();
base::PendingTask task;
task.posted_from =
base::Location("my_func", "my_file", 0, /*program_counter=*/&task);
{ TRACE_TASK_EXECUTION("ThreadControllerImpl::RunTask1", task); }
{ TRACE_TASK_EXECUTION("ThreadControllerImpl::RunTask1", task); }
INTERNAL_TRACE_EVENT_ADD(
TRACE_EVENT_PHASE_INSTANT, "toplevel", "ThreadControllerImpl::RunTask",
TRACE_EVENT_SCOPE_THREAD | TRACE_EVENT_FLAG_TYPED_PROTO_ARGS, "src_file",
"my_file", "src_func", "my_func");
INTERNAL_TRACE_EVENT_ADD(
TRACE_EVENT_PHASE_INSTANT, "toplevel", "ThreadControllerImpl::RunTask",
TRACE_EVENT_SCOPE_THREAD | TRACE_EVENT_FLAG_TYPED_PROTO_ARGS, "src_file",
"my_file", "src_func", "my_func");
size_t packet_index = ExpectStandardPreamble();
auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_BEGIN);
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
const auto& annotations = e_packet->track_event().debug_annotations();
EXPECT_EQ(annotations.size(), 0);
......@@ -1041,9 +1043,9 @@ TEST_F(TraceEventDataSourceTest, TaskExecutionEvent) {
EXPECT_EQ(locations[0].function_name(), "my_func");
// Second event should refer to the same interning entries.
auto* e_packet2 = producer_client()->GetFinalizedPacket(++packet_index);
auto* e_packet2 = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet2, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_BEGIN);
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
EXPECT_EQ(e_packet2->track_event().task_execution().posted_from_iid(), 1u);
EXPECT_EQ(e_packet2->interned_data().source_locations().size(), 0);
......@@ -1052,16 +1054,16 @@ TEST_F(TraceEventDataSourceTest, TaskExecutionEvent) {
TEST_F(TraceEventDataSourceTest, TaskExecutionEventWithoutFunction) {
CreateTraceEventDataSource();
base::PendingTask task;
task.posted_from = base::Location(/*function_name=*/nullptr, "my_file", 0,
/*program_counter=*/&task);
{ TRACE_TASK_EXECUTION("ThreadControllerImpl::RunTask", task); }
INTERNAL_TRACE_EVENT_ADD(
TRACE_EVENT_PHASE_INSTANT, "toplevel", "ThreadControllerImpl::RunTask",
TRACE_EVENT_SCOPE_THREAD | TRACE_EVENT_FLAG_TYPED_PROTO_ARGS, "src",
"my_file");
size_t packet_index = ExpectStandardPreamble();
auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_BEGIN, TRACE_EVENT_SCOPE_THREAD);
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
const auto& annotations = e_packet->track_event().debug_annotations();
EXPECT_EQ(annotations.size(), 0);
......
......@@ -67,6 +67,12 @@ constexpr uint64_t kAbsoluteThreadTimeTrackUuidBit = static_cast<uint64_t>(1u)
constexpr uint64_t kThreadInstructionCountTrackUuidBit =
static_cast<uint64_t>(1u) << 34;
// Names of events that should be converted into a TaskExecution event.
const char* kTaskExecutionEventCategory = "toplevel";
const char* kTaskExecutionEventNames[3] = {"ThreadControllerImpl::RunTask",
"ThreadPool_RunTask",
"SimpleAlarmTimer::OnTimerFired"};
void AddConvertableToTraceFormat(
base::trace_event::ConvertableToTraceFormat* value,
perfetto::protos::pbzero::DebugAnnotation* annotation) {
......@@ -468,6 +474,13 @@ TrackEvent* TrackEventThreadLocalEventSink::PrepareTrackEvent(
const size_t kMaxSize = base::trace_event::TraceArguments::kMaxSize;
InterningIndexEntry interned_annotation_names[kMaxSize] = {
InterningIndexEntry{}};
InterningIndexEntry interned_source_location{};
InterningIndexEntry interned_log_message_body{};
const char* src_file = nullptr;
const char* src_func = nullptr;
const char* log_message_body = nullptr;
int line_number = 0;
// No need to write the event name for end events (sync or nestable async).
// Trace processor will match them without, provided event nesting is correct.
......@@ -497,8 +510,49 @@ TrackEvent* TrackEventThreadLocalEventSink::PrepareTrackEvent(
}
}
} else {
// TODO(eseckler): Remove special handling of typed events here once we
// support them in TRACE_EVENT macros.
if (flags & TRACE_EVENT_FLAG_TYPED_PROTO_ARGS) {
NOTREACHED();
if (trace_event->arg_size() == 2u) {
DCHECK_EQ(strcmp(category_name, kTaskExecutionEventCategory), 0);
DCHECK(strcmp(trace_event->name(), kTaskExecutionEventNames[0]) == 0 ||
strcmp(trace_event->name(), kTaskExecutionEventNames[1]) == 0 ||
strcmp(trace_event->name(), kTaskExecutionEventNames[2]) == 0);
// Double argument task execution event (src_file, src_func).
DCHECK_EQ(trace_event->arg_type(0), TRACE_VALUE_TYPE_STRING);
DCHECK_EQ(trace_event->arg_type(1), TRACE_VALUE_TYPE_STRING);
src_file = trace_event->arg_value(0).as_string;
src_func = trace_event->arg_value(1).as_string;
} else {
// arg_size == 1 enforced by the maximum number of parameter == 2.
DCHECK_EQ(trace_event->arg_size(), 1u);
if (trace_event->arg_type(0) == TRACE_VALUE_TYPE_STRING) {
// Single argument task execution event (src_file).
DCHECK_EQ(strcmp(category_name, kTaskExecutionEventCategory), 0);
DCHECK(
strcmp(trace_event->name(), kTaskExecutionEventNames[0]) == 0 ||
strcmp(trace_event->name(), kTaskExecutionEventNames[1]) == 0 ||
strcmp(trace_event->name(), kTaskExecutionEventNames[2]) == 0);
src_file = trace_event->arg_value(0).as_string;
} else {
DCHECK_EQ(trace_event->arg_type(0), TRACE_VALUE_TYPE_CONVERTABLE);
DCHECK(strcmp(category_name, "log") == 0);
DCHECK(strcmp(trace_event->name(), "LogMessage") == 0);
const base::trace_event::LogMessage* value =
static_cast<base::trace_event::LogMessage*>(
trace_event->arg_value(0).as_convertable);
src_file = value->file();
line_number = value->line_number();
log_message_body = value->message().c_str();
interned_log_message_body =
interned_log_message_bodies_.LookupOrAdd(value->message());
} // else
} // else
interned_source_location = interned_source_locations_.LookupOrAdd(
std::make_tuple(src_file, src_func, line_number));
} else if (!privacy_filtering_enabled_) {
for (size_t i = 0;
i < trace_event->arg_size() && trace_event->arg_name(i); ++i) {
......@@ -572,7 +626,14 @@ TrackEvent* TrackEventThreadLocalEventSink::PrepareTrackEvent(
track_event->add_category_iids(interned_category.id);
}
if (!privacy_filtering_enabled_) {
if (interned_log_message_body.id) {
auto* log_message = track_event->set_log_message();
log_message->set_source_location_iid(interned_source_location.id);
log_message->set_body_iid(interned_log_message_body.id);
} else if (interned_source_location.id) {
track_event->set_task_execution()->set_posted_from_iid(
interned_source_location.id);
} else if (!privacy_filtering_enabled_) {
WriteDebugAnnotations(trace_event, track_event, interned_annotation_names);
}
......@@ -735,7 +796,19 @@ TrackEvent* TrackEventThreadLocalEventSink::PrepareTrackEvent(
std::make_tuple(IndexType::kName, IndexData{trace_event_name},
std::move(interned_name)));
}
if (!privacy_filtering_enabled_) {
if (interned_log_message_body.id && !interned_log_message_body.was_emitted) {
pending_interning_updates_.push_back(
std::make_tuple(IndexType::kLogMessage, IndexData{log_message_body},
std::move(interned_log_message_body)));
}
if (interned_source_location.id) {
if (!interned_source_location.was_emitted) {
pending_interning_updates_.push_back(std::make_tuple(
IndexType::kSourceLocation,
IndexData{std::make_tuple(src_file, src_func, line_number)},
std::move(interned_source_location)));
}
} else if (!privacy_filtering_enabled_) {
for (size_t i = 0; i < trace_event->arg_size() && trace_event->arg_name(i);
++i) {
DCHECK(interned_annotation_names[i].id);
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment