Skip to content

Commit

Permalink
finagle-core: Call Trace.isActivelyTracing less
Browse files Browse the repository at this point in the history
# Problem

We call `isActivelyTracing` too often to prevent unnecessarily structures from materializing (a very simple
proxy reports 12 calls/request). The overhead of `isActivelyTracing` (about 5% of CPU profile) may outweigh
the benefits of saving allocations.

Additionally, a canonical usage pattern requires users to guard tracing operations behind the `isActivelyTracing`
result, which pretty much doubles the number of checks we do today.

# Solution

Do not check `isActivelyTracing` internally before materializing annotations and rely on callers checking
that externally. This cuts the number of `isActivelyTracing` calls in a proxy in half: from 12 to 7.

JIRA Issues: CSL-5625

Differential Revision: https://phabricator.twitter.biz/D193300
  • Loading branch information
vkostyukov authored and jenkins committed Jul 19, 2018
1 parent b1ca8f8 commit 33841d2
Show file tree
Hide file tree
Showing 3 changed files with 8 additions and 30 deletions.
8 changes: 7 additions & 1 deletion CHANGES
Expand Up @@ -26,9 +26,16 @@ Breaking API Changes
* finagle-core: Parameter-less annotation classes (`c.t.f.tracing.Annotation`) have been
promoted to objects for efficiency reasons. ``PHAB_ID=D192598``

* finagle-core: `c.t.f.tracing.Trace.record(Record)` now accepts the record argument by
value (previously by name). ``PHAB_ID=D193300``

Runtime Behavior Changes
~~~~~~~~~~~~~~~~~~~~~~~~

* finagle-core: `c.t.f.tracing.Trace` API is no longer guarding `Trace.record` calls behind
`Trace.isActivelyTracing`. Add `Trace.isActivelyTracing` guards on the call sites if
materializing tracing annotations is a performance concern. ``PHAB_ID=D193300``

* finagle-mysql: Clients will now issue a ROLLBACK each time a service is checked out
of the connection pool. This can be disabled via `Mysql.Client.noRollback`.
``PHAB_ID=D193923``
Expand All @@ -43,7 +50,6 @@ Deprecations
* finagle-mux: The pull based mux implementation, c.t.f.Mux, has been deprecated in favor of
the push-based mux implementation, c.t.f.pushsession.MuxPush. ``PHAB_ID=D193630``


18.7.0
-------

Expand Down
Expand Up @@ -136,10 +136,7 @@ abstract class Tracing {
/**
* Record a raw [[Record]]. This will record to a _unique_ set of tracers in the stack.
*/
final def record(rec: => Record): Unit =
if (isActivelyTracing) {
tracers.record(rec)
}
final def record(rec: Record): Unit = tracers.record(rec)

/**
* Get the current trace identifier. If no identifiers have been pushed,
Expand Down
Expand Up @@ -169,29 +169,6 @@ class TraceTest extends FunSuite with MockitoSugar with BeforeAndAfter with OneI
}
}

test("Trace.record: not report when tracing turned off") {
try {
Trace.disable()
Trace.letTracer(tracer2) {
Trace.letTracerAndId(tracer1, id0) {
Trace.letTracer(tracer1) {
Trace.letTracer(tracer2) {
Trace.letId(id0) {
verify(tracer1, never()).record(any[Record])
verify(tracer2, never()).record(any[Record])
Trace.record("oh hey")
verify(tracer1, never()).record(any[Record])
verify(tracer2, never()).record(any[Record])
}
}
}
}
}
} finally {
Trace.enable()
}
}

/* TODO temporarily disabled until we can mock stopwatches
"Trace.time" in Time.withCurrentTimeFrozen { tc =>
val tracer = new BufferingTracer()
Expand Down Expand Up @@ -270,8 +247,6 @@ class TraceTest extends FunSuite with MockitoSugar with BeforeAndAfter with OneI
assert(Trace.isTerminal == false)
assert(Trace.tracers == List(tracer))
verify(tracer, never()).sampleTrace(currentId)
Trace.record("Hello world")
verify(tracer, never()).record(any[Record])
}
}
}
Expand Down

0 comments on commit 33841d2

Please sign in to comment.