From ec0097cd17e46e192d7e80444cdda1fcb0961407 Mon Sep 17 00:00:00 2001 From: Hamdi Allam Date: Sat, 13 Mar 2021 00:39:22 +0000 Subject: [PATCH] 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 --- CHANGELOG.rst | 4 + .../com/twitter/finagle/tracing/Trace.scala | 145 +----------------- .../com/twitter/finagle/tracing/Tracing.scala | 143 ++++++++++++++++- 3 files changed, 148 insertions(+), 144 deletions(-) diff --git a/CHANGELOG.rst b/CHANGELOG.rst index 51547fc182..93dcca3583 100644 --- 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 index 95d681f1c4..ad5272710b 100644 --- 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 index c9fd0239db..1bf97bd822 100644 --- 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 + } }