Reuse SpanBuilder within a Thread #9537
Conversation
Initial performance experiment The idea is to store a CoreSpanBuilder per thread, since usually only SpanBuilder is in use at a given time per thread -- and CoreSpanBuilder isn't thread safe This simple change provides a giant boost in small heaps Improving Spring petclinic throughput from -39% to -19% with 80m heap
|
Hi! 👋 Thanks for your pull request! 🎉 To help us review it, please make sure to:
If you need help, please check our contributing guidelines. |
dougqh
added
comp: core
|
🎯 Code Coverage 🔗 Commit SHA: ff9acbe | Docs | Was this helpful? Give us feedback! |
BenchmarksStartupParameters
See matching parameters
SummaryFound 0 performance improvements and 0 performance regressions! Performance is the same for 50 metrics, 9 unstable metrics. Startup time reports for insecure-bankgantt
title insecure-bank - global startup overhead: candidate=1.54.0-SNAPSHOT~ff9acbe38f, baseline=1.54.0-SNAPSHOT~1052f4935d
dateFormat X
axisFormat %s
section tracing
Agent [baseline] (1.07 s) : 0, 1070020
Total [baseline] (8.719 s) : 0, 8719243
Agent [candidate] (1.066 s) : 0, 1065585
Total [candidate] (8.653 s) : 0, 8652838
section iast
Agent [baseline] (1.191 s) : 0, 1190964
Total [baseline] (9.28 s) : 0, 9280479
Agent [candidate] (1.2 s) : 0, 1199536
Total [candidate] (9.364 s) : 0, 9364320
gantt
title insecure-bank - break down per module: candidate=1.54.0-SNAPSHOT~ff9acbe38f, baseline=1.54.0-SNAPSHOT~1052f4935d
dateFormat X
axisFormat %s
section tracing
crashtracking [baseline] (1.465 ms) : 0, 1465
crashtracking [candidate] (1.466 ms) : 0, 1466
BytebuddyAgent [baseline] (738.37 ms) : 0, 738370
BytebuddyAgent [candidate] (734.825 ms) : 0, 734825
GlobalTracer [baseline] (254.592 ms) : 0, 254592
GlobalTracer [candidate] (254.045 ms) : 0, 254045
AppSec [baseline] (30.905 ms) : 0, 30905
AppSec [candidate] (30.794 ms) : 0, 30794
Debugger [baseline] (6.456 ms) : 0, 6456
Debugger [candidate] (6.401 ms) : 0, 6401
Remote Config [baseline] (703.372 µs) : 0, 703
Remote Config [candidate] (684.955 µs) : 0, 685
Telemetry [baseline] (16.488 ms) : 0, 16488
Telemetry [candidate] (16.391 ms) : 0, 16391
section iast
crashtracking [baseline] (1.457 ms) : 0, 1457
crashtracking [candidate] (1.474 ms) : 0, 1474
BytebuddyAgent [baseline] (852.615 ms) : 0, 852615
BytebuddyAgent [candidate] (859.297 ms) : 0, 859297
GlobalTracer [baseline] (244.811 ms) : 0, 244811
GlobalTracer [candidate] (248.587 ms) : 0, 248587
AppSec [baseline] (29.785 ms) : 0, 29785
AppSec [candidate] (26.859 ms) : 0, 26859
Debugger [baseline] (6.053 ms) : 0, 6053
Debugger [candidate] (5.988 ms) : 0, 5988
Remote Config [baseline] (589.444 µs) : 0, 589
Remote Config [candidate] (594.935 µs) : 0, 595
Telemetry [baseline] (8.217 ms) : 0, 8217
Telemetry [candidate] (8.304 ms) : 0, 8304
IAST [baseline] (26.53 ms) : 0, 26530
IAST [candidate] (27.389 ms) : 0, 27389
Startup time reports for petclinicgantt
title petclinic - global startup overhead: candidate=1.54.0-SNAPSHOT~ff9acbe38f, baseline=1.54.0-SNAPSHOT~1052f4935d
dateFormat X
axisFormat %s
section tracing
Agent [baseline] (1.062 s) : 0, 1061827
Total [baseline] (10.725 s) : 0, 10725341
Agent [candidate] (1.064 s) : 0, 1063797
Total [candidate] (10.691 s) : 0, 10690810
section appsec
Agent [baseline] (1.243 s) : 0, 1242619
Total [baseline] (11.076 s) : 0, 11075861
Agent [candidate] (1.234 s) : 0, 1234329
Total [candidate] (10.986 s) : 0, 10985998
section iast
Agent [baseline] (1.193 s) : 0, 1192701
Total [baseline] (11.112 s) : 0, 11112354
Agent [candidate] (1.191 s) : 0, 1190785
Total [candidate] (11.176 s) : 0, 11175537
section profiling
Agent [baseline] (1.212 s) : 0, 1211939
Total [baseline] (11.025 s) : 0, 11024999
Agent [candidate] (1.207 s) : 0, 1207286
Total [candidate] (10.849 s) : 0, 10849240
gantt
title petclinic - break down per module: candidate=1.54.0-SNAPSHOT~ff9acbe38f, baseline=1.54.0-SNAPSHOT~1052f4935d
dateFormat X
axisFormat %s
section tracing
crashtracking [baseline] (1.448 ms) : 0, 1448
crashtracking [candidate] (1.446 ms) : 0, 1446
BytebuddyAgent [baseline] (733.135 ms) : 0, 733135
BytebuddyAgent [candidate] (733.368 ms) : 0, 733368
GlobalTracer [baseline] (252.321 ms) : 0, 252321
GlobalTracer [candidate] (254.011 ms) : 0, 254011
AppSec [baseline] (30.567 ms) : 0, 30567
AppSec [candidate] (30.743 ms) : 0, 30743
Debugger [baseline] (6.393 ms) : 0, 6393
Debugger [candidate] (6.384 ms) : 0, 6384
Remote Config [baseline] (682.008 µs) : 0, 682
Remote Config [candidate] (685.231 µs) : 0, 685
Telemetry [baseline] (16.231 ms) : 0, 16231
Telemetry [candidate] (16.091 ms) : 0, 16091
section appsec
crashtracking [baseline] (1.462 ms) : 0, 1462
crashtracking [candidate] (1.45 ms) : 0, 1450
BytebuddyAgent [baseline] (762.288 ms) : 0, 762288
BytebuddyAgent [candidate] (754.439 ms) : 0, 754439
GlobalTracer [baseline] (246.994 ms) : 0, 246994
GlobalTracer [candidate] (246.638 ms) : 0, 246638
AppSec [baseline] (171.444 ms) : 0, 171444
AppSec [candidate] (170.716 ms) : 0, 170716
Debugger [baseline] (5.978 ms) : 0, 5978
Debugger [candidate] (6.041 ms) : 0, 6041
Remote Config [baseline] (608.169 µs) : 0, 608
Remote Config [candidate] (642.886 µs) : 0, 643
Telemetry [baseline] (8.55 ms) : 0, 8550
Telemetry [candidate] (9.388 ms) : 0, 9388
IAST [baseline] (23.956 ms) : 0, 23956
IAST [candidate] (23.792 ms) : 0, 23792
section iast
crashtracking [baseline] (1.464 ms) : 0, 1464
crashtracking [candidate] (1.445 ms) : 0, 1445
BytebuddyAgent [baseline] (853.434 ms) : 0, 853434
BytebuddyAgent [candidate] (851.893 ms) : 0, 851893
GlobalTracer [baseline] (244.798 ms) : 0, 244798
GlobalTracer [candidate] (247.512 ms) : 0, 247512
AppSec [baseline] (28.161 ms) : 0, 28161
AppSec [candidate] (26.216 ms) : 0, 26216
Debugger [baseline] (6.104 ms) : 0, 6104
Debugger [candidate] (6.008 ms) : 0, 6008
Remote Config [baseline] (610.456 µs) : 0, 610
Remote Config [candidate] (597.65 µs) : 0, 598
Telemetry [baseline] (8.347 ms) : 0, 8347
Telemetry [candidate] (8.233 ms) : 0, 8233
IAST [baseline] (28.771 ms) : 0, 28771
IAST [candidate] (27.884 ms) : 0, 27884
section profiling
crashtracking [baseline] (1.44 ms) : 0, 1440
crashtracking [candidate] (1.429 ms) : 0, 1429
BytebuddyAgent [baseline] (762.651 ms) : 0, 762651
BytebuddyAgent [candidate] (760.458 ms) : 0, 760458
GlobalTracer [baseline] (233.085 ms) : 0, 233085
GlobalTracer [candidate] (233.124 ms) : 0, 233124
AppSec [baseline] (31.34 ms) : 0, 31340
AppSec [candidate] (31.193 ms) : 0, 31193
Debugger [baseline] (10.588 ms) : 0, 10588
Debugger [candidate] (13.527 ms) : 0, 13527
Remote Config [baseline] (721.959 µs) : 0, 722
Remote Config [candidate] (706.143 µs) : 0, 706
Telemetry [baseline] (11.857 ms) : 0, 11857
Telemetry [candidate] (8.714 ms) : 0, 8714
ProfilingAgent [baseline] (108.969 ms) : 0, 108969
ProfilingAgent [candidate] (106.979 ms) : 0, 106979
Profiling [baseline] (109.591 ms) : 0, 109591
Profiling [candidate] (107.646 ms) : 0, 107646
LoadParameters
See matching parameters
SummaryFound 2 performance improvements and 2 performance regressions! Performance is the same for 8 metrics, 12 unstable metrics.
Request duration reports for petclinicgantt
title petclinic - request duration [CI 0.99] : candidate=1.54.0-SNAPSHOT~ff9acbe38f, baseline=1.54.0-SNAPSHOT~1052f4935d
dateFormat X
axisFormat %s
section baseline
no_agent (35.837 ms) : 35548, 36126
. : milestone, 35837,
appsec (50.382 ms) : 49936, 50827
. : milestone, 50382,
code_origins (45.609 ms) : 45232, 45985
. : milestone, 45609,
iast (45.547 ms) : 45154, 45941
. : milestone, 45547,
profiling (49.258 ms) : 48788, 49729
. : milestone, 49258,
tracing (45.527 ms) : 45133, 45920
. : milestone, 45527,
section candidate
no_agent (37.413 ms) : 37109, 37716
. : milestone, 37413,
appsec (47.844 ms) : 47431, 48257
. : milestone, 47844,
code_origins (46.011 ms) : 45614, 46408
. : milestone, 46011,
iast (45.01 ms) : 44620, 45399
. : milestone, 45010,
profiling (46.476 ms) : 46023, 46928
. : milestone, 46476,
tracing (45.746 ms) : 45332, 46160
. : milestone, 45746,
Request duration reports for insecure-bankgantt
title insecure-bank - request duration [CI 0.99] : candidate=1.54.0-SNAPSHOT~ff9acbe38f, baseline=1.54.0-SNAPSHOT~1052f4935d
dateFormat X
axisFormat %s
section baseline
no_agent (4.397 ms) : 4341, 4453
. : milestone, 4397,
iast (9.349 ms) : 9193, 9505
. : milestone, 9349,
iast_FULL (13.94 ms) : 13667, 14213
. : milestone, 13940,
iast_GLOBAL (10.511 ms) : 10326, 10696
. : milestone, 10511,
profiling (8.98 ms) : 8841, 9120
. : milestone, 8980,
tracing (7.598 ms) : 7492, 7705
. : milestone, 7598,
section candidate
no_agent (4.332 ms) : 4283, 4382
. : milestone, 4332,
iast (9.443 ms) : 9283, 9602
. : milestone, 9443,
iast_FULL (13.869 ms) : 13598, 14140
. : milestone, 13869,
iast_GLOBAL (10.612 ms) : 10411, 10814
. : milestone, 10612,
profiling (9.15 ms) : 8995, 9305
. : milestone, 9150,
tracing (8.035 ms) : 7919, 8152
. : milestone, 8035,
DacapoParameters
See matching parameters
SummaryFound 1 performance improvements and 0 performance regressions! Performance is the same for 10 metrics, 1 unstable metrics.
Execution time for biojavagantt
title biojava - execution time [CI 0.99] : candidate=1.54.0-SNAPSHOT~ff9acbe38f, baseline=1.54.0-SNAPSHOT~1052f4935d
dateFormat X
axisFormat %s
section baseline
no_agent (14.889 s) : 14889000, 14889000
. : milestone, 14889000,
appsec (14.856 s) : 14856000, 14856000
. : milestone, 14856000,
iast (18.772 s) : 18772000, 18772000
. : milestone, 18772000,
iast_GLOBAL (17.997 s) : 17997000, 17997000
. : milestone, 17997000,
profiling (15.39 s) : 15390000, 15390000
. : milestone, 15390000,
tracing (14.83 s) : 14830000, 14830000
. : milestone, 14830000,
section candidate
no_agent (14.969 s) : 14969000, 14969000
. : milestone, 14969000,
appsec (15.028 s) : 15028000, 15028000
. : milestone, 15028000,
iast (18.298 s) : 18298000, 18298000
. : milestone, 18298000,
iast_GLOBAL (17.885 s) : 17885000, 17885000
. : milestone, 17885000,
profiling (15.823 s) : 15823000, 15823000
. : milestone, 15823000,
tracing (15.129 s) : 15129000, 15129000
. : milestone, 15129000,
Execution time for tomcatgantt
title tomcat - execution time [CI 0.99] : candidate=1.54.0-SNAPSHOT~ff9acbe38f, baseline=1.54.0-SNAPSHOT~1052f4935d
dateFormat X
axisFormat %s
section baseline
no_agent (1.472 ms) : 1460, 1483
. : milestone, 1472,
appsec (3.675 ms) : 3458, 3891
. : milestone, 3675,
iast (2.194 ms) : 2132, 2256
. : milestone, 2194,
iast_GLOBAL (2.236 ms) : 2173, 2298
. : milestone, 2236,
profiling (2.486 ms) : 2318, 2654
. : milestone, 2486,
tracing (2.015 ms) : 1967, 2064
. : milestone, 2015,
section candidate
no_agent (1.473 ms) : 1462, 1485
. : milestone, 1473,
appsec (2.426 ms) : 2376, 2475
. : milestone, 2426,
iast (2.193 ms) : 2131, 2255
. : milestone, 2193,
iast_GLOBAL (2.24 ms) : 2177, 2303
. : milestone, 2240,
profiling (2.06 ms) : 2009, 2112
. : milestone, 2060,
tracing (2.019 ms) : 1970, 2068
. : milestone, 2019,
|
| public static final String OPTIMIZED_MAP_ENABLED = "optimized.map.enabled"; | ||
| public static final String TAG_NAME_UTF8_CACHE_SIZE = "tag.name.utf8.cache.size"; | ||
| public static final String TAG_VALUE_UTF8_CACHE_SIZE = "tag.value.utf8.cache.size"; | ||
| public static final String SPAN_BUILDER_REUSE_ENABLED = "span.builder.reuse.enabled"; |
There was a problem hiding this comment.
I'm not sure if this is best class to be placing these in. Or if this is the proper namespace. dd.trace... might be better
There was a problem hiding this comment.
❔ question: Quick question for my understanding: how is that supposed to work with manual tracing API? (DD or OTel)
Let’s say:
var spanBuilder = tracer.spanBuilder("span1");
// …
var span = tracer.spanBuilder("span2").startSpan();
// …
spanBuilder.setAttribute("key", "value").startSpan(); The second startSpan() call will start the span with the wrong name ("span2" instead of "span1") and there is nothing we can do on the API to prevent such use case.
The solution that I put in place yesterday was that I track whether or not the SpanBuilder is "in-use". A SpanBuilder is considered "in -use" from the point that it is So So the 'in-use' check solves the case mentioned in the original comment. You'll still get two distinct SpanBuilders. But there are still other cases that worry me, specifically, I'm worried that you can actually call build on the SpanBuilder multiple times. That's not idiomatic, but it would probably work today. My solution doesn't handle that. I don't believe our own instrumentation produces multiple Spans per builder today, so we could solve the problem by having two slightly different sets of rules: one for automatic and one for manual. We can accomplish that by having two sets of methods: one set that will reuse SpanBuilders that we use in automatic instrumentation, and another set that always creates a new SpanBuilder that we use in manual instrumentation (and the OTel bridge). UPDATE: buildSpan can maintain the existing semantics including allowing building multiple spans. That does mean that we have to update some instrumentation to get the full benefit, but at least, we know the change is safe. |
Refactored code, so tests work regardless of Config
…ace-java into dougqh/spanbuilder-pooling
To avoid breaking any potential code that builds multiple spans from the same SpanBuilder, updated the SpanBuilder pooling approach Introduced a new method singleSpanBuilder which can build one and only one span, this method can be used by automatic instrumentation as an optimization. singleSpanBuilder is now used inside the startSpan convenience methods, since we know they only build and return one span. Any automatic instrumentation using startSpan gets the optimization for free. buildSpan maintains its original semantics, so all existing continues to work as is.
…ace-java into dougqh/spanbuilder-pooling
In a microbenchmark, buildSpan was performing worse than previously. To address, that shortcoming and to clean-up the code... Made CoreSpanBuilder abstract and introduced two child classes: MultiSpanBuilder and ReusableSingleSpanBuilder MultiSpanBuilder is used by buildSpan ReusableSingleSpanBuilder is used by singleSpanBuilder / startSpan (indirectly)
…ace-java into dougqh/spanbuilder-pooling
The current code does try to always reuse the SpanBuilder, it just safe guards against the case where the prior caller hasn't finished with it. However, the assert won't be completely reliable. If the SpanBuilder gets reset before the next call to buildSpan, then I cannot detect that. Or at least, I don't think I can detect it without adding a wrapper object (which is counter to the aim).
Yes, I considered that. I kind of like the explicitness of |
| private static final boolean SPAN_BUILDER_REUSE_ENABLED = | ||
| Config.get().isSpanBuilderReuseEnabled(); |
There was a problem hiding this comment.
I'm not super familiar with dd-java-agent configuration, just curious, is there a possibility for remote on-the-fly configuration? Or this flag can be applied only with restart? Just thinking out loud about usability.
There was a problem hiding this comment.
Not currently - although, that is something that we've discussed doing off and on
I'm honestly not expecting any customer to ever set this, so I'm going with the approach that works best for the JIT
|
|
||
| // TODO: counter for how often the fallback is used? | ||
| ReusableSingleSpanBuilder newSpanBuilder = new ReusableSingleSpanBuilder(tracer); | ||
| newSpanBuilder.reset(instrumentationName, operationName); |
There was a problem hiding this comment.
Just curious, why we need reset fresh builder? Can it be created in proper state?
There was a problem hiding this comment.
Yeah, I debated that myself.
It is technically in a nearly prepared state after construction.
I could have a "fast" reset or another constructor instead of explicitly calling reset.
| static final class ReusableSingleSpanBuilderThreadLocalCache | ||
| extends ThreadLocal<ReusableSingleSpanBuilder> { | ||
| private final CoreTracer tracer; |
There was a problem hiding this comment.
Just curious if it will be OK on latest JDKs with virtual threads?
Added an init instead of calling reset when creating a new ReusableSingleSpanBuilder Added some asserts to catch misuse of the API
What Does This Do
This changes reuses a SpanBuilder within a thread.
Motivation
SpanBuilders are one of the major causes of allocation within the client library, but typically only one SpanBuilder is needed at a time in a thread. By reseting and reusing the same SpanBuilder, tracing allocation can be reduced significantly.
By reducing allocation, the garbage collector needs to run less frequently improving the maximum sustainable throughput of the host application. In local tests with Spring Petclinic, this reduces the throughput penalty with tiny heaps (<= 80m) significantly from -40% to -20%. On larger heaps, the gain is more modest, since garbage collector has less of an impact on the application.