use JFR timestamping for queue time thresholds #6703

richardstartin · 2024-02-20T13:47:13Z

What Does This Do

Exposes and feeds TSC counter from JFR to be used in queue time tracking. WIP because this exercise exposed need for refactoring to make changes like this maintainable. Will rebase on top of the pending refactoring.

WIP - this change

Motivation

Do not incur JNI overhead when recording time in queue

Additional Notes

Jira ticket: [PROJ-IDENT]

pr-commenter · 2024-02-20T14:35:57Z

Benchmarks

Startup

Parameters

	Baseline	Candidate
baseline_or_candidate	baseline	candidate
git_branch	master	rgs/queue-time-tsc
git_commit_date	1709904830	1709904408
git_commit_sha	`fa3cf4d`	`ed007cf`
release_version	1.32.0-SNAPSHOT~fa3cf4dc0e	1.32.0-SNAPSHOT~ed007cfa3f

See matching parameters

	Baseline	Candidate
application	insecure-bank	insecure-bank
ci_job_date	1709908825	1709908825
ci_job_id	455048267	455048267
ci_pipeline_id	29798300	29798300
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 petclinic

gantt
    title petclinic - global startup overhead: candidate=1.32.0-SNAPSHOT~ed007cfa3f, baseline=1.32.0-SNAPSHOT~fa3cf4dc0e

    dateFormat X
    axisFormat %s
section tracing
Agent [baseline] (1.087 s) : 0, 1086783
Total [baseline] (9.256 s) : 0, 9255759
Agent [candidate] (1.091 s) : 0, 1091113
Total [candidate] (9.26 s) : 0, 9259713
section appsec
Agent [baseline] (1.203 s) : 0, 1202913
Total [baseline] (9.293 s) : 0, 9292682
Agent [candidate] (1.203 s) : 0, 1203301
Total [candidate] (9.348 s) : 0, 9348121
section iast
Agent [baseline] (1.203 s) : 0, 1202785
Total [baseline] (9.303 s) : 0, 9303087
Agent [candidate] (1.208 s) : 0, 1208034
Total [candidate] (9.343 s) : 0, 9343292
section profiling
Agent [baseline] (1.272 s) : 0, 1271642
Total [baseline] (9.365 s) : 0, 9365079
Agent [candidate] (1.275 s) : 0, 1275161
Total [candidate] (9.395 s) : 0, 9395072

baseline results

Module	Variant	Duration	Δ tracing
Agent	tracing	1.087 s	-
Agent	appsec	1.203 s	116.13 ms (10.7%)
Agent	iast	1.203 s	116.001 ms (10.7%)
Agent	profiling	1.272 s	184.859 ms (17.0%)
Total	tracing	9.256 s	-
Total	appsec	9.293 s	36.923 ms (0.4%)
Total	iast	9.303 s	47.328 ms (0.5%)
Total	profiling	9.365 s	109.32 ms (1.2%)

candidate results

Module	Variant	Duration	Δ tracing
Agent	tracing	1.091 s	-
Agent	appsec	1.203 s	112.187 ms (10.3%)
Agent	iast	1.208 s	116.92 ms (10.7%)
Agent	profiling	1.275 s	184.047 ms (16.9%)
Total	tracing	9.26 s	-
Total	appsec	9.348 s	88.408 ms (1.0%)
Total	iast	9.343 s	83.579 ms (0.9%)
Total	profiling	9.395 s	135.359 ms (1.5%)

gantt
    title petclinic - break down per module: candidate=1.32.0-SNAPSHOT~ed007cfa3f, baseline=1.32.0-SNAPSHOT~fa3cf4dc0e

    dateFormat X
    axisFormat %s
