tp: suppress spurious clock sync errors for deferred packets

When a packet arrives with a sequence-scoped clock before its
ClockSnapshot, ToTraceTime fails and records a spurious
clock_sync_failure_unknown_source_clock error even though the
packet will be resolved later at EOF.

Fix this by plumbing a suppress_errors bool through the conversion
path (ClockSynchronizer::Convert -> ConvertSlowpath). Before EOF,
errors are suppressed and the packet is deferred. At EOF, errors
are allowed so genuinely broken clocks are still reported.

Extract the convert-or-defer logic into an inline helper
ResolveTimestampToTraceTime with a clear three-state return
(kResolved, kDeferred, kDropped) to make the hot path readable.

Add clock_sync_failure_undeferrable_packet_loss stat (with import
logging) for the rare case where conversion fails and deferral
is not possible.

Bug: #5163

Author: LalitMaganti

src/trace_processor/importers/common/clock_tracker.h

@@ -64,14 +64,15 @@ class ClockTracker {
   PERFETTO_ALWAYS_INLINE std::optional<int64_t> ToTraceTime(
       ClockId clock_id,
       int64_t timestamp,
-      std::optional<size_t> byte_offset = std::nullopt) {
+      std::optional<size_t> byte_offset = std::nullopt,
+      bool suppress_errors = false) {
     if (PERFETTO_UNLIKELY(deferred_identity_clock_.has_value())) {
       FlushDeferredIdentitySync();
     }
     auto* state = context_->trace_time_state.get();
     ++num_conversions_;
     auto ts = active_sync_->Convert(clock_id, timestamp, state->clock_id,
-                                    byte_offset);
+                                    byte_offset, suppress_errors);
     return ts ? std::optional(ToHostTraceTime(*ts)) : ts;
   }
 

src/trace_processor/importers/proto/proto_trace_reader.cc

@@ -380,6 +380,34 @@ base::Status ProtoTraceReader::ParsePacket(TraceBlobView packet) {
   return TimestampTokenizeAndPushToSorter(std::move(packet));
 }
 
