Skip to content

Rework Queue time tracking to avoid unwrapping the task type unless the event will be recorded#5785

Merged
richardstartin merged 1 commit into
masterfrom
rgs/queue-time-performance
Aug 25, 2023
Merged

Rework Queue time tracking to avoid unwrapping the task type unless the event will be recorded#5785
richardstartin merged 1 commit into
masterfrom
rgs/queue-time-performance

Conversation

@richardstartin

@richardstartin richardstartin commented Aug 25, 2023

Copy link
Copy Markdown
Contributor

What Does This Do

  • Move TaskWrapper from bootstrap to internal api so it can be used by the profiler
  • Track a weak reference to the task rather than an eagerly unwrapped task, the unwrapping will take place if the queue time threshold is breached
  • Stop filtering out Netty chores because filtering them out by unwrapped class name may be too expensive - they will probably be filtered out by the duration threshold anyway.

Motivation

Interface instanceof checks are dangerous in instrumentation because they may lead to flip-flopping of secondary_super_cache which can be a scalability bottleneck. This change delays unwrapping the task type until we know we will record a queue time sample, and therefore there is already a bottleneck anyway.

Additional Notes

@richardstartin
richardstartin requested review from a team as code owners August 25, 2023 11:44
mcculls
mcculls reviewed Aug 25, 2023
View reviewed changes
Comment thread internal-api/src/main/java/datadog/trace/api/TaskWrapper.java Outdated
@pr-commenter

pr-commenter Bot commented Aug 25, 2023

Copy link
Copy Markdown

Benchmarks

Startup

Parameters

Baseline Candidate
commit 1.20.0-SNAPSHOT~acb417b5b2 1.20.0-SNAPSHOT~e39133c39d
config baseline candidate
See matching parameters
Baseline Candidate
application insecure-bank insecure-bank
module Agent Agent
parent None None
variant appsec appsec

Summary

Found 0 performance improvements and 0 performance regressions! Performance is the same for 62 cases.

Startup time reports for petclinic 
gantt
    title petclinic - global startup overhead: candidate=1.20.0-SNAPSHOT~e39133c39d, baseline=1.20.0-SNAPSHOT~acb417b5b2

    dateFormat X
    axisFormat %s
section tracing
Agent [baseline] (989.507 ms) : 0, 989507
Total [baseline] (9.192 s) : 0, 9191866
Agent [candidate] (991.778 ms) : 0, 991778
Total [candidate] (9.208 s) : 0, 9208336
section appsec
Agent [baseline] (1.075 s) : 0, 1074670
Total [baseline] (9.287 s) : 0, 9286656
Agent [candidate] (1.075 s) : 0, 1074694
Total [candidate] (9.233 s) : 0, 9232554
section iast
Agent [baseline] (1.093 s) : 0, 1093079
Total [baseline] (9.406 s) : 0, 9406177
Agent [candidate] (1.093 s) : 0, 1092812
Total [candidate] (9.465 s) : 0, 9464795
section profiling
Agent [baseline] (1.157 s) : 0, 1156559
Total [baseline] (9.465 s) : 0, 9464970
Agent [candidate] (1.159 s) : 0, 1158864
Total [candidate] (9.473 s) : 0, 9472774
Loading
  • baseline results
Module Variant Duration Δ tracing
Agent tracing 989.507 ms -
Agent appsec 1.075 s 85.163 ms (8.6%)
Agent iast 1.093 s 103.572 ms (10.5%)
Agent profiling 1.157 s 167.052 ms (16.9%)
Total tracing 9.192 s -
Total appsec 9.287 s 94.79 ms (1.0%)
Total iast 9.406 s 214.311 ms (2.3%)
Total profiling 9.465 s 273.104 ms (3.0%)
  • candidate results