section tracing
BytebuddyAgent [baseline] (699.984 ms) : 0, 699984
BytebuddyAgent [candidate] (702.125 ms) : 0, 702125
GlobalTracer [baseline] (292.587 ms) : 0, 292587
GlobalTracer [candidate] (294.511 ms) : 0, 294511
AppSec [baseline] (51.096 ms) : 0, 51096
AppSec [candidate] (51.282 ms) : 0, 51282
Remote Config [baseline] (732.505 µs) : 0, 733
Remote Config [candidate] (736.774 µs) : 0, 737
Telemetry [baseline] (7.792 ms) : 0, 7792
Telemetry [candidate] (7.836 ms) : 0, 7836
section appsec
BytebuddyAgent [baseline] (696.336 ms) : 0, 696336
BytebuddyAgent [candidate] (696.281 ms) : 0, 696281
GlobalTracer [baseline] (290.934 ms) : 0, 290934
GlobalTracer [candidate] (291.761 ms) : 0, 291761
AppSec [baseline] (156.115 ms) : 0, 156115
AppSec [candidate] (155.732 ms) : 0, 155732
IAST [baseline] (17.8 ms) : 0, 17800
IAST [candidate] (17.761 ms) : 0, 17761
Remote Config [baseline] (608.608 µs) : 0, 609
Remote Config [candidate] (612.995 µs) : 0, 613
Telemetry [baseline] (6.88 ms) : 0, 6880
Telemetry [candidate] (6.895 ms) : 0, 6895
section iast
BytebuddyAgent [baseline] (798.769 ms) : 0, 798769
BytebuddyAgent [candidate] (801.985 ms) : 0, 801985
GlobalTracer [baseline] (287.57 ms) : 0, 287570
GlobalTracer [candidate] (288.848 ms) : 0, 288848
AppSec [baseline] (50.119 ms) : 0, 50119
AppSec [candidate] (53.501 ms) : 0, 53501
IAST [baseline] (23.185 ms) : 0, 23185
IAST [candidate] (21.314 ms) : 0, 21314
Remote Config [baseline] (594.451 µs) : 0, 594
Remote Config [candidate] (584.46 µs) : 0, 584
Telemetry [baseline] (8.252 ms) : 0, 8252
Telemetry [candidate] (7.477 ms) : 0, 7477
section profiling
BytebuddyAgent [baseline] (687.738 ms) : 0, 687738
BytebuddyAgent [candidate] (688.708 ms) : 0, 688708
GlobalTracer [baseline] (374.654 ms) : 0, 374654
GlobalTracer [candidate] (373.551 ms) : 0, 373551
AppSec [baseline] (52.319 ms) : 0, 52319
AppSec [candidate] (53.062 ms) : 0, 53062
Remote Config [baseline] (716.818 µs) : 0, 717
Remote Config [candidate] (757.62 µs) : 0, 758
Telemetry [baseline] (7.387 ms) : 0, 7387
Telemetry [candidate] (7.407 ms) : 0, 7407
ProfilingAgent [baseline] (93.003 ms) : 0, 93003
ProfilingAgent [candidate] (95.489 ms) : 0, 95489
Profiling [baseline] (93.026 ms) : 0, 93026
Profiling [candidate] (95.513 ms) : 0, 95513

Startup time reports for insecure-bank

gantt
    title insecure-bank - global startup overhead: candidate=1.32.0-SNAPSHOT~ed007cfa3f, baseline=1.32.0-SNAPSHOT~fa3cf4dc0e

    dateFormat X
    axisFormat %s
section tracing
Agent [baseline] (1.08 s) : 0, 1079865
Total [baseline] (8.548 s) : 0, 8547974
Agent [candidate] (1.082 s) : 0, 1082234
Total [candidate] (8.598 s) : 0, 8597982
section iast
Agent [baseline] (1.211 s) : 0, 1210753
Total [baseline] (9.055 s) : 0, 9055397
Agent [candidate] (1.205 s) : 0, 1205382
Total [candidate] (9.053 s) : 0, 9053218
section iast_HARDCODED_SECRET_DISABLED
Agent [baseline] (1.207 s) : 0, 1207052
Total [baseline] (9.014 s) : 0, 9013804
Agent [candidate] (1.207 s) : 0, 1207078
Total [candidate] (9.019 s) : 0, 9018652
section iast_TELEMETRY_OFF
Agent [baseline] (1.197 s) : 0, 1197225
Total [baseline] (9.035 s) : 0, 9034784
Agent [candidate] (1.198 s) : 0, 1198353
Total [candidate] (9.031 s) : 0, 9031103

baseline results

