finagle-core: move Trace helpers to Tracing

Problem: Using the `Trace.traceLocal` or other APIs results in multiple lookups. We recommend our customers to first capture a trace via `Trace.apply` before doing any actual tracing. We should do the same for `traceLocal` and variant APIs. Solution: Move things besides `letId`, `letTracers`, etc into `Tracing`. Result: Add `isActivelyTracing` guards to each of the APIs as well. JIRA Issues: CSL-10782 Differential Revision: https://phabricator.twitter.biz/D633318
twitter · Mar 13, 2021 · ec0097c · ec0097c
1 parent 8a48eab
commit ec0097c
Show file tree

Hide file tree

Showing 3 changed files with 148 additions and 144 deletions.
diff --git a/CHANGELOG.rst b/CHANGELOG.rst
@@ -34,6 +34,10 @@ Breaking API Changes
 Runtime Behavior Changes
 ~~~~~~~~~~~~~~~~~~~~~~~~
 
+* finagle-core: Move helper tracing methods like `traceLocal` in `Trace` into the `Tracing` class. This
+  allows cheaper use of these APIs by first capturing a Trace via `Trace#apply`, avoiding the extra lookups
+  that will add overhead on the request path. ``PHAB_ID=D633318``.
+
 * finagle-core: `c.t.finagle.InetResolver`, `c.t.finagle.builder.ClientBuilder`,
   `c.t.finagle.liveness.FailureAccrualFactory`, `c.t.finagle.liveness.FailureAccrualPolicy`,
   `c.t.finagle.param.ClientParams`, `c.t.finagle.param.SessionQualificationParams`,

diff --git a/finagle-core/src/main/scala/com/twitter/finagle/tracing/Trace.scala b/finagle-core/src/main/scala/com/twitter/finagle/tracing/Trace.scala
@@ -1,11 +1,9 @@
 package com.twitter.finagle.tracing
 
-import com.twitter.finagle.Init
+import com.twitter.app.GlobalFlag
 import com.twitter.finagle.context.Contexts
 import com.twitter.io.Buf
-import com.twitter.util._
-import java.net.InetSocketAddress
-import com.twitter.app.GlobalFlag
+import com.twitter.util.Try
 
 object traceId128Bit
     extends GlobalFlag[Boolean](
@@ -192,143 +190,4 @@ object Trace extends Tracing {
         f
       }
     }
