[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/+/2462636Reviewed-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}

base/BUILD.gn

@@ -2135,6 +2135,7 @@ 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",

base/trace_event/base_tracing.h

@@ -16,8 +16,10 @@
 // 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"

base/trace_event/common/trace_event_common.h

@@ -969,6 +969,7 @@
 #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)
 

base/trace_event/task_execution_macros.h

+// 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_

base/trace_event/trace_event.h

@@ -22,7 +22,6 @@
 #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"
@@ -390,45 +389,6 @@
     }                                                                \
   } 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

cc/raster/synchronous_task_graph_runner.cc

@@ -10,6 +10,7 @@
 #include <utility>
 
 #include "base/threading/simple_thread.h"
+#include "base/trace_event/heap_profiler.h"
 #include "base/trace_event/trace_event.h"
 
 namespace cc {

components/heap_profiling/multi_process/test_driver.cc

@@ -17,6 +17,7 @@
 #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"

components/services/heap_profiling/public/cpp/profiling_client.cc

@@ -14,6 +14,7 @@
 #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"

components/timers/alarm_timer_chromeos.cc

@@ -17,6 +17,7 @@
 #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 {

components/tracing/test/trace_event_perftest.cc

@@ -11,6 +11,7 @@
 #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"

services/tracing/public/cpp/perfetto/trace_event_data_source_unittest.cc

@@ -26,6 +26,7 @@
 #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"
@@ -1018,20 +1019,17 @@ TEST_F(TraceEventDataSourceTest, EventWithConvertableArgs) {
 TEST_F(TraceEventDataSourceTest, TaskExecutionEvent) {
   CreateTraceEventDataSource();
 
-  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");
+  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); }
 
   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_INSTANT, TRACE_EVENT_SCOPE_THREAD);
+                   TRACE_EVENT_PHASE_BEGIN);
 
   const auto& annotations = e_packet->track_event().debug_annotations();
   EXPECT_EQ(annotations.size(), 0);
@@ -1043,9 +1041,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_INSTANT, TRACE_EVENT_SCOPE_THREAD);
+                   TRACE_EVENT_PHASE_BEGIN);
 
   EXPECT_EQ(e_packet2->track_event().task_execution().posted_from_iid(), 1u);
   EXPECT_EQ(e_packet2->interned_data().source_locations().size(), 0);
@@ -1054,16 +1052,16 @@ TEST_F(TraceEventDataSourceTest, TaskExecutionEvent) {
 TEST_F(TraceEventDataSourceTest, TaskExecutionEventWithoutFunction) {
   CreateTraceEventDataSource();
 
-  INTERNAL_TRACE_EVENT_ADD(
-      TRACE_EVENT_PHASE_INSTANT, "toplevel", "ThreadControllerImpl::RunTask",
-      TRACE_EVENT_SCOPE_THREAD | TRACE_EVENT_FLAG_TYPED_PROTO_ARGS, "src",
-      "my_file");
+  base::PendingTask task;
+  task.posted_from = base::Location(/*function_name=*/nullptr, "my_file", 0,
+                                    /*program_counter=*/&task);
+  { TRACE_TASK_EXECUTION("ThreadControllerImpl::RunTask", task); }
 
   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_INSTANT, TRACE_EVENT_SCOPE_THREAD);
+                   TRACE_EVENT_PHASE_BEGIN, TRACE_EVENT_SCOPE_THREAD);
 
   const auto& annotations = e_packet->track_event().debug_annotations();
   EXPECT_EQ(annotations.size(), 0);

services/tracing/public/cpp/perfetto/track_event_thread_local_event_sink.cc

@@ -67,12 +67,6 @@ 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) {
@@ -474,13 +468,6 @@ 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.
@@ -510,49 +497,8 @@ 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) {
-      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));
+      NOTREACHED();
     } else if (!privacy_filtering_enabled_) {
       for (size_t i = 0;
            i < trace_event->arg_size() && trace_event->arg_name(i); ++i) {
@@ -626,14 +572,7 @@ TrackEvent* TrackEventThreadLocalEventSink::PrepareTrackEvent(
     track_event->add_category_iids(interned_category.id);
   }
 
-  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_) {
+  if (!privacy_filtering_enabled_) {
     WriteDebugAnnotations(trace_event, track_event, interned_annotation_names);
   }
 
@@ -796,19 +735,7 @@ TrackEvent* TrackEventThreadLocalEventSink::PrepareTrackEvent(
         std::make_tuple(IndexType::kName, IndexData{trace_event_name},
                         std::move(interned_name)));
   }
-  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_) {
+  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);