Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Ensure queue timer is started for RunnableFuture types #6828

Merged
merged 1 commit into from Mar 21, 2024
Merged

Ensure queue timer is started for RunnableFuture types #6828

merged 1 commit into from Mar 21, 2024

Conversation

richardstartin
Copy link
Member

@richardstartin richardstartin commented Mar 20, 2024 •
edited

What Does This Do

This fixes a regression in an unreleased profiling feature (queue time) which times how long is spent scheduling tasks which run in thread pools. This was inadvertently broken by #6446 but there wasn't a test in place to prevent this. The root cause was that FutureTask is excluded as a RUNNABLE so the timer was no longer started after being moved into TPEHelper, but the original instrumentation was using the wrong context field within FutureTask (the one for Runnable, not RunnableFuture) in the first place. The solution is to move the starting the queue timer back into the instrumentation, and (hopefully, temporarily) complicating the instrumentation slightly to handle RunnableFutures whenever excluded as RUNNABLE. A test is also added to verify the fix and prevent regression.

In the longer term, this instrumentation could be simplified by entirely removing the RunnableInstrumentation and only instrumenting or wrapping instances we fully know the state lifecycle of.

Motivation

Additional Notes

Jira ticket: [PROJ-IDENT]

@richardstartin richardstartin force-pushed the rgs/fix-tpe-queue-timer branch 6 times, most recently from e893948 to 39fd859 Compare March 20, 2024 17:15
@richardstartin richardstartin marked this pull request as ready for review March 20, 2024 19:03
@richardstartin richardstartin requested a review from a team as a code owner March 20, 2024 19:03
@pr-commenter
Copy link

pr-commenter bot commented Mar 20, 2024

Benchmarks

Startup

Parameters

Baseline Candidate
baseline_or_candidate baseline candidate
git_branch master rgs/fix-tpe-queue-timer
git_commit_date 1710938634 1710959464
git_commit_sha e20dfff b7cf900
release_version 1.32.0-SNAPSHOT~e20dfff5e5 1.32.0-SNAPSHOT~b7cf900de6
See matching parameters
Baseline Candidate
application insecure-bank insecure-bank
ci_job_date 1710962698 1710962698
ci_job_id 465122942 465122942
ci_pipeline_id 30489370 30489370
cpu_model Intel(R) Xeon(R) Platinum 8259CL CPU @ 2.50GHz Intel(R) Xeon(R) Platinum 8259CL CPU @ 2.50GHz
module Agent Agent
parent None None
variant iast iast

Summary

Found 0 performance improvements and 0 performance regressions! Performance is the same for 50 metrics, 13 unstable metrics.

Startup time reports for insecure-bank 
gantt
    title insecure-bank - global startup overhead: candidate=1.32.0-SNAPSHOT~b7cf900de6, baseline=1.32.0-SNAPSHOT~e20dfff5e5

    dateFormat X
    axisFormat %s
section tracing
Agent [baseline] (1.081 s) : 0, 1081023
Total [baseline] (8.58 s) : 0, 8579545
Agent [candidate] (1.089 s) : 0, 1089039
Total [candidate] (8.606 s) : 0, 8606144
section iast
Agent [baseline] (1.206 s) : 0, 1206209
Total [baseline] (9.062 s) : 0, 9062086
Agent [candidate] (1.215 s) : 0, 1215179
Total [candidate] (9.075 s) : 0, 9075376
section iast_HARDCODED_SECRET_DISABLED
Agent [baseline] (1.206 s) : 0, 1206368
Total [baseline] (9.053 s) : 0, 9052657
Agent [candidate] (1.221 s) : 0, 1221217
Total [candidate] (9.102 s) : 0, 9102441
section iast_TELEMETRY_OFF
Agent [baseline] (1.2 s) : 0, 1200254
Total [baseline] (9.118 s) : 0, 9118351
Agent [candidate] (1.206 s) : 0, 1205613
Total [candidate] (9.092 s) : 0, 9092336
  • baseline results