Module	Variant	Duration	Δ tracing
Agent	tracing	1.08 s	-
Agent	iast	1.211 s	130.889 ms (12.1%)
Agent	iast_HARDCODED_SECRET_DISABLED	1.207 s	127.187 ms (11.8%)
Agent	iast_TELEMETRY_OFF	1.197 s	117.361 ms (10.9%)
Total	tracing	8.548 s	-
Total	iast	9.055 s	507.423 ms (5.9%)
Total	iast_HARDCODED_SECRET_DISABLED	9.014 s	465.831 ms (5.4%)
Total	iast_TELEMETRY_OFF	9.035 s	486.81 ms (5.7%)

candidate results

Module	Variant	Duration	Δ tracing
Agent	tracing	1.082 s	-
Agent	iast	1.205 s	123.148 ms (11.4%)
Agent	iast_HARDCODED_SECRET_DISABLED	1.207 s	124.844 ms (11.5%)
Agent	iast_TELEMETRY_OFF	1.198 s	116.119 ms (10.7%)
Total	tracing	8.598 s	-
Total	iast	9.053 s	455.236 ms (5.3%)
Total	iast_HARDCODED_SECRET_DISABLED	9.019 s	420.67 ms (4.9%)
Total	iast_TELEMETRY_OFF	9.031 s	433.121 ms (5.0%)

gantt
    title insecure-bank - break down per module: candidate=1.32.0-SNAPSHOT~ed007cfa3f, baseline=1.32.0-SNAPSHOT~fa3cf4dc0e

    dateFormat X
    axisFormat %s
section tracing
BytebuddyAgent [baseline] (695.323 ms) : 0, 695323
BytebuddyAgent [candidate] (696.734 ms) : 0, 696734
GlobalTracer [baseline] (290.87 ms) : 0, 290870
GlobalTracer [candidate] (292.044 ms) : 0, 292044
AppSec [baseline] (50.865 ms) : 0, 50865
AppSec [candidate] (50.525 ms) : 0, 50525
Remote Config [baseline] (727.882 µs) : 0, 728
Remote Config [candidate] (738.142 µs) : 0, 738
Telemetry [baseline] (7.694 ms) : 0, 7694
Telemetry [candidate] (7.768 ms) : 0, 7768
section iast
BytebuddyAgent [baseline] (804.051 ms) : 0, 804051
BytebuddyAgent [candidate] (799.366 ms) : 0, 799366
GlobalTracer [baseline] (289.33 ms) : 0, 289330
GlobalTracer [candidate] (288.344 ms) : 0, 288344
AppSec [baseline] (51.54 ms) : 0, 51540
AppSec [candidate] (53.587 ms) : 0, 53587
IAST [baseline] (23.914 ms) : 0, 23914
IAST [candidate] (22.412 ms) : 0, 22412
Remote Config [baseline] (598.268 µs) : 0, 598
Remote Config [candidate] (599.392 µs) : 0, 599
Telemetry [baseline] (6.74 ms) : 0, 6740
Telemetry [candidate] (6.797 ms) : 0, 6797
section iast_HARDCODED_SECRET_DISABLED
BytebuddyAgent [baseline] (800.497 ms) : 0, 800497
BytebuddyAgent [candidate] (800.517 ms) : 0, 800517
GlobalTracer [baseline] (288.555 ms) : 0, 288555
GlobalTracer [candidate] (288.951 ms) : 0, 288951
AppSec [baseline] (51.495 ms) : 0, 51495
AppSec [candidate] (51.391 ms) : 0, 51391
IAST [baseline] (24.032 ms) : 0, 24032
IAST [candidate] (23.816 ms) : 0, 23816
Remote Config [baseline] (591.047 µs) : 0, 591
Remote Config [candidate] (586.637 µs) : 0, 587
Telemetry [baseline] (7.483 ms) : 0, 7483
Telemetry [candidate] (7.479 ms) : 0, 7479
section iast_TELEMETRY_OFF
BytebuddyAgent [baseline] (792.27 ms) : 0, 792270
BytebuddyAgent [candidate] (792.313 ms) : 0, 792313
GlobalTracer [baseline] (288.674 ms) : 0, 288674
GlobalTracer [candidate] (289.306 ms) : 0, 289306
AppSec [baseline] (50.196 ms) : 0, 50196
AppSec [candidate] (53.157 ms) : 0, 53157
IAST [baseline] (23.994 ms) : 0, 23994
IAST [candidate] (21.493 ms) : 0, 21493
Remote Config [baseline] (595.376 µs) : 0, 595
Remote Config [candidate] (583.193 µs) : 0, 583
Telemetry [baseline] (7.327 ms) : 0, 7327
Telemetry [candidate] (7.291 ms) : 0, 7291