+ProtoTraceReader::ClockResolution ProtoTraceReader::ResolveTimestampToTraceTime(
+    ClockTracker::ClockId clock_id,
+    int64_t* timestamp,
+    TraceBlobView* packet) {
+  // Before EOF, suppress errors: the clock snapshot may arrive later and
+  // the packet will be retried at EOF. At EOF, allow errors so genuinely
+  // broken clocks are reported.
+  bool suppress_errors = !received_eof_;
+  auto trace_ts = context_->clock_tracker->ToTraceTime(
+      clock_id, *timestamp, packet->offset(), suppress_errors);
+  if (PERFETTO_LIKELY(trace_ts.has_value())) {
+    *timestamp = *trace_ts;
+    return ClockResolution::kResolved;
+  }
+
+  // Conversion failed. Before EOF, try to defer for later resolution.
+  if (!received_eof_ &&
+      context_->sorter->SetSortingMode(TraceSorter::SortingMode::kFullSort)) {
+    eof_deferred_packets_.push_back(std::move(*packet));
+    return ClockResolution::kDeferred;
+  }
+
+  // Cannot defer: record the error and drop the packet.
+  context_->import_logs_tracker->RecordTokenizationError(
+      stats::clock_sync_failure_undeferrable_packet_loss, packet->offset());
+  return ClockResolution::kDropped;
+}
+
 base::Status ProtoTraceReader::TimestampTokenizeAndPushToSorter(
     TraceBlobView packet) {
   protos::pbzero::TracePacket::Decoder decoder(packet.data(), packet.length());
@@ -439,23 +467,12 @@ base::Status ProtoTraceReader::TimestampTokenizeAndPushToSorter(
       } else {
         converted_clock_id = ClockId::Machine(timestamp_clock_id);
       }
-      auto trace_ts = context_->clock_tracker->ToTraceTime(
-          converted_clock_id, timestamp, packet.offset());
-      if (!trace_ts) {
-        // We need to switch to full sorting mode to ensure that packets with
-        // missing timestamp are handled correctly. Don't save the packet unless
-        // switching to full sorting mode succeeded.
-        if (!received_eof_ && context_->sorter->SetSortingMode(
-                                  TraceSorter::SortingMode::kFullSort)) {
-          eof_deferred_packets_.push_back(std::move(packet));
-          return base::OkStatus();
-        }
-        // We don't return an error here as it will cause the trace to stop
-        // parsing. Instead, we rely on the stat increment (which happened
-        // automatically in ToTraceTime) to inform the user about the error.
+      auto resolution =
+          ResolveTimestampToTraceTime(converted_clock_id, &timestamp, &packet);
+      if (resolution == ClockResolution::kDeferred ||
+          resolution == ClockResolution::kDropped) {
         return base::OkStatus();
       }
-      timestamp = *trace_ts;
     }
   } else {
     timestamp = std::max(latest_timestamp_, context_->sorter->max_timestamp());

src/trace_processor/importers/proto/proto_trace_reader.h

@@ -89,6 +89,20 @@ class ProtoTraceReader : public ChunkedTraceReader {
     uint32_t needs_incremental_state_skipped = 0;
   };
 
+  // Result of attempting to resolve a packet's timestamp to trace time.
+  enum class ClockResolution {
+    kResolved,  // Timestamp was successfully converted.
+    kDeferred,  // Packet deferred for resolution at EOF.
+    kDropped,   // Conversion failed and packet cannot be deferred.
+  };
+
+  // Hot-path: converts |timestamp| from |clock_id| to trace time. If the
+  // clock is not yet known, defers the packet for resolution at EOF.
+  PERFETTO_ALWAYS_INLINE ClockResolution
+  ResolveTimestampToTraceTime(ClockTracker::ClockId clock_id,
+                              int64_t* timestamp,
+                              TraceBlobView* packet);
+
   using ConstBytes = protozero::ConstBytes;
   base::Status ParsePacket(TraceBlobView);
   base::Status TimestampTokenizeAndPushToSorter(TraceBlobView);

src/trace_processor/importers/proto/proto_trace_reader_unittest.cc

@@ -36,6 +36,7 @@
 #include "src/trace_processor/importers/common/metadata_tracker.h"
 #include "src/trace_processor/importers/proto/additional_modules.h"
 #include "src/trace_processor/sorter/trace_sorter.h"
+#include "src/trace_processor/storage/stats.h"
 #include "src/trace_processor/storage/trace_storage.h"
 #include "src/trace_processor/types/trace_processor_context.h"
 #include "src/trace_processor/types/trace_processor_context_ptr.h"
@@ -257,5 +258,32 @@ TEST_F(ProtoTraceReaderTest, CalculateClockOffset_MultiRounds) {
   ASSERT_EQ(-114375, clock_offsets[ClockId::Machine(BOOTTIME)]);
 }
 
+TEST_F(ProtoTraceReaderTest, DeferredClockSnapshotSequenceScopedClock) {
+  // Packet 1: has a sequence-scoped clock (64) but no clock snapshot yet.
+  // This will fail ToTraceTime and be deferred for later processing.
+  auto* packet1 = trace_->add_packet();
+  packet1->set_trusted_packet_sequence_id(1);
+  packet1->set_timestamp(1000);
+  packet1->set_timestamp_clock_id(64);
+
+  // Packet 2: clock snapshot on the same sequence mapping clock 64 -> BOOTTIME.
+  auto* packet2 = trace_->add_packet();
+  packet2->set_trusted_packet_sequence_id(1);
+  auto* snap = packet2->set_clock_snapshot();
+  auto* clk1 = snap->add_clocks();
+  clk1->set_clock_id(64);
+  clk1->set_timestamp(10);
+  auto* clk2 = snap->add_clocks();
+  clk2->set_clock_id(BOOTTIME);
+  clk2->set_timestamp(10000);
+
+  ASSERT_TRUE(Tokenize().ok());
+  ASSERT_TRUE(proto_trace_reader_->OnPushDataToSorter().ok());
+
+  // The deferred packet should have resolved without recording an error.
+  EXPECT_EQ(0, host_context_.storage->GetStats(
+                   stats::clock_sync_failure_unknown_source_clock));
+}
+
 }  // namespace
 }  // namespace perfetto::trace_processor

src/trace_processor/storage/stats.h

@@ -304,6 +304,15 @@ namespace perfetto::trace_processor::stats {
       "snapshots and its own for timestamp conversion. Timestamps "            \
       "converted before the first own clock snapshot used the primary "        \
       "trace's clocks which may differ."),                                     \
