finagle-core,util-core,util-benchmark: tag traces with microsecond ti…

…mestamp resolution

Problem

Currently traces are stamped with millisecond resolution timestamps. This makes
it hard to sequence within traces because events often occur less than a
millisecond apart. In addition we cannot derive meaningful information about
relative timing of events.

Solution/Result

Offer a new method on the Time object to allow us to gather timestamps at
nanosecond resolution so that, when using a JDK that supports it, we will
have more precise timing information in traces.

JIRA Issues: CSL-8695

Differential Revision: https://phabricator.twitter.biz/D400661

CHANGELOG.rst

@@ -34,6 +34,9 @@ Changes
 
  * finagle: Upgrade Jackson dependency from version `2.9.9` to version `2.10.1` ``PHAB_ID=D402722``
 
+ * finagle-zipkin-core: Tracing produces microsecond resolution timestamps in JDK9 or later. 
+   ``PHAB_ID=D400661``
+
 19.11.0
 -------
 

finagle-core/src/main/scala/com/twitter/finagle/tracing/Tracing.scala

@@ -162,11 +162,17 @@ abstract class Tracing {
    */
   final def isTerminal: Boolean = id.terminal
 
+  // The underlying tracing format allows us to add annotations to
+  // traces with microsecond resolution. Unfortunately Time.now only
+  // gives us millisecond resolution so we need to use a higher
+  // precision clock for our timestamps. We use a nanosecond clock,
+  // which will allow us to truncate to microseconds when
+  // we finally persist this trace.
   final def record(ann: Annotation): Unit =
-    record(Record(id, Time.now, ann, None))
+    record(Record(id, Time.nowNanoPrecision, ann, None))
 
   final def record(ann: Annotation, duration: Duration): Unit =
-    record(Record(id, Time.now, ann, Some(duration)))
+    record(Record(id, Time.nowNanoPrecision, ann, Some(duration)))
 
   final def recordWireSend(): Unit =
     record(Annotation.WireSend)

finagle-zipkin-core/src/main/scala/com/twitter/finagle/zipkin/core/DeadlineSpanMap.scala

@@ -61,7 +61,8 @@ private class DeadlineSpanMap(
         // it's already been flushed. copy most of it and immediately log it.
         val copy = ms.copyForImmediateLogging()
         f(copy)
-        copy.addAnnotation(ZipkinAnnotation(Time.now, "finagle.zipkin.late_arrival", ms.endpoint))
+        copy.addAnnotation(
+          ZipkinAnnotation(Time.nowNanoPrecision, "finagle.zipkin.late_arrival", ms.endpoint))
         Some(copy)
       } else {
         f(ms)

finagle-zipkin-core/src/main/scala/com/twitter/finagle/zipkin/core/Span.scala

@@ -37,7 +37,15 @@ case class Span(
     annotations: Seq[ZipkinAnnotation],
     bAnnotations: Seq[BinaryAnnotation],
     endpoint: Endpoint
-  ) = this(traceId, _serviceName, _name, annotations, bAnnotations, endpoint, created = Time.now)
+  ) =
+    this(
+      traceId,
+      _serviceName,
+      _name,
+      annotations,
+      bAnnotations,
+      endpoint,
+      created = Time.nowNanoPrecision)
 
   // If necessary, we compute the timestamp of when the span was created
   // which we serialize and send to the collector.
@@ -102,7 +110,7 @@ case class Span(
 
 object Span {
   def apply(traceId: TraceId): Span =
-    Span(traceId, None, None, Nil, Nil, Endpoint.Unknown, Time.now)
+    Span(traceId, None, None, Nil, Nil, Endpoint.Unknown, Time.nowNanoPrecision)
 
   def apply(
     traceId: TraceId,
@@ -112,5 +120,5 @@ object Span {
     bAnnotations: Seq[BinaryAnnotation],
     endpoint: Endpoint
   ): Span =
-    Span(traceId, _serviceName, _name, annotations, bAnnotations, endpoint, Time.now)
+    Span(traceId, _serviceName, _name, annotations, bAnnotations, endpoint, Time.nowNanoPrecision)
 }