tracing: Support thread instructions on begin/end events

Currently, we only support thread instruction delta values on
PHASE_COMPLETE events. Since we'll soon replace complete events
(at least on TrackEvent proto level) with begin/end event pairs, this
patch adds support for emitting absolute thread instruction count
values on begin/end events.

Also ensures that we write sensible timestamps for all metadata events
in TraceLog.

Bug: 925589
Change-Id: Ie01339aefb3d148457f51057e0722c4506dda82f
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1729262
Commit-Queue: Eric Seckler <eseckler@chromium.org>
Reviewed-by: Sami Kyöstilä <skyostil@chromium.org>
Cr-Commit-Position: refs/heads/master@{#682840}

base/trace_event/thread_instruction_count.h

@@ -7,12 +7,14 @@
 
 #include <stdint.h>
 
+#include "base/base_export.h"
+
 namespace base {
 namespace trace_event {
 
 // Represents the number of instructions that were retired between two samples
 // of a thread's performance counters.
-class ThreadInstructionDelta {
+class BASE_EXPORT ThreadInstructionDelta {
  public:
   constexpr ThreadInstructionDelta() : delta_(0) {}
   explicit constexpr ThreadInstructionDelta(int64_t delta) : delta_(delta) {}
@@ -25,7 +27,7 @@ class ThreadInstructionDelta {
 
 // Uses the system's performance counters in order to measure the number of
 // instructions that have been retired on the current thread.
-class ThreadInstructionCount {
+class BASE_EXPORT ThreadInstructionCount {
  public:
   // Returns true if the platform supports hardware retired instruction
   // counters.

base/trace_event/trace_event_impl.cc

@@ -214,6 +214,12 @@ void TraceEvent::AppendAsJSON(
     StringAppendF(out, ",\"tts\":%" PRId64, thread_time_int64);
   }
 
+  // Output ticount if thread_instruction_count is valid.
+  if (!thread_instruction_count_.is_null()) {
+    int64_t thread_instructions = thread_instruction_count_.ToInternalValue();
+    StringAppendF(out, ",\"ticount\":%" PRId64, thread_instructions);
+  }
+
   // Output async tts marker field if flag is set.
   if (flags_ & TRACE_EVENT_FLAG_ASYNC_TTS) {
     StringAppendF(out, ", \"use_async_tts\":1");

base/trace_event/trace_log.cc

@@ -114,8 +114,11 @@ void InitializeMetadataEvent(TraceEvent* trace_event,
     return;
 
   TraceArguments args(arg_name, value);
-  trace_event->Reset(thread_id, TimeTicks(), ThreadTicks(),
-                     ThreadInstructionCount(), TRACE_EVENT_PHASE_METADATA,
+  base::TimeTicks now = TRACE_TIME_TICKS_NOW();
+  ThreadTicks thread_now = ThreadNow();
+  ThreadInstructionCount thread_instruction_count = ThreadInstructionNow();
+  trace_event->Reset(thread_id, now, thread_now, thread_instruction_count,
+                     TRACE_EVENT_PHASE_METADATA,
                      CategoryRegistry::kCategoryMetadata->state_ptr(),
                      metadata_name,
                      trace_event_internal::kGlobalScope,  // scope

services/tracing/perfetto/json_trace_exporter.cc

@@ -584,6 +584,11 @@ void JSONTraceExporter::ScopedJSONTraceEventAppender::AddThreadTimestamp(
   out_->AppendF(",\"tts\":%" PRId64, thread_timestamp);
 }
 
+void JSONTraceExporter::ScopedJSONTraceEventAppender::AddThreadInstructionCount(
+    int64_t thread_instruction_count) {
+  out_->AppendF(",\"ticount\":%" PRId64, thread_instruction_count);
+}
+
 void JSONTraceExporter::ScopedJSONTraceEventAppender::AddThreadInstructionDelta(
     int64_t thread_instruction_delta) {
   out_->AppendF(",\"tidelta\":%" PRId64, thread_instruction_delta);

services/tracing/perfetto/json_trace_exporter.h

@@ -166,6 +166,7 @@ class JSONTraceExporter {
     void AddDuration(int64_t duration);
     void AddThreadDuration(int64_t thread_duration);
     void AddThreadTimestamp(int64_t thread_timestamp);
+    void AddThreadInstructionCount(int64_t thread_instruction_count);
     void AddThreadInstructionDelta(int64_t thread_instruction_delta);
     void AddBindId(uint64_t bind_id);
     // A set of bit flags for this trace event, along with a |scope|. |scope| is

services/tracing/perfetto/track_event_json_exporter.cc

@@ -204,6 +204,21 @@ base::Optional<int64_t> TrackEventJSONExporter::ComputeThreadTimeUs(
   }
 }
 
+base::Optional<int64_t> TrackEventJSONExporter::ComputeThreadInstructionCount(
+    const TrackEvent& event) {
+  switch (event.thread_instruction_count_case()) {
+    case TrackEvent::kThreadInstructionCountAbsolute:
+      return event.thread_instruction_count_absolute();
+    case TrackEvent::kThreadInstructionCountDelta:
+      DCHECK_NE(current_state_->thread_instruction_count, -1);
+      current_state_->thread_instruction_count +=
+          event.thread_instruction_count_delta();
+      return current_state_->thread_instruction_count;
+    case TrackEvent::THREAD_INSTRUCTION_COUNT_NOT_SET:
+      return base::nullopt;
+  }
+}
+
 void TrackEventJSONExporter::HandleInternedData(
     const ChromeTracePacket& packet) {
   DCHECK(packet.has_interned_data());
@@ -380,6 +395,8 @@ void TrackEventJSONExporter::HandleThreadDescriptor(
   current_state_->tid = thread.tid();
   current_state_->time_us = thread.reference_timestamp_us();
   current_state_->thread_time_us = thread.reference_thread_time_us();
+  current_state_->thread_instruction_count =
+      thread.reference_thread_instruction_count();
 
   // If we aren't outputting traceEvents then we don't need to look at the
   // metadata that might need to be emitted.
@@ -468,6 +485,8 @@ void TrackEventJSONExporter::HandleTrackEvent(const ChromeTracePacket& packet) {
   int64_t timestamp_us = ComputeTimeUs(track);
   DCHECK_NE(timestamp_us, -1);
   base::Optional<int64_t> thread_time_us = ComputeThreadTimeUs(track);
+  base::Optional<int64_t> thread_instruction_count =
+      ComputeThreadInstructionCount(track);
 
   std::vector<base::StringPiece> all_categories;
   all_categories.reserve(track.category_iids().size());
@@ -490,6 +509,10 @@ void TrackEventJSONExporter::HandleTrackEvent(const ChromeTracePacket& packet) {
     builder.AddThreadTimestamp(*thread_time_us);
   }
 
+  if (thread_instruction_count) {
+    builder.AddThreadInstructionCount(*thread_instruction_count);
+  }
+
   // Now we add args from both |task_execution| and |debug_annotations|. Recall
   // that |args_builder| must run its deconstructer before any other fields in
   // traceEvents are added. Therefore do not do anything below this comment but

services/tracing/perfetto/track_event_json_exporter.h

@@ -58,6 +58,7 @@ class TrackEventJSONExporter : public JSONTraceExporter {
     int32_t tid = -1;
     int64_t time_us = -1;
     int64_t thread_time_us = -1;
+    int64_t thread_instruction_count = -1;
 
     // We only want to add metadata events about the process or threads once.
     // This is to prevent duplicate events in the json since the packets
@@ -125,6 +126,8 @@ class TrackEventJSONExporter : public JSONTraceExporter {
   int64_t ComputeTimeUs(const perfetto::protos::TrackEvent& event);
   base::Optional<int64_t> ComputeThreadTimeUs(
       const perfetto::protos::TrackEvent& event);
+  base::Optional<int64_t> ComputeThreadInstructionCount(
+      const perfetto::protos::TrackEvent& event);
 
   // Gather all the interned strings of different types.
   void HandleInternedData(const perfetto::protos::ChromeTracePacket& packet);

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

@@ -320,6 +320,23 @@ void TrackEventThreadLocalEventSink::AddTraceEvent(
     }
   }
 
+  if (!trace_event->thread_instruction_count().is_null()) {
+    // Thread instruction counts are never user-provided, but COMPLETE events
+    // may get reordered, so we can still observe counts that are lower. Emit
+    // those as absolute counts, since we don't support negative deltas.
+    if (last_thread_instruction_count_.ToInternalValue() >
+        trace_event->thread_instruction_count().ToInternalValue()) {
+      track_event->set_thread_instruction_count_absolute(
+          trace_event->thread_instruction_count().ToInternalValue());
+    } else {
+      track_event->set_thread_instruction_count_delta(
+          (trace_event->thread_instruction_count() -
+           last_thread_instruction_count_)
+              .ToInternalValue());
+      last_thread_instruction_count_ = trace_event->thread_instruction_count();
+    }
+  }
+
   // TODO(eseckler): Split comma-separated category strings.
   track_event->add_category_iids(interned_category.id);
 
@@ -576,13 +593,29 @@ void TrackEventThreadLocalEventSink::EmitThreadDescriptor(
     last_thread_time_ = ThreadNow();
   } else {
     // Thread timestamp is never user-provided.
-    DCHECK(trace_event->thread_timestamp() <= ThreadNow());
+    DCHECK_LE(trace_event->thread_timestamp(), ThreadNow());
     last_thread_time_ = trace_event->thread_timestamp();
   }
   thread_descriptor->set_reference_timestamp_us(
       last_timestamp_.since_origin().InMicroseconds());
   thread_descriptor->set_reference_thread_time_us(
       last_thread_time_.since_origin().InMicroseconds());
+
+  if (base::trace_event::ThreadInstructionCount::IsSupported()) {
+    if (!trace_event || trace_event->thread_instruction_count().is_null()) {
+      last_thread_instruction_count_ =
+          base::trace_event::ThreadInstructionCount::Now();
+    } else {
+      // Thread instruction count is never user-provided.
+      DCHECK_LE(
+          trace_event->thread_instruction_count().ToInternalValue(),
+          base::trace_event::ThreadInstructionCount::Now().ToInternalValue());
+      last_thread_instruction_count_ = trace_event->thread_instruction_count();
+    }
+    thread_descriptor->set_reference_thread_instruction_count(
+        last_thread_instruction_count_.ToInternalValue());
+  }
+
   // TODO(eseckler): Fill in remaining fields in ThreadDescriptor.
 }
 

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

@@ -13,6 +13,7 @@
 #include "base/component_export.h"
 #include "base/threading/thread_id_name_manager.h"
 #include "base/time/time.h"
+#include "base/trace_event/thread_instruction_count.h"
 #include "services/tracing/public/cpp/perfetto/interning_index.h"
 #include "services/tracing/public/cpp/perfetto/thread_local_event_sink.h"
 #include "third_party/perfetto/include/perfetto/ext/tracing/core/trace_writer.h"
@@ -80,6 +81,7 @@ class COMPONENT_EXPORT(TRACING_CPP) TrackEventThreadLocalEventSink
   uint32_t last_incremental_state_reset_id_ = 0;
   base::TimeTicks last_timestamp_;
   base::ThreadTicks last_thread_time_;
+  base::trace_event::ThreadInstructionCount last_thread_instruction_count_;
   int process_id_;
   int thread_id_;
   std::string thread_name_;