Avoid including startTime in SpanEnd, sending it via RPC

Author: fhanau

src/workerd/io/trace.c++

@@ -1529,15 +1529,8 @@ void SpanOpenData::copyTo(rpc::SpanOpenData::Builder builder) const {
   builder.setParentSpanId(parentSpanId);
 }
 
-SpanEndData::SpanEndData(CompleteSpan&& span)
-    : spanId(span.spanId),
-      startTime(span.startTime),
-      endTime(span.endTime),
-      tags(kj::mv(span.tags)) {}
-
 SpanEndData::SpanEndData(rpc::SpanEndData::Reader reader)
     : spanId(reader.getSpanId()),
-      startTime(kj::UNIX_EPOCH + reader.getStartTimeNs() * kj::NANOSECONDS),
       endTime(kj::UNIX_EPOCH + reader.getEndTimeNs() * kj::NANOSECONDS) {
   auto tagsParam = reader.getTags();
   tags.reserve(tagsParam.size());
@@ -1548,7 +1541,6 @@ SpanEndData::SpanEndData(rpc::SpanEndData::Reader reader)
 }
 
 void SpanEndData::copyTo(rpc::SpanEndData::Builder builder) const {
-  builder.setStartTimeNs((startTime - kj::UNIX_EPOCH) / kj::NANOSECONDS);
   builder.setEndTimeNs((endTime - kj::UNIX_EPOCH) / kj::NANOSECONDS);
   builder.setSpanId(spanId);
 

src/workerd/io/trace.capnp

@@ -57,13 +57,10 @@ struct SpanEndData {
   # Representation of an event that indicates completion of a user span. This information is
   # provided to the streaming tail worker in the Attributes and SpanClose events.
 
-  # TODO(cleanup): startTimeNs is merely used as a fallback timestamp, consider obsoleting it.
-  startTimeNs @0 :Int64;
-  # Nanoseconds since Unix epoch
-  endTimeNs @1 :Int64;
+  endTimeNs @0 :Int64;
   # Nanoseconds since Unix epoch
 
   # List of span attributes
-  tags @2 :List(Tag);
-  spanId @3 :UInt64;
+  tags @1 :List(Tag);
+  spanId @2 :UInt64;
 }

src/workerd/io/trace.h

@@ -671,22 +671,17 @@ struct SpanEndData {
   // Represents the data needed when closing a span, including the Attributes and SpanClose events.
   tracing::SpanId spanId;
 
-  kj::Date startTime;
   kj::Date endTime;
   // Should be Span::TagMap, but we can't forward-declare that.
   kj::HashMap<kj::ConstString, tracing::Attribute::Value> tags;
 
-  // Convert CompleteSpan to SpanEndData
-  explicit SpanEndData(CompleteSpan&& span);
   SpanEndData(rpc::SpanEndData::Reader reader);
   void copyTo(rpc::SpanEndData::Builder builder) const;
   explicit SpanEndData(tracing::SpanId spanId,
-      kj::Date startTime,
       kj::Date endTime,
       kj::HashMap<kj::ConstString, tracing::Attribute::Value> tags =
           kj::HashMap<kj::ConstString, tracing::Attribute::Value>())
       : spanId(spanId),
-        startTime(startTime),
         endTime(endTime),
         tags(kj::mv(tags)) {}
 };

src/workerd/io/tracer.c++

@@ -127,8 +127,8 @@ void WorkerTracer::addSpan(tracing::CompleteSpan&& span) {
   // The span information is not transmitted via RPC at this point, we can decompose the span into
   // spanOpen/spanEnd.
   addSpanOpen(span.spanId, span.parentSpanId, kj::mv(span.operationName), span.startTime);
-  tracing::SpanEndData spanEnd(kj::mv(span));
-  addSpanEnd(kj::mv(spanEnd));
+  tracing::SpanEndData spanEnd(span.spanId, span.endTime, kj::mv(span.tags));
+  addSpanEnd(kj::mv(spanEnd), span.startTime);
 }
 
 void WorkerTracer::addSpanOpen(tracing::SpanId spanId,
@@ -154,7 +154,7 @@ void WorkerTracer::addSpanOpen(tracing::SpanId spanId,
       spanOpenContext, tracing::SpanOpen(spanId, kj::mv(operationName)), startTime, spanNameSize);
 }
 
-void WorkerTracer::addSpanEnd(tracing::SpanEndData&& span) {
+void WorkerTracer::addSpanEnd(tracing::SpanEndData&& span, kj::Maybe<kj::Date> maybeStartTime) {
   if (pipelineLogLevel == PipelineLogLevel::NONE) {
     return;
   }
@@ -163,7 +163,7 @@ void WorkerTracer::addSpanEnd(tracing::SpanEndData&& span) {
   // variable for it and it can't cause truncation.
   auto& tailStreamWriter = KJ_UNWRAP_OR_RETURN(maybeTailStreamWriter);
 
-  adjustSpanTime(span);
+  adjustSpanTime(span, maybeStartTime);
 
   size_t spanTagsSize = 0;
   for (const Span::TagMap::Entry& tag: span.tags) {
@@ -192,7 +192,7 @@ void WorkerTracer::addSpanEnd(tracing::SpanEndData&& span) {
     tracing::CustomInfo attr = KJ_MAP(tag, span.tags) {
       return tracing::Attribute(kj::mv(tag.key), kj::mv(tag.value));
     };
-    tailStreamWriter->report(spanComponentContext, kj::mv(attr), span.startTime, spanTagsSize);
+    tailStreamWriter->report(spanComponentContext, kj::mv(attr), span.endTime, spanTagsSize);
   }
   tailStreamWriter->report(spanComponentContext, tracing::SpanClose(), span.endTime, 0);
 }
@@ -459,14 +459,18 @@ void BaseTracer::adjustSpanTime(tracing::CompleteSpan& span) {
   }
 }
 
-void BaseTracer::adjustSpanTime(tracing::SpanEndData& span) {
+void BaseTracer::adjustSpanTime(tracing::SpanEndData& span, kj::Maybe<kj::Date> maybeStartTime) {
   // To report I/O time, we need the IOContext to still be alive.
   // weakIoContext is only none if we are tracing via RPC (in this case span times have already been
   // adjusted) or if we failed to transmit an Onset event (in that case we'll get an error based on
   // missing topLevelInvocationSpanContext right after).
   if (weakIoContext != kj::none) {
     auto& weakIoCtx = KJ_ASSERT_NONNULL(weakIoContext);
-    weakIoCtx->runIfAlive([this, &span](IoContext& context) {
+    // startTime is generally available when we are not tracing via RPC, so we can assert that it is
+    // present. For the RPC case, the adjustment will already have been done earlier and it's ok
+    // for maybeStartTime to be none as this code won't run based on weakIoContext being none.
+    kj::Date startTime = KJ_ASSERT_NONNULL(maybeStartTime);
+    weakIoCtx->runIfAlive([this, &span, &startTime](IoContext& context) {
       if (context.hasCurrentIncomingRequest()) {
         span.endTime = context.now();
       } else {
@@ -478,7 +482,7 @@ void BaseTracer::adjustSpanTime(tracing::SpanEndData& span) {
           span.endTime = completeTime;
           hasCompleteTime = true;
         } else {
-          span.endTime = span.startTime;
+          span.endTime = startTime;
         }
         if (isPredictableModeForTest()) {
           KJ_FAIL_ASSERT("reported span without current request", hasCompleteTime);
@@ -498,7 +502,7 @@ void BaseTracer::adjustSpanTime(tracing::SpanEndData& span) {
       } else {
         // Otherwise, we can't actually get an end timestamp that makes sense. Report a zero-duration
         // span and log a warning (or fail assert in test mode).
-        span.endTime = span.startTime;
+        span.endTime = startTime;
         if (isPredictableModeForTest()) {
           KJ_FAIL_ASSERT("reported span after IoContext was deallocated");
         } else {

src/workerd/io/tracer.h

@@ -39,7 +39,7 @@ class BaseTracer: public kj::Refcounted {
       kj::ConstString operationName,
       kj::Date startTime) = 0;
   // Add span events when the span is complete (Attributes and SpanClose).
-  virtual void addSpanEnd(tracing::SpanEndData&& span) = 0;
+  virtual void addSpanEnd(tracing::SpanEndData&& span, kj::Maybe<kj::Date> maybeStartTime) = 0;
 
   virtual void addException(const tracing::InvocationSpanContext& context,
       kj::Date timestamp,
@@ -97,7 +97,7 @@ class BaseTracer: public kj::Refcounted {
 
   // helper method for addSpan() implementations
   void adjustSpanTime(tracing::CompleteSpan& span);
-  void adjustSpanTime(tracing::SpanEndData& span);
+  void adjustSpanTime(tracing::SpanEndData& span, kj::Maybe<kj::Date> maybeStartTime);
 
   // Function to create the root span for the new tracing format.
   kj::Maybe<MakeUserRequestSpanFunc> makeUserRequestSpanFunc;
@@ -138,7 +138,7 @@ class WorkerTracer final: public BaseTracer {
       tracing::SpanId parentSpanId,
       kj::ConstString operationName,
       kj::Date startTime) override;
-  void addSpanEnd(tracing::SpanEndData&& span) override;
+  void addSpanEnd(tracing::SpanEndData&& span, kj::Maybe<kj::Date> maybeStartTime) override;
   void addException(const tracing::InvocationSpanContext& context,
       kj::Date timestamp,
       kj::String name,

src/workerd/server/server.c++

@@ -1703,16 +1703,17 @@ class SequentialSpanSubmitter final: public SpanSubmitter {
   void submitSpan(tracing::SpanId spanId, tracing::SpanId parentSpanId, const Span& span) override {
     // This code path is workerd-only, we can safely utilize submitSpanOpen here.
     submitSpanOpen(spanId, parentSpanId, span.operationName.clone(), span.startTime);
-    tracing::SpanEndData span2(spanId, span.startTime, span.endTime);
+    kj::Date startTime = span.startTime;
+    tracing::SpanEndData span2(spanId, span.endTime);
     span2.tags.reserve(span.tags.size());
     for (auto& tag: span.tags) {
       span2.tags.insert(tag.key.clone(), spanTagClone(tag.value));
     }
     if (isPredictableModeForTest()) {
-      span2.startTime = span2.endTime = kj::UNIX_EPOCH;
+      startTime = span2.endTime = kj::UNIX_EPOCH;
     }
 
-    workerTracer->addSpanEnd(kj::mv(span2));
+    workerTracer->addSpanEnd(kj::mv(span2), startTime);
   }
 
   void submitSpanOpen(tracing::SpanId spanId,