Module Variant Duration Δ tracing
Agent tracing 1.081 s -
Agent iast 1.206 s 125.186 ms (11.6%)
Agent iast_HARDCODED_SECRET_DISABLED 1.206 s 125.345 ms (11.6%)
Agent iast_TELEMETRY_OFF 1.2 s 119.231 ms (11.0%)
Total tracing 8.58 s -
Total iast 9.062 s 482.541 ms (5.6%)
Total iast_HARDCODED_SECRET_DISABLED 9.053 s 473.111 ms (5.5%)
Total iast_TELEMETRY_OFF 9.118 s 538.806 ms (6.3%)
  • candidate results
Module Variant Duration Δ tracing
Agent tracing 1.089 s -
Agent iast 1.215 s 126.139 ms (11.6%)
Agent iast_HARDCODED_SECRET_DISABLED 1.221 s 132.177 ms (12.1%)
Agent iast_TELEMETRY_OFF 1.206 s 116.574 ms (10.7%)
Total tracing 8.606 s -
Total iast 9.075 s 469.231 ms (5.5%)
Total iast_HARDCODED_SECRET_DISABLED 9.102 s 496.296 ms (5.8%)
Total iast_TELEMETRY_OFF 9.092 s 486.192 ms (5.6%) 
gantt
    title insecure-bank - break down per module: candidate=1.32.0-SNAPSHOT~b7cf900de6, baseline=1.32.0-SNAPSHOT~e20dfff5e5

    dateFormat X
    axisFormat %s
section tracing
BytebuddyAgent [baseline] (697.233 ms) : 0, 697233
BytebuddyAgent [candidate] (702.162 ms) : 0, 702162
GlobalTracer [baseline] (291.879 ms) : 0, 291879
GlobalTracer [candidate] (294.247 ms) : 0, 294247
AppSec [baseline] (49.105 ms) : 0, 49105
AppSec [candidate] (49.605 ms) : 0, 49605
Remote Config [baseline] (1.074 ms) : 0, 1074
Remote Config [candidate] (1.072 ms) : 0, 1072
Telemetry [baseline] (7.41 ms) : 0, 7410
Telemetry [candidate] (7.448 ms) : 0, 7448
section iast
BytebuddyAgent [baseline] (802.11 ms) : 0, 802110
BytebuddyAgent [candidate] (807.456 ms) : 0, 807456
GlobalTracer [baseline] (288.981 ms) : 0, 288981
GlobalTracer [candidate] (291.598 ms) : 0, 291598
AppSec [baseline] (50.827 ms) : 0, 50827
AppSec [candidate] (48.377 ms) : 0, 48377
Remote Config [baseline] (569.304 µs) : 0, 569
Remote Config [candidate] (575.373 µs) : 0, 575
Telemetry [baseline] (7.343 ms) : 0, 7343
Telemetry [candidate] (6.573 ms) : 0, 6573
IAST [baseline] (22.045 ms) : 0, 22045
IAST [candidate] (25.99 ms) : 0, 25990
section iast_HARDCODED_SECRET_DISABLED
BytebuddyAgent [baseline] (801.43 ms) : 0, 801430
BytebuddyAgent [candidate] (810.79 ms) : 0, 810790
GlobalTracer [baseline] (289.479 ms) : 0, 289479
GlobalTracer [candidate] (292.62 ms) : 0, 292620
AppSec [baseline] (51.845 ms) : 0, 51845
AppSec [candidate] (49.641 ms) : 0, 49641
Remote Config [baseline] (581.708 µs) : 0, 582
Remote Config [candidate] (593.961 µs) : 0, 594
Telemetry [baseline] (6.614 ms) : 0, 6614
Telemetry [candidate] (6.734 ms) : 0, 6734
IAST [baseline] (22.052 ms) : 0, 22052
IAST [candidate] (26.165 ms) : 0, 26165
section iast_TELEMETRY_OFF
BytebuddyAgent [baseline] (795.142 ms) : 0, 795142
BytebuddyAgent [candidate] (798.818 ms) : 0, 798818
GlobalTracer [baseline] (289.936 ms) : 0, 289936
GlobalTracer [candidate] (291.538 ms) : 0, 291538
AppSec [baseline] (50.038 ms) : 0, 50038
AppSec [candidate] (49.0 ms) : 0, 49000
Remote Config [baseline] (564.927 µs) : 0, 565
Remote Config [candidate] (569.538 µs) : 0, 570
Telemetry [baseline] (6.472 ms) : 0, 6472
Telemetry [candidate] (6.559 ms) : 0, 6559
IAST [baseline] (23.684 ms) : 0, 23684
IAST [candidate] (24.657 ms) : 0, 24657
Startup time reports for petclinic 
gantt
    title petclinic - global startup overhead: candidate=1.32.0-SNAPSHOT~b7cf900de6, baseline=1.32.0-SNAPSHOT~e20dfff5e5

    dateFormat X
    axisFormat %s