Module Variant Duration Δ tracing
Agent tracing 991.778 ms -
Agent appsec 1.075 s 82.916 ms (8.4%)
Agent iast 1.093 s 101.034 ms (10.2%)
Agent profiling 1.159 s 167.087 ms (16.8%)
Total tracing 9.208 s -
Total appsec 9.233 s 24.219 ms (0.3%)
Total iast 9.465 s 256.46 ms (2.8%)
Total profiling 9.473 s 264.439 ms (2.9%) 
gantt
    title petclinic - break down per module: candidate=1.20.0-SNAPSHOT~e39133c39d, baseline=1.20.0-SNAPSHOT~acb417b5b2

    dateFormat X
    axisFormat %s
section tracing
BytebuddyAgent [baseline] (613.093 ms) : 0, 613093
BytebuddyAgent [candidate] (614.612 ms) : 0, 614612
GlobalTracer [baseline] (284.782 ms) : 0, 284782
GlobalTracer [candidate] (286.591 ms) : 0, 286591
AppSec [baseline] (50.59 ms) : 0, 50590
AppSec [candidate] (49.505 ms) : 0, 49505
Remote Config [baseline] (670.325 µs) : 0, 670
Remote Config [candidate] (661.896 µs) : 0, 662
Telemetry [baseline] (6.068 ms) : 0, 6068
Telemetry [candidate] (6.059 ms) : 0, 6059
section appsec
BytebuddyAgent [baseline] (613.856 ms) : 0, 613856
BytebuddyAgent [candidate] (613.517 ms) : 0, 613517
GlobalTracer [baseline] (284.684 ms) : 0, 284684
GlobalTracer [candidate] (285.163 ms) : 0, 285163
AppSec [baseline] (135.309 ms) : 0, 135309
AppSec [candidate] (135.267 ms) : 0, 135267
Remote Config [baseline] (726.178 µs) : 0, 726
Remote Config [candidate] (720.799 µs) : 0, 721
Telemetry [baseline] (5.781 ms) : 0, 5781
Telemetry [candidate] (5.735 ms) : 0, 5735
section iast
BytebuddyAgent [baseline] (720.001 ms) : 0, 720001
BytebuddyAgent [candidate] (719.434 ms) : 0, 719434
GlobalTracer [baseline] (271.182 ms) : 0, 271182
GlobalTracer [candidate] (271.518 ms) : 0, 271518
AppSec [baseline] (47.491 ms) : 0, 47491
AppSec [candidate] (47.43 ms) : 0, 47430
Remote Config [baseline] (542.708 µs) : 0, 543
Remote Config [candidate] (551.563 µs) : 0, 552
Telemetry [baseline] (5.695 ms) : 0, 5695
Telemetry [candidate] (5.666 ms) : 0, 5666
IAST [baseline] (13.742 ms) : 0, 13742
IAST [candidate] (13.8 ms) : 0, 13800
section profiling
ProfilingAgent [baseline] (78.589 ms) : 0, 78589
ProfilingAgent [candidate] (76.777 ms) : 0, 76777
BytebuddyAgent [baseline] (624.12 ms) : 0, 624120
BytebuddyAgent [candidate] (626.452 ms) : 0, 626452
GlobalTracer [baseline] (345.478 ms) : 0, 345478
GlobalTracer [candidate] (347.052 ms) : 0, 347052
AppSec [baseline] (49.07 ms) : 0, 49070
AppSec [candidate] (49.027 ms) : 0, 49027
Remote Config [baseline] (653.837 µs) : 0, 654
Remote Config [candidate] (660.692 µs) : 0, 661
Telemetry [baseline] (5.949 ms) : 0, 5949
Telemetry [candidate] (5.964 ms) : 0, 5964
Profiling [baseline] (78.613 ms) : 0, 78613
Profiling [candidate] (76.802 ms) : 0, 76802
Loading
Startup time reports for insecure-bank 
gantt
    title insecure-bank - global startup overhead: candidate=1.20.0-SNAPSHOT~e39133c39d, baseline=1.20.0-SNAPSHOT~acb417b5b2

    dateFormat X
    axisFormat %s