+  F(clock_sync_failure_undeferrable_packet_loss, kSingle, kDataLoss,          \
+      kAnalysis,                                                               \
+      "A packet had a timestamp with a clock ID that could not be resolved "   \
+      "to trace time and the packet could not be deferred for later "          \
+      "resolution (the trace sorter was unable to switch to full-sort mode). " \
+      "The packet was dropped and its data will be missing from query "        \
+      "results. This can happen when a sequence-scoped clock (64-127) is "    \
+      "used before the ClockSnapshot defining it arrives, and the sorter "     \
+      "has already started flushing."),                                        \
   F(clock_sync_cache_miss,                kSingle,  kInfo,     kAnalysis, ""), \
   F(process_tracker_errors,               kSingle,  kError,    kAnalysis, ""), \
   F(namespaced_thread_missing_process,    kSingle,  kError,    kAnalysis,      \

src/trace_processor/util/clock_synchronizer.cc

@@ -202,25 +202,28 @@ std::optional<int64_t> ClockSynchronizer::ConvertSlowpath(
     int64_t src_timestamp,
     std::optional<int64_t> src_ts_ns,
     ClockId target_clock_id,
-    std::optional<size_t> byte_offset) {
+    std::optional<size_t> byte_offset,
+    bool suppress_errors) {
   PERFETTO_DCHECK(!src_clock_id.IsSequenceClock() || src_clock_id.seq_id != 0);
   PERFETTO_DCHECK(!target_clock_id.IsSequenceClock() ||
                   target_clock_id.seq_id != 0);
   clock_event_listener_->OnClockSyncCacheMiss();
 
   ClockPath path = FindPath(src_clock_id, target_clock_id);
   if (!path.valid()) {
-    // Determine which clock(s) are unknown and record error
-    ClockSyncErrorType error;
-    if (clocks_.find(src_clock_id) == clocks_.end()) {
-      error = ClockSyncErrorType::kUnknownSourceClock;
-    } else if (clocks_.find(target_clock_id) == clocks_.end()) {
-      error = ClockSyncErrorType::kUnknownTargetClock;
-    } else {
-      error = ClockSyncErrorType::kNoPath;
+    if (!suppress_errors) {
+      // Determine which clock(s) are unknown and record error
+      ClockSyncErrorType error;
+      if (clocks_.find(src_clock_id) == clocks_.end()) {
+        error = ClockSyncErrorType::kUnknownSourceClock;
+      } else if (clocks_.find(target_clock_id) == clocks_.end()) {
+        error = ClockSyncErrorType::kUnknownTargetClock;
+      } else {
+        error = ClockSyncErrorType::kNoPath;
+      }
+      clock_event_listener_->RecordConversionError(
+          error, src_clock_id, target_clock_id, src_timestamp, byte_offset);
     }
-    clock_event_listener_->RecordConversionError(
-        error, src_clock_id, target_clock_id, src_timestamp, byte_offset);
     return std::nullopt;
   }
 

src/trace_processor/util/clock_synchronizer.h

@@ -260,7 +260,8 @@ class ClockSynchronizer {
   std::optional<int64_t> Convert(ClockId src_clock_id,
                                  int64_t src_timestamp,
                                  ClockId target_clock_id,
-                                 std::optional<size_t> byte_offset) {
+                                 std::optional<size_t> byte_offset,
+                                 bool suppress_errors = false) {
     if (PERFETTO_LIKELY(src_clock_id == target_clock_id)) {
       return src_timestamp;
     }
@@ -282,7 +283,7 @@ class ClockSynchronizer {
       }
     }
     return ConvertSlowpath(src_clock_id, src_timestamp, ns, target_clock_id,
-                           byte_offset);
+                           byte_offset, suppress_errors);
   }
 
   // For testing:
@@ -386,7 +387,8 @@ class ClockSynchronizer {
                                          int64_t src_timestamp,
                                          std::optional<int64_t> src_ts_ns,
                                          ClockId target_clock_id,
-                                         std::optional<size_t> byte_offset);
+                                         std::optional<size_t> byte_offset,
+                                         bool suppress_errors);
 
   // Returns whether |global_clock_id| represents a sequence-scoped clock, i.e.
   // a ClockId returned by SequenceToGlobalClock().