section tracing
Agent [baseline] (1.103 s) : 0, 1103186
Total [baseline] (9.273 s) : 0, 9273083
Agent [candidate] (1.091 s) : 0, 1091223
Total [candidate] (9.197 s) : 0, 9197471
section appsec
Agent [baseline] (1.203 s) : 0, 1202568
Total [baseline] (9.353 s) : 0, 9353362
Agent [candidate] (1.207 s) : 0, 1206872
Total [candidate] (9.383 s) : 0, 9382985
section iast
Agent [baseline] (1.219 s) : 0, 1219397
Total [baseline] (9.421 s) : 0, 9420634
Agent [candidate] (1.214 s) : 0, 1214365
Total [candidate] (9.458 s) : 0, 9457958
section profiling
Agent [baseline] (1.274 s) : 0, 1274334
Total [baseline] (9.468 s) : 0, 9468362
Agent [candidate] (1.277 s) : 0, 1277125
Total [candidate] (9.354 s) : 0, 9354199
  • baseline results
Module Variant Duration Δ tracing
Agent tracing 1.103 s -
Agent appsec 1.203 s 99.382 ms (9.0%)
Agent iast 1.219 s 116.211 ms (10.5%)
Agent profiling 1.274 s 171.148 ms (15.5%)
Total tracing 9.273 s -
Total appsec 9.353 s 80.279 ms (0.9%)
Total iast 9.421 s 147.551 ms (1.6%)
Total profiling 9.468 s 195.279 ms (2.1%)
  • candidate results
Module Variant Duration Δ tracing
Agent tracing 1.091 s -
Agent appsec 1.207 s 115.649 ms (10.6%)
Agent iast 1.214 s 123.142 ms (11.3%)
Agent profiling 1.277 s 185.903 ms (17.0%)
Total tracing 9.197 s -
Total appsec 9.383 s 185.514 ms (2.0%)
Total iast 9.458 s 260.487 ms (2.8%)
Total profiling 9.354 s 156.728 ms (1.7%) 
gantt
    title petclinic - break down per module: candidate=1.32.0-SNAPSHOT~b7cf900de6, baseline=1.32.0-SNAPSHOT~e20dfff5e5

    dateFormat X
    axisFormat %s
section tracing
BytebuddyAgent [baseline] (711.445 ms) : 0, 711445
BytebuddyAgent [candidate] (703.355 ms) : 0, 703355
GlobalTracer [baseline] (297.658 ms) : 0, 297658
GlobalTracer [candidate] (295.193 ms) : 0, 295193
AppSec [baseline] (50.325 ms) : 0, 50325
AppSec [candidate] (49.498 ms) : 0, 49498
Remote Config [baseline] (1.103 ms) : 0, 1103
Remote Config [candidate] (1.091 ms) : 0, 1091
Telemetry [baseline] (7.584 ms) : 0, 7584
Telemetry [candidate] (7.484 ms) : 0, 7484
section appsec
BytebuddyAgent [baseline] (697.673 ms) : 0, 697673
BytebuddyAgent [candidate] (699.757 ms) : 0, 699757
GlobalTracer [baseline] (291.933 ms) : 0, 291933
GlobalTracer [candidate] (293.5 ms) : 0, 293500
AppSec [baseline] (153.344 ms) : 0, 153344
AppSec [candidate] (153.801 ms) : 0, 153801
IAST [baseline] (17.84 ms) : 0, 17840
IAST [candidate] (17.935 ms) : 0, 17935
Remote Config [baseline] (603.954 µs) : 0, 604
Remote Config [candidate] (607.697 µs) : 0, 608
Telemetry [baseline] (6.847 ms) : 0, 6847
Telemetry [candidate] (6.88 ms) : 0, 6880
section iast
BytebuddyAgent [baseline] (809.667 ms) : 0, 809667
BytebuddyAgent [candidate] (805.478 ms) : 0, 805478
GlobalTracer [baseline] (292.894 ms) : 0, 292894
GlobalTracer [candidate] (292.256 ms) : 0, 292256
AppSec [baseline] (51.507 ms) : 0, 51507
AppSec [candidate] (51.635 ms) : 0, 51635
IAST [baseline] (23.315 ms) : 0, 23315
IAST [candidate] (23.359 ms) : 0, 23359
Remote Config [baseline] (606.822 µs) : 0, 607
Remote Config [candidate] (573.72 µs) : 0, 574
Telemetry [baseline] (6.716 ms) : 0, 6716
Telemetry [candidate] (6.653 ms) : 0, 6653
section profiling
BytebuddyAgent [baseline] (689.305 ms) : 0, 689305
BytebuddyAgent [candidate] (690.675 ms) : 0, 690675
GlobalTracer [baseline] (375.934 ms) : 0, 375934
GlobalTracer [candidate] (377.614 ms) : 0, 377614
AppSec [baseline] (50.035 ms) : 0, 50035
AppSec [candidate] (50.026 ms) : 0, 50026
Remote Config [baseline] (872.316 µs) : 0, 872
Remote Config [candidate] (812.829 µs) : 0, 813
Telemetry [baseline] (7.237 ms) : 0, 7237
Telemetry [candidate] (7.332 ms) : 0, 7332
ProfilingAgent [baseline] (94.872 ms) : 0, 94872
ProfilingAgent [candidate] (94.526 ms) : 0, 94526
Profiling [baseline] (94.896 ms) : 0, 94896
Profiling [candidate] (94.549 ms) : 0, 94549