section tracing
Agent [baseline] (995.816 ms) : 0, 995816
Total [baseline] (8.662 s) : 0, 8661569
Agent [candidate] (990.033 ms) : 0, 990033
Total [candidate] (8.668 s) : 0, 8667735
section appsec
Agent [baseline] (1.073 s) : 0, 1072846
Total [baseline] (8.745 s) : 0, 8744642
Agent [candidate] (1.077 s) : 0, 1077457
Total [candidate] (8.758 s) : 0, 8757751
section iast
Agent [baseline] (1.092 s) : 0, 1092396
Total [baseline] (9.161 s) : 0, 9160957
Agent [candidate] (1.1 s) : 0, 1099649
Total [candidate] (9.228 s) : 0, 9227779
section profiling
Agent [baseline] (1.155 s) : 0, 1155216
Total [baseline] (8.849 s) : 0, 8848975
Agent [candidate] (1.161 s) : 0, 1160868
Total [candidate] (8.881 s) : 0, 8880571
Loading
  • baseline results
Module Variant Duration Δ tracing
Agent tracing 995.816 ms -
Agent appsec 1.073 s 77.03 ms (7.7%)
Agent iast 1.092 s 96.579 ms (9.7%)
Agent profiling 1.155 s 159.4 ms (16.0%)
Total tracing 8.662 s -
Total appsec 8.745 s 83.072 ms (1.0%)
Total iast 9.161 s 499.388 ms (5.8%)
Total profiling 8.849 s 187.406 ms (2.2%)
  • candidate results
Module Variant Duration Δ tracing
Agent tracing 990.033 ms -
Agent appsec 1.077 s 87.424 ms (8.8%)
Agent iast 1.1 s 109.616 ms (11.1%)
Agent profiling 1.161 s 170.836 ms (17.3%)
Total tracing 8.668 s -
Total appsec 8.758 s 90.016 ms (1.0%)
Total iast 9.228 s 560.045 ms (6.5%)
Total profiling 8.881 s 212.837 ms (2.5%) 
gantt
    title insecure-bank - break down per module: candidate=1.20.0-SNAPSHOT~e39133c39d, baseline=1.20.0-SNAPSHOT~acb417b5b2

    dateFormat X
    axisFormat %s
section tracing
BytebuddyAgent [baseline] (617.531 ms) : 0, 617531
BytebuddyAgent [candidate] (613.884 ms) : 0, 613884
GlobalTracer [baseline] (286.305 ms) : 0, 286305
GlobalTracer [candidate] (285.032 ms) : 0, 285032
AppSec [baseline] (50.549 ms) : 0, 50549
AppSec [candidate] (50.147 ms) : 0, 50147
Remote Config [baseline] (669.503 µs) : 0, 670
Remote Config [candidate] (657.705 µs) : 0, 658
Telemetry [baseline] (6.057 ms) : 0, 6057
Telemetry [candidate] (5.964 ms) : 0, 5964
section appsec
BytebuddyAgent [baseline] (612.997 ms) : 0, 612997
BytebuddyAgent [candidate] (615.212 ms) : 0, 615212
GlobalTracer [baseline] (284.647 ms) : 0, 284647
GlobalTracer [candidate] (286.612 ms) : 0, 286612
AppSec [baseline] (134.549 ms) : 0, 134549
AppSec [candidate] (134.649 ms) : 0, 134649
Remote Config [baseline] (717.437 µs) : 0, 717
Remote Config [candidate] (722.702 µs) : 0, 723
Telemetry [baseline] (5.756 ms) : 0, 5756
Telemetry [candidate] (5.78 ms) : 0, 5780
section iast
BytebuddyAgent [baseline] (719.548 ms) : 0, 719548
BytebuddyAgent [candidate] (724.534 ms) : 0, 724534
GlobalTracer [baseline] (271.068 ms) : 0, 271068
GlobalTracer [candidate] (272.585 ms) : 0, 272585
AppSec [baseline] (47.4 ms) : 0, 47400
AppSec [candidate] (47.746 ms) : 0, 47746
Remote Config [baseline] (540.69 µs) : 0, 541
Remote Config [candidate] (563.088 µs) : 0, 563
Telemetry [baseline] (5.692 ms) : 0, 5692
Telemetry [candidate] (5.71 ms) : 0, 5710
IAST [baseline] (13.73 ms) : 0, 13730
IAST [candidate] (13.965 ms) : 0, 13965
section profiling
ProfilingAgent [baseline] (76.558 ms) : 0, 76558
ProfilingAgent [candidate] (77.472 ms) : 0, 77472
BytebuddyAgent [baseline] (624.325 ms) : 0, 624325
BytebuddyAgent [candidate] (627.071 ms) : 0, 627071
GlobalTracer [baseline] (345.713 ms) : 0, 345713
GlobalTracer [candidate] (347.433 ms) : 0, 347433
AppSec [baseline] (49.123 ms) : 0, 49123
AppSec [candidate] (49.197 ms) : 0, 49197
Remote Config [baseline] (652.209 µs) : 0, 652
Remote Config [candidate] (646.314 µs) : 0, 646
Telemetry [baseline] (6.018 ms) : 0, 6018
Telemetry [candidate] (5.993 ms) : 0, 5993
Profiling [baseline] (76.583 ms) : 0, 76583
Profiling [candidate] (77.497 ms) : 0, 77497
Loading

