perfetto: Collect and emit stats for proto2json conversion

To aid debugging data loss issues.

Bug: 914092, 1008424
Change-Id: I06b91acd892970b6bba251c1893247debf61b16a
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1835577Reviewed-by: Stephen Nusko <nuskos@chromium.org>
Commit-Queue: Eric Seckler <eseckler@chromium.org>
Cr-Commit-Position: refs/heads/master@{#702030}

services/tracing/perfetto/json_trace_exporter.cc

@@ -359,6 +359,17 @@ void JSONTraceExporter::SetTraceStatsMetadata(
   metadata_->SetDictionary("perfetto_trace_stats", std::move(dict));
 }
 
+void JSONTraceExporter::AddMetadata(const std::string& entry_name,
+                                    std::unique_ptr<base::Value> value) {
+  if (!metadata_filter_predicate_.is_null() &&
+      !metadata_filter_predicate_.Run(entry_name)) {
+    metadata_->SetString(entry_name, kStrippedArgument);
+    return;
+  }
+
+  metadata_->Set(entry_name, std::move(value));
+}
+
 JSONTraceExporter::ScopedJSONTraceEventAppender
 JSONTraceExporter::AddTraceEvent(const char* name,
                                  const char* categories,

services/tracing/perfetto/json_trace_exporter.h

@@ -255,6 +255,9 @@ class JSONTraceExporter {
                                              int32_t pid,
                                              int32_t tid);
 
+  void AddMetadata(const std::string& entry_name,
+                   std::unique_ptr<base::Value> value);
+
  private:
   // Used by the implementation to ensure the proper separators exist between
   // trace events in the array.

services/tracing/perfetto/track_event_json_exporter.cc

@@ -94,17 +94,17 @@ void TrackEventJSONExporter::ProcessPackets(
     // and wait for the first state_clear before emitting anything.
     if (packet.trusted_packet_sequence_id() !=
         current_state_->trusted_packet_sequence_id) {
+      stats_.sequences_seen++;
       StartNewState(packet.trusted_packet_sequence_id(),
                     packet.incremental_state_cleared());
     } else if (packet.incremental_state_cleared()) {
+      stats_.incremental_state_resets++;
       ResetIncrementalState();
     } else if (packet.previous_packet_dropped()) {
       // If we've lost packets we can no longer trust any timestamp data and
       // other state which might have been dropped. We will keep skipping events
       // until we start a new sequence.
-      LOG_IF(ERROR, current_state_->incomplete)
-          << "Previous packet was dropped. Skipping TraceEvents until reset or "
-          << "new sequence.";
+      stats_.packets_with_previous_packet_dropped++;
       current_state_->incomplete = true;
     }
 
@@ -136,6 +136,7 @@ void TrackEventJSONExporter::ProcessPackets(
   }
   if (!has_more) {
     EmitThreadDescriptorIfNeeded();
+    EmitStats();
   }
 }
 
@@ -227,6 +228,7 @@ void TrackEventJSONExporter::HandleInternedData(
 
   // InternedData is only emitted on sequences with incremental state.
   if (current_state_->incomplete) {
+    stats_.packets_dropped_invalid_incremental_state++;
     return;
   }
 
@@ -311,6 +313,7 @@ void TrackEventJSONExporter::HandleProcessDescriptor(
 
   // ProcessDescriptor is only emitted on sequences with incremental state.
   if (current_state_->incomplete) {
+    stats_.packets_dropped_invalid_incremental_state++;
     return;
   }
 
@@ -388,6 +391,7 @@ void TrackEventJSONExporter::HandleThreadDescriptor(
 
   // ThreadDescriptor is only emitted on sequences with incremental state.
   if (current_state_->incomplete) {
+    stats_.packets_dropped_invalid_incremental_state++;
     return;
   }
 
@@ -472,6 +476,7 @@ void TrackEventJSONExporter::HandleTrackEvent(const ChromeTracePacket& packet) {
 
   // TrackEvents need incremental state.
   if (current_state_->incomplete) {
+    stats_.packets_dropped_invalid_incremental_state++;
     return;
   }
 
@@ -500,12 +505,8 @@ void TrackEventJSONExporter::HandleTrackEvent(const ChromeTracePacket& packet) {
   const std::string joined_categories = base::JoinString(all_categories, ",");
 
   DCHECK(track.has_legacy_event()) << "required field legacy_event missing";
-  auto maybe_builder =
+  auto builder =
       HandleLegacyEvent(track.legacy_event(), joined_categories, timestamp_us);
-  if (!maybe_builder) {
-    return;
-  }
-  auto& builder = *maybe_builder;
 
   if (thread_time_us) {
     builder.AddThreadTimestamp(*thread_time_us);
@@ -532,7 +533,12 @@ void TrackEventJSONExporter::HandleTrackEvent(const ChromeTracePacket& packet) {
 
 void TrackEventJSONExporter::HandleStreamingProfilePacket(
     const perfetto::protos::StreamingProfilePacket& profile_packet) {
-  if (current_state_->incomplete || !ShouldOutputTraceEvents()) {
+  if (current_state_->incomplete) {
+    stats_.packets_dropped_invalid_incremental_state++;
+    return;
+  }
+
+  if (!ShouldOutputTraceEvents()) {
     return;
   }
 
@@ -701,7 +707,7 @@ void TrackEventJSONExporter::HandleTaskExecution(
   }
 }
 
-base::Optional<JSONTraceExporter::ScopedJSONTraceEventAppender>
+JSONTraceExporter::ScopedJSONTraceEventAppender
 TrackEventJSONExporter::HandleLegacyEvent(const TrackEvent::LegacyEvent& event,
                                           const std::string& categories,
                                           int64_t timestamp_us) {
@@ -791,4 +797,17 @@ TrackEventJSONExporter::HandleLegacyEvent(const TrackEvent::LegacyEvent& event,
   builder.AddFlags(flags, id, event.id_scope());
   return builder;
 }
+
+void TrackEventJSONExporter::EmitStats() {
+  auto value = std::make_unique<base::DictionaryValue>();
+  value->SetInteger("sequences_seen", stats_.sequences_seen);
+  value->SetInteger("incremental_state_resets",
+                    stats_.incremental_state_resets);
+  value->SetInteger("packets_dropped_invalid_incremental_state",
+                    stats_.packets_dropped_invalid_incremental_state);
+  value->SetInteger("packets_with_previous_packet_dropped",
+                    stats_.packets_with_previous_packet_dropped);
+  AddMetadata("json_exporter_stats", std::move(value));
+}
+
 }  // namespace tracing

services/tracing/perfetto/track_event_json_exporter.h

@@ -154,17 +154,27 @@ class TrackEventJSONExporter : public JSONTraceExporter {
                            ArgumentBuilder* args_builder);
 
   // Used to handle the LegacyEvent message found inside the TrackEvent proto.
-  base::Optional<ScopedJSONTraceEventAppender> HandleLegacyEvent(
+  ScopedJSONTraceEventAppender HandleLegacyEvent(
       const perfetto::protos::TrackEvent_LegacyEvent& event,
       const std::string& categories,
       int64_t timestamp_us);
 
+  void EmitStats();
+
   // Tracks all the interned state in the current sequence.
   std::unique_ptr<ProducerWriterState> current_state_;
 
   // Tracks out-of-order seqeuence data.
   std::map<uint32_t, UnorderedProducerWriterState> unordered_state_data_;
 
+  struct Stats {
+    int sequences_seen = 0;
+    int incremental_state_resets = 0;
+    int packets_dropped_invalid_incremental_state = 0;
+    int packets_with_previous_packet_dropped = 0;
+  };
+  Stats stats_;
+
   DISALLOW_COPY_AND_ASSIGN(TrackEventJSONExporter);
 };
 

services/tracing/perfetto/track_event_json_exporter_unittest.cc

@@ -414,7 +414,8 @@ TEST_F(TrackEventJsonExporterTest, EmptyProcessDescriptor) {
   FinalizePackets(trace_packet_protos);
   // No traceEvents or data was emitted but a process descriptor without extra
   // data should just be an empty array and not cause crashes.
-  EXPECT_EQ("{\"traceEvents\":[]}", unparsed_trace_data_);
+  EXPECT_THAT(unparsed_trace_data_,
+              testing::StartsWith("{\"traceEvents\":[],"));
 }
 
 TEST_F(TrackEventJsonExporterTest, SortIndexProcessDescriptor) {
@@ -575,7 +576,8 @@ TEST_F(TrackEventJsonExporterTest, EmptyThreadDescriptor) {
   FinalizePackets(trace_packet_protos);
   // No traceEvents or data was emitted but a thread descriptor should be an
   // empty array and not cause crashes.
-  EXPECT_EQ("{\"traceEvents\":[]}", unparsed_trace_data_);
+  EXPECT_THAT(unparsed_trace_data_,
+              testing::StartsWith("{\"traceEvents\":[],"));
 }
 
 TEST_F(TrackEventJsonExporterTest, SortIndexThreadDescriptor) {
@@ -715,7 +717,8 @@ TEST_F(TrackEventJsonExporterTest, JustInternedData) {
                             &trace_packet_protos);
   FinalizePackets(trace_packet_protos);
   // Interned data by itself does not call any trace events to be emitted.
-  EXPECT_EQ("{\"traceEvents\":[]}", unparsed_trace_data_);
+  EXPECT_THAT(unparsed_trace_data_,
+              testing::StartsWith("{\"traceEvents\":[],"));
 }
 
 TEST_F(TrackEventJsonExporterTest, LegacyEventBasicTest) {
@@ -1758,10 +1761,11 @@ TEST_F(TrackEventJsonExporterTest, TestTraceStats) {
   // base class. See json_trace_exporter_unittest for a more complete test.
   trace_packet_protos.back().mutable_trace_stats();
   FinalizePackets(trace_packet_protos);
-  EXPECT_TRUE(base::StartsWith(unparsed_trace_data_,
-                               "{\"traceEvents\":[],"
-                               "\"metadata\":{\"perfetto_trace_stats\":{\"",
-                               base::CompareCase::SENSITIVE));
+
+  EXPECT_THAT(unparsed_trace_data_, testing::StartsWith("{\"traceEvents\":[],"
+                                                        "\"metadata\":{"));
+  EXPECT_THAT(unparsed_trace_data_,
+              testing::HasSubstr("\"perfetto_trace_stats\":{\""));
 }
 
 TEST_F(TrackEventJsonExporterTest, ComplexLongSequenceWithDroppedPackets) {