-
-  /**
-   * Convenience method for event loops in services.  Put your
-   * service handling code inside this to get proper tracing with all
-   * the correct fields filled in.
-   */
-  def traceService[T](
-    service: String,
-    rpc: String,
-    hostOpt: Option[InetSocketAddress] = None
-  )(
-    f: => T
-  ): T = Trace.letId(Trace.nextId) {
-    val trace = Trace()
-    if (trace.isActivelyTracing) {
-      trace.recordBinary("finagle.version", Init.finagleVersion)
-      trace.recordServiceName(service)
-      trace.recordRpc(rpc)
-
-      hostOpt match {
-        case Some(addr) => trace.recordServerAddr(addr)
-        case None =>
-      }
-
-      trace.record(Annotation.ServerRecv)
-
-      try f
-      finally {
-        trace.record(Annotation.ServerSend)
-      }
-    } else f
-  }
-
-  private[this] def serviceName: String = {
-    TraceServiceName() match {
-      case Some(name) => name
-      case None => "local"
-    }
-  }
-
-  val LocalBeginAnnotation: String = "local/begin"
-  val LocalEndAnnotation: String = "local/end"
-
-  /**
-   * Create a span that begins right before the function is called
-   * and ends immediately after the function completes. This
-   * span will never have a corresponding remote component and is contained
-   * completely within the process it is created.
-   */
-  def traceLocal[T](name: String)(f: => T): T = {
-    letId(Trace.nextId) {
-      val timestamp = Time.nowNanoPrecision
-      try {
-        f
-      } finally {
-        val duration = Time.nowNanoPrecision - timestamp
-        recordSpan(name, timestamp, duration)
-      }
-    }
-  }
-
-  /**
-   * Create a span that begins right before the function is called
-   * and ends immediately after the async operation completes. This span will
-   * never have a corresponding remote component and is contained
-   * completely within the process it is created.
-   */
-  def traceLocalFuture[T](name: String)(f: => Future[T]): Future[T] = {
-    letId(Trace.nextId) {
-      val timestamp = Time.nowNanoPrecision
-      f.ensure {
-        val duration = Time.nowNanoPrecision - timestamp
-        recordSpan(name, timestamp, duration)
-      }
-    }
-  }
-
-  /**
-   * Create a span with the given name and Duration, with the end of the span at `Time.now`.
-   */
-  def traceLocalSpan(name: String, duration: Duration): Unit = {
-    letId(Trace.nextId) {
-      recordSpan(name, Time.nowNanoPrecision - duration, duration)
-    }
-  }
-
-  /**
-   * Create a span with the given name, timestamp and Duration. This is useful for debugging, or
-   * if you do not have complete control over the whole execution, e.g. you can not use
-   * [[traceLocalFuture]].
-   */
-  def traceLocalSpan(name: String, timestamp: Time, duration: Duration): Unit = {
-    letId(Trace.nextId) {
-      recordSpan(name, timestamp, duration)
-    }
-  }
-
-  private[this] def recordSpan(name: String, timestamp: Time, duration: Duration): Unit = {
-    val trace = Trace()
-    // these annotations are necessary to get the
-    // zipkin ui to properly display the span.
-    trace.record(Record(id, timestamp, Annotation.Rpc(name)))
-    trace.record(Record(id, timestamp, Annotation.ServiceName(serviceName)))
-    trace.record(Record(id, timestamp, Annotation.BinaryAnnotation("lc", name)))
-
-    trace.record(Record(id, timestamp, Annotation.Message(LocalBeginAnnotation)))
-    trace.record(Record(id, timestamp + duration, Annotation.Message(LocalEndAnnotation)))
-  }
-
-  /**
-   * Time an operation and add a binary annotation to the current span
-   * with the duration.
-   *
-   * @param message The message describing the operation
-   * @param f operation to perform
-   * @tparam T return type
-   * @return return value of the operation
-   */
-  def time[T](message: String)(f: => T): T = {
-    val trace = Trace()
-    if (trace.isActivelyTracing) {
-      val elapsed = Stopwatch.start()
-      val rv = f
-      trace.recordBinary(message, elapsed())
-      rv
-    } else f
-  }
-
-  /**
-   * Time an async operation and add a binary annotation to the current span
-   * with the duration.
-   */
-  def timeFuture[T](message: String)(f: Future[T]): Future[T] = {
-    val trace = Trace()
-    if (trace.isActivelyTracing) {
-      val elapsed = Stopwatch.start()
-      f.ensure(trace.recordBinary(message, elapsed()))
-    } else f
-  }
 }
diff --git a/finagle-core/src/main/scala/com/twitter/finagle/tracing/Tracing.scala b/finagle-core/src/main/scala/com/twitter/finagle/tracing/Tracing.scala
@@ -1,7 +1,8 @@
 package com.twitter.finagle.tracing
 
+import com.twitter.finagle.Init
 import com.twitter.finagle.stats.FinagleStatsReceiver
-import com.twitter.util.{Duration, Time}
+import com.twitter.util.{Duration, Future, Stopwatch, Time}
 import java.net.InetSocketAddress
 import scala.annotation.tailrec
 import scala.util.Random
@@ -246,4 +247,144 @@ abstract class Tracing {
       recordBinary(key, value)
     }
   }