Load

Request duration reports for insecure-bank 
gantt
    title insecure-bank - request duration [CI 0.99] : candidate=1.32.0-SNAPSHOT~b7cf900de6, baseline=1.32.0-SNAPSHOT~e20dfff5e5
    dateFormat X
    axisFormat %s
section baseline
no_agent (362.851 µs) : 343, 382
.   : milestone, 363,
iast (479.87 µs) : 459, 500
.   : milestone, 480,
iast_FULL (544.035 µs) : 523, 565
.   : milestone, 544,
iast_GLOBAL (502.759 µs) : 482, 523
.   : milestone, 503,
iast_HARDCODED_SECRET_DISABLED (478.796 µs) : 458, 499
.   : milestone, 479,
iast_INACTIVE (452.002 µs) : 431, 473
.   : milestone, 452,
iast_TELEMETRY_OFF (475.493 µs) : 455, 496
.   : milestone, 475,
tracing (453.164 µs) : 433, 474
.   : milestone, 453,
section candidate
no_agent (370.295 µs) : 350, 390
.   : milestone, 370,
iast (476.325 µs) : 456, 497
.   : milestone, 476,
iast_FULL (544.086 µs) : 524, 565
.   : milestone, 544,
iast_GLOBAL (497.824 µs) : 478, 518
.   : milestone, 498,
iast_HARDCODED_SECRET_DISABLED (484.278 µs) : 464, 505
.   : milestone, 484,
iast_INACTIVE (456.508 µs) : 436, 477
.   : milestone, 457,
iast_TELEMETRY_OFF (477.886 µs) : 457, 499
.   : milestone, 478,
tracing (444.855 µs) : 425, 465
.   : milestone, 445,
  • baseline results
Variant Request duration [CI 0.99] Δ no_agent
no_agent 362.851 µs [343.465 µs, 382.238 µs] -
iast 479.87 µs [459.326 µs, 500.414 µs] 117.019 µs (32.2%)
iast_FULL 544.035 µs [523.455 µs, 564.615 µs] 181.184 µs (49.9%)
iast_GLOBAL 502.759 µs [482.317 µs, 523.201 µs] 139.908 µs (38.6%)
iast_HARDCODED_SECRET_DISABLED 478.796 µs [458.205 µs, 499.387 µs] 115.945 µs (32.0%)
iast_INACTIVE 452.002 µs [430.874 µs, 473.13 µs] 89.15 µs (24.6%)
iast_TELEMETRY_OFF 475.493 µs [454.717 µs, 496.269 µs] 112.642 µs (31.0%)
tracing 453.164 µs [432.807 µs, 473.52 µs] 90.312 µs (24.9%)
  • candidate results