Load

Parameters

Baseline Candidate
commit 1.20.0-SNAPSHOT~acb417b5b2 1.20.0-SNAPSHOT~e39133c39d
config baseline candidate
end_time 2023-08-25T12:00:50 2023-08-25T12:18:56
start_time 2023-08-25T12:00:32 2023-08-25T12:18:39
See matching parameters
Baseline Candidate
application insecure-bank insecure-bank
variant appsec appsec

Summary

Found 0 performance improvements and 0 performance regressions! Performance is the same for 24 cases.

Request duration reports for petclinic 
gantt
    title petclinic - request duration [CI 0.99] : candidate=1.20.0-SNAPSHOT~e39133c39d, baseline=1.20.0-SNAPSHOT~acb417b5b2
    dateFormat X
    axisFormat %s
section baseline
no_agent (1.338 ms) : 1319, 1357
.   : milestone, 1338,
appsec (1.7 ms) : 1675, 1724
.   : milestone, 1700,
iast (1.473 ms) : 1449, 1496
.   : milestone, 1473,
profiling (1.453 ms) : 1428, 1479
.   : milestone, 1453,
tracing (1.438 ms) : 1414, 1462
.   : milestone, 1438,
section candidate
no_agent (1.342 ms) : 1323, 1362
.   : milestone, 1342,
appsec (1.681 ms) : 1656, 1705
.   : milestone, 1681,
iast (1.438 ms) : 1414, 1462
.   : milestone, 1438,
profiling (1.478 ms) : 1453, 1503
.   : milestone, 1478,
tracing (1.436 ms) : 1412, 1460
.   : milestone, 1436,
Loading
  • baseline results
Variant Request duration [CI 0.99] Δ no_agent
no_agent 1.338 ms [1.319 ms, 1.357 ms] -
appsec 1.7 ms [1.675 ms, 1.724 ms] 361.37 µs (27.0%)
iast 1.473 ms [1.449 ms, 1.496 ms] 134.323 µs (10.0%)
profiling 1.453 ms [1.428 ms, 1.479 ms] 114.856 µs (8.6%)
tracing 1.438 ms [1.414 ms, 1.462 ms] 99.544 µs (7.4%)
  • candidate results
Variant Request duration [CI 0.99] Δ no_agent
no_agent 1.342 ms [1.323 ms, 1.362 ms] -
appsec 1.681 ms [1.656 ms, 1.705 ms] 338.353 µs (25.2%)
iast 1.438 ms [1.414 ms, 1.462 ms] 95.826 µs (7.1%)
profiling 1.478 ms [1.453 ms, 1.503 ms] 135.814 µs (10.1%)
tracing 1.436 ms [1.412 ms, 1.46 ms] 93.39 µs (7.0%)
Request duration reports for insecure-bank 
gantt
    title insecure-bank - request duration [CI 0.99] : candidate=1.20.0-SNAPSHOT~e39133c39d, baseline=1.20.0-SNAPSHOT~acb417b5b2
    dateFormat X
    axisFormat %s
