finagle-thriftmux,scrooge: Server tracing of serde timings

Problem

Users have limited visibility into how much time Thrift servers spend
deserializing requests and serializing responses.

Solution

Wire this up as new binary tracing annotations.

Result

The annotation keys are "srv/request_deserialization_ns" and
"srv/response_serialization_ns". Both use nanoseconds as the time
unit.

JIRA Issues: CSL-7615

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

CHANGELOG.rst

@@ -18,11 +18,14 @@ New Features
   contained within the same file. ``PHAB_ID=D264325``
 
 * finagle-thriftmux: Additional information is now annotated in traces for clients
-  using Scrooge generated Thrift bindings. ``PHAB_ID=D269383``, ``PHAB_ID=D270597``
+  using Scrooge generated Thrift bindings. ``PHAB_ID=D269383``, ``PHAB_ID=D270597``,
+  ``PHAB_ID=D272934``.
   This includes:
 
   - RPC method name
   - Request serialization time, in nanoseconds
+  - Request deserialization time, in nanoseconds
+  - Response serialization time, in nanoseconds
   - Response deserialization time, in nanoseconds
 
 Breaking API Changes

finagle-thrift/src/test/scala/com/twitter/finagle/thrift/EndToEndTest.scala

@@ -244,7 +244,7 @@ class EndToEndTest extends FunSuite with ThriftTest with BeforeAndAfter {
       // Verify the count of the annotations. Order may change.
       // These are set twice - by client and server
       assert(
-        traces.collect { case Record(_, _, Annotation.BinaryAnnotation(k, v), _) => () }.size == 5
+        traces.collect { case Record(_, _, Annotation.BinaryAnnotation(_, _), _) => () }.size == 7
       )
       assert(traces.collect { case Record(_, _, Annotation.ServerAddr(_), _) => () }.size == 2)
       // With Stack, we get an extra ClientAddr because of the

finagle-thriftmux/src/test/scala/com/twitter/finagle/thriftmux/EndToEndTest.scala

@@ -449,7 +449,22 @@ class EndToEndTest
   }
 
   test("client + server: serialization time should be included in trace") {
+    val reqDeser = new AtomicBoolean(false)
+    val resSer = new AtomicBoolean(false)
+    val serverTracer: Tracer = new Tracer {
+      def record(record: Record): Unit = {
+        record match {
+          case Record(_, _, Annotation.BinaryAnnotation("srv/request_deserialization_ns", _), _) =>
+            reqDeser.set(true)
+          case Record(_, _, Annotation.BinaryAnnotation("srv/response_serialization_ns", _), _) =>
+            resSer.set(true)
+          case _ =>
+        }
+      }
+      def sampleTrace(traceId: TraceId): Option[Boolean] = Tracer.SomeTrue
+    }
     val server = serverImpl
+      .withTracer(serverTracer)
       .serveIface(
         new InetSocketAddress(InetAddress.getLoopbackAddress, 0),
         new TestService.MethodPerEndpoint {
@@ -461,7 +476,7 @@ class EndToEndTest
 
     val reqSer = new AtomicBoolean(false)
     val resDeser = new AtomicBoolean(false)
-    val tracer: Tracer = new Tracer {
+    val clientTracer: Tracer = new Tracer {
       def record(record: Record): Unit = {
         record match {
           case Record(_, _, Annotation.BinaryAnnotation("clnt/request_serialization_ns", _), _) =>
@@ -479,7 +494,7 @@ class EndToEndTest
     }
 
     val client = clientImpl
-      .withTracer(tracer)
+      .withTracer(clientTracer)
       .build[TestService.MethodPerEndpoint](
         Name.bound(Address(server.boundAddress.asInstanceOf[InetSocketAddress])),
         "client"
@@ -488,8 +503,10 @@ class EndToEndTest
     await(client.query("ok"))
 
     eventually {
-      assert(reqSer.get)
-      assert(resDeser.get)
+      assert(reqSer.get) // client sends req
+      assert(reqDeser.get) // server receives req
+      assert(resSer.get) // server sends response
+      assert(resDeser.get) // client receives response
     }
     await(server.close())
   }