Variant Request duration [CI 0.99] Δ no_agent
no_agent 370.295 µs [350.414 µs, 390.175 µs] -
iast 476.325 µs [456.06 µs, 496.591 µs] 106.031 µs (28.6%)
iast_FULL 544.086 µs [523.621 µs, 564.55 µs] 173.791 µs (46.9%)
iast_GLOBAL 497.824 µs [477.53 µs, 518.118 µs] 127.529 µs (34.4%)
iast_HARDCODED_SECRET_DISABLED 484.278 µs [463.632 µs, 504.923 µs] 113.983 µs (30.8%)
iast_INACTIVE 456.508 µs [436.123 µs, 476.893 µs] 86.213 µs (23.3%)
iast_TELEMETRY_OFF 477.886 µs [456.833 µs, 498.94 µs] 107.591 µs (29.1%)
tracing 444.855 µs [424.817 µs, 464.893 µs] 74.561 µs (20.1%)
Request duration reports for petclinic 
gantt
    title petclinic - request duration [CI 0.99] : candidate=1.32.0-SNAPSHOT~b7cf900de6, baseline=1.32.0-SNAPSHOT~e20dfff5e5
    dateFormat X
    axisFormat %s
section baseline
no_agent (1.355 ms) : 1336, 1374
.   : milestone, 1355,
appsec (1.78 ms) : 1756, 1803
.   : milestone, 1780,
iast (1.543 ms) : 1519, 1566
.   : milestone, 1543,
profiling (1.584 ms) : 1559, 1608
.   : milestone, 1584,
tracing (1.512 ms) : 1489, 1536
.   : milestone, 1512,
section candidate
no_agent (1.361 ms) : 1342, 1380
.   : milestone, 1361,
appsec (1.783 ms) : 1760, 1807
.   : milestone, 1783,
iast (1.517 ms) : 1493, 1541
.   : milestone, 1517,
profiling (1.58 ms) : 1555, 1605
.   : milestone, 1580,
tracing (1.511 ms) : 1487, 1535
.   : milestone, 1511,
  • baseline results
Variant Request duration [CI 0.99] Δ no_agent
no_agent 1.355 ms [1.336 ms, 1.374 ms] -
appsec 1.78 ms [1.756 ms, 1.803 ms] 424.413 µs (31.3%)
iast 1.543 ms [1.519 ms, 1.566 ms] 187.681 µs (13.8%)
profiling 1.584 ms [1.559 ms, 1.608 ms] 228.451 µs (16.9%)
tracing 1.512 ms [1.489 ms, 1.536 ms] 157.168 µs (11.6%)
  • candidate results
Variant Request duration [CI 0.99] Δ no_agent
no_agent 1.361 ms [1.342 ms, 1.38 ms] -
appsec 1.783 ms [1.76 ms, 1.807 ms] 422.162 µs (31.0%)
iast 1.517 ms [1.493 ms, 1.541 ms] 155.593 µs (11.4%)
profiling 1.58 ms [1.555 ms, 1.605 ms] 218.834 µs (16.1%)
tracing 1.511 ms [1.487 ms, 1.535 ms] 149.673 µs (11.0%)

mcculls
mcculls approved these changes Mar 20, 2024
View reviewed changes
Copy link
Contributor

@mcculls mcculls left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM, thanks for the additional test

@richardstartin richardstartin merged commit 302c754 into master Mar 21, 2024
80 checks passed
@richardstartin richardstartin deleted the rgs/fix-tpe-queue-timer branch March 21, 2024 06:07
@github-actions github-actions bot added this to the 1.32.0 milestone Mar 21, 2024
@PerfectSlayer PerfectSlayer changed the title ensure queue timer is started for RunnableFuture types Ensure queue timer is started for RunnableFuture types Apr 4, 2024
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

@dougqh dougqh Awaiting requested review from dougqh dougqh is a code owner automatically assigned from DataDog/apm-java

@am312 am312 Awaiting requested review from am312 am312 is a code owner automatically assigned from DataDog/apm-java

Assignees
No one assigned
Labels
comp: profiling Profiling
Projects
None yet
Milestone
1.32.0
Development

Successfully merging this pull request may close these issues.

None yet
2 participants
@richardstartin @mcculls