section baseline
no_agent (362.077 µs) : 341, 383
.   : milestone, 362,
appsec (658.866 µs) : 638, 680
.   : milestone, 659,
iast (450.611 µs) : 430, 471
.   : milestone, 451,
iast_FULL (516.461 µs) : 496, 537
.   : milestone, 516,
iast_INACTIVE (429.995 µs) : 409, 451
.   : milestone, 430,
profiling (441.455 µs) : 420, 463
.   : milestone, 441,
tracing (431.38 µs) : 411, 452
.   : milestone, 431,
section candidate
no_agent (359.962 µs) : 340, 380
.   : milestone, 360,
appsec (664.07 µs) : 643, 685
.   : milestone, 664,
iast (456.744 µs) : 436, 478
.   : milestone, 457,
iast_FULL (519.334 µs) : 499, 540
.   : milestone, 519,
iast_INACTIVE (426.893 µs) : 406, 447
.   : milestone, 427,
profiling (448.056 µs) : 427, 469
.   : milestone, 448,
tracing (433.574 µs) : 412, 455
.   : milestone, 434,
Loading
  • baseline results
Variant Request duration [CI 0.99] Δ no_agent
no_agent 362.077 µs [341.496 µs, 382.658 µs] -
appsec 658.866 µs [637.873 µs, 679.858 µs] 296.789 µs (82.0%)
iast 450.611 µs [429.825 µs, 471.397 µs] 88.534 µs (24.5%)
iast_FULL 516.461 µs [495.794 µs, 537.129 µs] 154.384 µs (42.6%)
iast_INACTIVE 429.995 µs [409.318 µs, 450.671 µs] 67.918 µs (18.8%)
profiling 441.455 µs [420.312 µs, 462.598 µs] 79.378 µs (21.9%)
tracing 431.38 µs [410.626 µs, 452.134 µs] 69.303 µs (19.1%)
  • candidate results
Variant Request duration [CI 0.99] Δ no_agent
no_agent 359.962 µs [339.845 µs, 380.08 µs] -
appsec 664.07 µs [642.894 µs, 685.245 µs] 304.107 µs (84.5%)
iast 456.744 µs [435.52 µs, 477.968 µs] 96.782 µs (26.9%)
iast_FULL 519.334 µs [498.502 µs, 540.166 µs] 159.372 µs (44.3%)
iast_INACTIVE 426.893 µs [406.488 µs, 447.299 µs] 66.931 µs (18.6%)
profiling 448.056 µs [426.86 µs, 469.251 µs] 88.093 µs (24.5%)
tracing 433.574 µs [412.049 µs, 455.099 µs] 73.612 µs (20.4%)

@richardstartin
richardstartin force-pushed the rgs/queue-time-performance branch from e39133c to a33c8a0 Compare August 25, 2023 12:49
@richardstartin richardstartin changed the title rework to avoid unwrapping the task type unless the event will be recorded rework Queue time tracking to avoid unwrapping the task type unless the event will be recorded Aug 25, 2023
@richardstartin
richardstartin merged commit 7ab70d9 into master Aug 25, 2023
@richardstartin
richardstartin deleted the rgs/queue-time-performance branch August 25, 2023 13:25
@github-actions github-actions Bot added this to the 1.20.0 milestone Aug 25, 2023
@bantonsson bantonsson changed the title rework Queue time tracking to avoid unwrapping the task type unless the event will be recorded Rework Queue time tracking to avoid unwrapping the task type unless the event will be recorded Aug 25, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@mcculls mcculls mcculls approved these changes
@jbachorik jbachorik jbachorik approved these changes
@bantonsson bantonsson Awaiting requested review from bantonsson bantonsson is a code owner automatically assigned from DataDog/apm-java

Assignees

No one assigned

Labels

comp: profiling Profiling

Projects

None yet

Milestone

1.20.0

Development

Successfully merging this pull request may close these issues.

3 participants

@richardstartin @mcculls @jbachorik