Load

Request duration reports for petclinic

gantt
    title petclinic - request duration [CI 0.99] : candidate=1.32.0-SNAPSHOT~ed007cfa3f, baseline=1.32.0-SNAPSHOT~fa3cf4dc0e
    dateFormat X
    axisFormat %s
section baseline
no_agent (1.35 ms) : 1331, 1369
.   : milestone, 1350,
appsec (1.764 ms) : 1741, 1788
.   : milestone, 1764,
iast (1.522 ms) : 1498, 1545
.   : milestone, 1522,
profiling (1.545 ms) : 1522, 1568
.   : milestone, 1545,
tracing (1.528 ms) : 1504, 1551
.   : milestone, 1528,
section candidate
no_agent (1.353 ms) : 1334, 1373
.   : milestone, 1353,
appsec (1.757 ms) : 1734, 1780
.   : milestone, 1757,
iast (1.533 ms) : 1509, 1556
.   : milestone, 1533,
profiling (1.528 ms) : 1504, 1551
.   : milestone, 1528,
tracing (1.505 ms) : 1482, 1529
.   : milestone, 1505,

baseline results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	1.35 ms [1.331 ms, 1.369 ms]	-
appsec	1.764 ms [1.741 ms, 1.788 ms]	413.95 µs (30.7%)
iast	1.522 ms [1.498 ms, 1.545 ms]	171.525 µs (12.7%)
profiling	1.545 ms [1.522 ms, 1.568 ms]	194.875 µs (14.4%)
tracing	1.528 ms [1.504 ms, 1.551 ms]	177.341 µs (13.1%)

candidate results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	1.353 ms [1.334 ms, 1.373 ms]	-
appsec	1.757 ms [1.734 ms, 1.78 ms]	403.672 µs (29.8%)
iast	1.533 ms [1.509 ms, 1.556 ms]	179.483 µs (13.3%)
profiling	1.528 ms [1.504 ms, 1.551 ms]	174.419 µs (12.9%)
tracing	1.505 ms [1.482 ms, 1.529 ms]	152.182 µs (11.2%)

Request duration reports for insecure-bank

gantt
    title insecure-bank - request duration [CI 0.99] : candidate=1.32.0-SNAPSHOT~ed007cfa3f, baseline=1.32.0-SNAPSHOT~fa3cf4dc0e
    dateFormat X
    axisFormat %s
section baseline
no_agent (366.019 µs) : 347, 385
.   : milestone, 366,
iast (476.152 µs) : 455, 497
.   : milestone, 476,
iast_FULL (541.638 µs) : 521, 562
.   : milestone, 542,
iast_GLOBAL (503.341 µs) : 481, 526
.   : milestone, 503,
iast_HARDCODED_SECRET_DISABLED (471.264 µs) : 451, 492
.   : milestone, 471,
iast_INACTIVE (444.424 µs) : 424, 465
.   : milestone, 444,
iast_TELEMETRY_OFF (468.985 µs) : 448, 490
.   : milestone, 469,
tracing (443.274 µs) : 423, 464
.   : milestone, 443,
section candidate
no_agent (368.742 µs) : 348, 389
.   : milestone, 369,
iast (466.192 µs) : 446, 487
.   : milestone, 466,
iast_FULL (538.399 µs) : 518, 559
.   : milestone, 538,
iast_GLOBAL (492.896 µs) : 473, 513
.   : milestone, 493,
iast_HARDCODED_SECRET_DISABLED (469.244 µs) : 449, 490
.   : milestone, 469,
iast_INACTIVE (443.571 µs) : 423, 464
.   : milestone, 444,
iast_TELEMETRY_OFF (468.062 µs) : 448, 488
.   : milestone, 468,
tracing (441.719 µs) : 421, 462
.   : milestone, 442,