+
+  private[this] def serviceName: String = {
+    TraceServiceName() match {
+      case Some(name) => name
+      case None => "local"
+    }
+  }
+
+  val LocalBeginAnnotation: String = "local/begin"
+  val LocalEndAnnotation: String = "local/end"
+
+  /**
+   * Convenience method for event loops in services.  Put your
+   * service handling code inside this to get proper tracing with all
+   * the correct fields filled in.
+   */
+  def traceService[T](
+    service: String,
+    rpc: String,
+    hostOpt: Option[InetSocketAddress] = None
+  )(
+    f: => T
+  ): T = Trace.letId(nextId) {
+    if (isActivelyTracing) {
+      recordBinary("finagle.version", Init.finagleVersion)
+      recordServiceName(service)
+      recordRpc(rpc)
+
+      hostOpt match {
+        case Some(addr) => recordServerAddr(addr)
+        case None =>
+      }
+
+      record(Annotation.ServerRecv)
+      try f
+      finally record(Annotation.ServerSend)
+    } else f
+  }
+
+  /**
+   * Create a span that begins right before the function is called
+   * and ends immediately after the function completes. This
+   * span will never have a corresponding remote component and is contained
+   * completely within the process it is created.
+   */
+  def traceLocal[T](name: String)(f: => T): T = {
+    Trace.letId(nextId) {
+      if (isActivelyTracing) {
+        val timestamp = Time.nowNanoPrecision
+        try f
+        finally {
+          val duration = Time.nowNanoPrecision - timestamp
+          recordSpan(name, timestamp, duration)
+        }
+      } else f
+    }
+  }
+
+  /**
+   * Create a span that begins right before the function is called
+   * and ends immediately after the async operation completes. This span will
+   * never have a corresponding remote component and is contained
+   * completely within the process it is created.
+   */
+  def traceLocalFuture[T](name: String)(f: => Future[T]): Future[T] = {
+    Trace.letId(nextId) {
+      if (isActivelyTracing) {
+        val timestamp = Time.nowNanoPrecision
+        f.ensure {
+          val duration = Time.nowNanoPrecision - timestamp
+          recordSpan(name, timestamp, duration)
+        }
+      } else f
+    }
+  }
+
+  /**
+   * Create a span with the given name and Duration, with the end of the span at `Time.now`.
+   */
+  def traceLocalSpan(name: String, duration: Duration): Unit = {
+    Trace.letId(nextId) {
+      if (isActivelyTracing) {
+        recordSpan(name, Time.nowNanoPrecision - duration, duration)
+      }
+    }
+  }
+
+  /**
+   * Create a span with the given name, timestamp and Duration. This is useful for debugging, or
+   * if you do not have complete control over the whole execution, e.g. you can not use
+   * [[traceLocalFuture]].
+   */
+  def traceLocalSpan(name: String, timestamp: Time, duration: Duration): Unit = {
+    Trace.letId(nextId) {
+      if (isActivelyTracing) {
+        recordSpan(name, timestamp, duration)
+      }
+    }
+  }
+
+  private[this] def recordSpan(name: String, timestamp: Time, duration: Duration): Unit = {
+    if (isActivelyTracing) {
+      // these annotations are necessary to get the
+      // zipkin ui to properly display the span.
+      record(Record(id, timestamp, Annotation.Rpc(name)))
+      record(Record(id, timestamp, Annotation.ServiceName(serviceName)))
+      record(Record(id, timestamp, Annotation.BinaryAnnotation("lc", name)))
+      record(Record(id, timestamp, Annotation.Message(LocalBeginAnnotation)))
+      record(Record(id, timestamp + duration, Annotation.Message(LocalEndAnnotation)))
+    }
+  }
+
+  /**
+   * Time an operation and add a binary annotation to the current span
+   * with the duration.
+   *
+   * @param message The message describing the operation
+   * @param f operation to perform
+   * @tparam T return type
+   * @return return value of the operation
+   */
+  def time[T](message: String)(f: => T): T = {
+    if (isActivelyTracing) {
+      val elapsed = Stopwatch.start()
+      val rv = f
+      recordBinary(message, elapsed())
+      rv
+    } else f
+  }
+
+  /**
+   * Time an async operation and add a binary annotation to the current span
+   * with the duration.
+   */
+  def timeFuture[T](message: String)(f: Future[T]): Future[T] = {
+    if (isActivelyTracing) {
+      val elapsed = Stopwatch.start()
+      f.ensure(recordBinary(message, elapsed()))
+    } else f
+  }
 }