baseline results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	366.019 µs [346.66 µs, 385.379 µs]	-
iast	476.152 µs [454.911 µs, 497.392 µs]	110.132 µs (30.1%)
iast_FULL	541.638 µs [521.127 µs, 562.149 µs]	175.618 µs (48.0%)
iast_GLOBAL	503.341 µs [481.144 µs, 525.537 µs]	137.321 µs (37.5%)
iast_HARDCODED_SECRET_DISABLED	471.264 µs [450.625 µs, 491.903 µs]	105.245 µs (28.8%)
iast_INACTIVE	444.424 µs [423.804 µs, 465.043 µs]	78.404 µs (21.4%)
iast_TELEMETRY_OFF	468.985 µs [447.671 µs, 490.299 µs]	102.966 µs (28.1%)
tracing	443.274 µs [422.998 µs, 463.551 µs]	77.255 µs (21.1%)

candidate results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	368.742 µs [348.075 µs, 389.409 µs]	-
iast	466.192 µs [445.855 µs, 486.529 µs]	97.45 µs (26.4%)
iast_FULL	538.399 µs [518.093 µs, 558.705 µs]	169.657 µs (46.0%)
iast_GLOBAL	492.896 µs [472.544 µs, 513.249 µs]	124.154 µs (33.7%)
iast_HARDCODED_SECRET_DISABLED	469.244 µs [448.738 µs, 489.75 µs]	100.502 µs (27.3%)
iast_INACTIVE	443.571 µs [423.387 µs, 463.754 µs]	74.829 µs (20.3%)
iast_TELEMETRY_OFF	468.062 µs [447.645 µs, 488.479 µs]	99.32 µs (26.9%)
tracing	441.719 µs [421.486 µs, 461.952 µs]	72.977 µs (19.8%)

github-actions · 2024-03-08T13:14:33Z

Hi! 👋 Looks like you updated a Git Submodule.
If this was not intentional please make sure to:

Update the submodule to the latest commit on the master branch using the git submodule update command,
Check you properly set up your environment for contributing.

github-actions · 2024-03-08T13:20:03Z

Hi! 👋 Looks like you updated a Git Submodule.
If this was not intentional please make sure to:

Update the submodule to the latest commit on the master branch using the git submodule update command,
Check you properly set up your environment for contributing.

richardstartin force-pushed the rgs/queue-time-tsc branch from 7eb8a86 to 41b901d Compare February 23, 2024 10:59

richardstartin force-pushed the rgs/queue-time-tsc branch from 41b901d to e4ca623 Compare March 8, 2024 13:14

richardstartin marked this pull request as ready for review March 8, 2024 13:15

richardstartin requested review from a team as code owners March 8, 2024 13:15

richardstartin requested review from dougqh and nayeem-kamal March 8, 2024 13:15

richardstartin force-pushed the rgs/queue-time-tsc branch from e4ca623 to 4f2bb9f Compare March 8, 2024 13:19

JFR based timer

ed007cf

richardstartin force-pushed the rgs/queue-time-tsc branch from 4f2bb9f to ed007cf Compare March 8, 2024 13:27

richardstartin added the comp: profiling Profiling label Mar 8, 2024

jbachorik approved these changes Mar 8, 2024

View reviewed changes

richardstartin merged commit e9c489f into master Mar 8, 2024
77 of 79 checks passed

richardstartin deleted the rgs/queue-time-tsc branch March 8, 2024 14:47

github-actions bot added this to the 1.32.0 milestone Mar 8, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

use JFR timestamping for queue time thresholds #6703

use JFR timestamping for queue time thresholds #6703

richardstartin commented Feb 20, 2024

pr-commenter bot commented Feb 20, 2024 •

edited

github-actions bot commented Mar 8, 2024

github-actions bot commented Mar 8, 2024

use JFR timestamping for queue time thresholds #6703

use JFR timestamping for queue time thresholds #6703

Conversation

richardstartin commented Feb 20, 2024

What Does This Do

Motivation

Additional Notes

pr-commenter bot commented Feb 20, 2024 • edited

Benchmarks

Startup

Parameters

Summary

Load

github-actions bot commented Mar 8, 2024

github-actions bot commented Mar 8, 2024

pr-commenter bot commented Feb 20, 2024 •

edited