do not record queue time before JFR is initialised #5977

richardstartin · 2023-10-03T10:43:18Z

What Does This Do

Because the profiler's TSC hacks into JFR, it can read the frequency before it has been initialised, and get a default value instead, which is then saved into a constant. This delays recording queue time until JFR has been initialised, so we won't read the frequency before it's available.

Motivation

Additional Notes

pr-commenter · 2023-10-03T11:43:12Z

Benchmarks

Startup

Parameters

	Baseline	Candidate
commit	1.22.0-SNAPSHOT~d4ca13f3e4	1.22.0-SNAPSHOT~578a6151e1
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 2 performance regressions! Performance is the same for 60 cases.

scenario	Δ mean execution_time	candidate mean execution_time	baseline mean execution_time
scenario:petclinic:profiling:ProfilingAgent	worse [+16.526ms; +20.244ms] or [+13.659%; +16.732%]	139.376ms	120.991ms
scenario:petclinic:profiling:Profiling	worse [+16.525ms; +20.242ms] or [+13.653%; +16.723%]	139.424ms	121.040ms

Startup time reports for insecure-bank

gantt
    title insecure-bank - global startup overhead: candidate=1.22.0-SNAPSHOT~578a6151e1, baseline=1.22.0-SNAPSHOT~d4ca13f3e4

    dateFormat X
    axisFormat %s
section tracing
Agent [baseline] (1.54 s) : 0, 1540334
Total [baseline] (12.22 s) : 0, 12220355
Agent [candidate] (1.524 s) : 0, 1524329
Total [candidate] (12.147 s) : 0, 12146821
section appsec
Agent [baseline] (1.66 s) : 0, 1659652
Total [baseline] (12.219 s) : 0, 12218973
Agent [candidate] (1.661 s) : 0, 1660874
Total [candidate] (12.244 s) : 0, 12244451
section iast
Agent [baseline] (1.676 s) : 0, 1676441
Total [baseline] (12.93 s) : 0, 12930084
Agent [candidate] (1.669 s) : 0, 1669477
Total [candidate] (12.886 s) : 0, 12886150
section profiling
Agent [baseline] (1.817 s) : 0, 1817392
Total [baseline] (12.541 s) : 0, 12540930
Agent [candidate] (1.82 s) : 0, 1820206
Total [candidate] (12.485 s) : 0, 12484714

baseline results

Module	Variant	Duration	Δ tracing
Agent	tracing	1.54 s	-
Agent	appsec	1.66 s	119.318 ms (7.7%)
Agent	iast	1.676 s	136.107 ms (8.8%)
Agent	profiling	1.817 s	277.058 ms (18.0%)
Total	tracing	12.22 s	-
Total	appsec	12.219 s	-1.382 ms (-0.0%)
Total	iast	12.93 s	709.728 ms (5.8%)
Total	profiling	12.541 s	320.574 ms (2.6%)

candidate results

Module	Variant	Duration	Δ tracing
Agent	tracing	1.524 s	-
Agent	appsec	1.661 s	136.545 ms (9.0%)
Agent	iast	1.669 s	145.148 ms (9.5%)
Agent	profiling	1.82 s	295.877 ms (19.4%)
Total	tracing	12.147 s	-
Total	appsec	12.244 s	97.63 ms (0.8%)
Total	iast	12.886 s	739.329 ms (6.1%)
Total	profiling	12.485 s	337.893 ms (2.8%)

gantt
    title insecure-bank - break down per module: candidate=1.22.0-SNAPSHOT~578a6151e1, baseline=1.22.0-SNAPSHOT~d4ca13f3e4

    dateFormat X
    axisFormat %s
section tracing
BytebuddyAgent [baseline] (955.819 ms) : 0, 955819
BytebuddyAgent [candidate] (944.687 ms) : 0, 944687
GlobalTracer [baseline] (443.794 ms) : 0, 443794
GlobalTracer [candidate] (440.427 ms) : 0, 440427
AppSec [baseline] (71.083 ms) : 0, 71083
AppSec [candidate] (70.397 ms) : 0, 70397
Remote Config [baseline] (848.501 µs) : 0, 849
Remote Config [candidate] (819.879 µs) : 0, 820
Telemetry [baseline] (8.02 ms) : 0, 8020
Telemetry [candidate] (7.792 ms) : 0, 7792
section appsec
BytebuddyAgent [baseline] (945.578 ms) : 0, 945578
BytebuddyAgent [candidate] (946.366 ms) : 0, 946366
GlobalTracer [baseline] (438.603 ms) : 0, 438603
GlobalTracer [candidate] (438.879 ms) : 0, 438879
AppSec [baseline] (206.997 ms) : 0, 206997
AppSec [candidate] (207.092 ms) : 0, 207092
Remote Config [baseline] (785.847 µs) : 0, 786
Remote Config [candidate] (781.39 µs) : 0, 781
Telemetry [baseline] (7.689 ms) : 0, 7689
Telemetry [candidate] (7.683 ms) : 0, 7683
section iast
BytebuddyAgent [baseline] (1.105 s) : 0, 1105325
BytebuddyAgent [candidate] (1.102 s) : 0, 1102255
GlobalTracer [baseline] (413.49 ms) : 0, 413490
GlobalTracer [candidate] (412.001 ms) : 0, 412001
AppSec [baseline] (67.032 ms) : 0, 67032
AppSec [candidate] (66.701 ms) : 0, 66701
Remote Config [baseline] (692.018 µs) : 0, 692
Remote Config [candidate] (719.405 µs) : 0, 719
Telemetry [baseline] (10.817 ms) : 0, 10817
Telemetry [candidate] (9.405 ms) : 0, 9405
IAST [baseline] (18.804 ms) : 0, 18804
IAST [candidate] (18.154 ms) : 0, 18154
section profiling
BytebuddyAgent [baseline] (968.94 ms) : 0, 968940
BytebuddyAgent [candidate] (970.713 ms) : 0, 970713
GlobalTracer [baseline] (544.103 ms) : 0, 544103
GlobalTracer [candidate] (543.869 ms) : 0, 543869
AppSec [baseline] (72.116 ms) : 0, 72116
AppSec [candidate] (71.38 ms) : 0, 71380
Remote Config [baseline] (824.729 µs) : 0, 825
Remote Config [candidate] (836.362 µs) : 0, 836
Telemetry [baseline] (8.016 ms) : 0, 8016
Telemetry [candidate] (8.022 ms) : 0, 8022
ProfilingAgent [baseline] (135.689 ms) : 0, 135689
ProfilingAgent [candidate] (137.243 ms) : 0, 137243
Profiling [baseline] (135.737 ms) : 0, 135737
Profiling [candidate] (137.291 ms) : 0, 137291

Startup time reports for petclinic

gantt
    title petclinic - global startup overhead: candidate=1.22.0-SNAPSHOT~578a6151e1, baseline=1.22.0-SNAPSHOT~d4ca13f3e4

    dateFormat X
    axisFormat %s
section tracing
Agent [baseline] (1.524 s) : 0, 1523912
Total [baseline] (12.656 s) : 0, 12655936
Agent [candidate] (1.532 s) : 0, 1532343
Total [candidate] (12.726 s) : 0, 12726138
section appsec
Agent [baseline] (1.658 s) : 0, 1657828
Total [baseline] (12.775 s) : 0, 12775423
Agent [candidate] (1.669 s) : 0, 1669396
Total [candidate] (12.834 s) : 0, 12834249
section iast
Agent [baseline] (1.675 s) : 0, 1674820
Total [baseline] (13.12 s) : 0, 13120132
Agent [candidate] (1.673 s) : 0, 1673320
Total [candidate] (13.1 s) : 0, 13099635
section profiling
Agent [baseline] (1.8 s) : 0, 1800335
Total [baseline] (13.06 s) : 0, 13059883
Agent [candidate] (1.82 s) : 0, 1820019
Total [candidate] (13.077 s) : 0, 13076984

baseline results

Module	Variant	Duration	Δ tracing
Agent	tracing	1.524 s	-
Agent	appsec	1.658 s	133.917 ms (8.8%)
Agent	iast	1.675 s	150.908 ms (9.9%)
Agent	profiling	1.8 s	276.423 ms (18.1%)
Total	tracing	12.656 s	-
Total	appsec	12.775 s	119.487 ms (0.9%)
Total	iast	13.12 s	464.197 ms (3.7%)
Total	profiling	13.06 s	403.947 ms (3.2%)

candidate results

Module	Variant	Duration	Δ tracing
Agent	tracing	1.532 s	-
Agent	appsec	1.669 s	137.054 ms (8.9%)
Agent	iast	1.673 s	140.978 ms (9.2%)
Agent	profiling	1.82 s	287.676 ms (18.8%)
Total	tracing	12.726 s	-
Total	appsec	12.834 s	108.112 ms (0.8%)
Total	iast	13.1 s	373.497 ms (2.9%)
Total	profiling	13.077 s	350.846 ms (2.8%)

gantt
    title petclinic - break down per module: candidate=1.22.0-SNAPSHOT~578a6151e1, baseline=1.22.0-SNAPSHOT~d4ca13f3e4

    dateFormat X
    axisFormat %s
section tracing
BytebuddyAgent [baseline] (944.571 ms) : 0, 944571
BytebuddyAgent [candidate] (950.298 ms) : 0, 950298
GlobalTracer [baseline] (440.022 ms) : 0, 440022
GlobalTracer [candidate] (442.025 ms) : 0, 442025
AppSec [baseline] (70.784 ms) : 0, 70784
AppSec [candidate] (70.865 ms) : 0, 70865
Remote Config [baseline] (824.76 µs) : 0, 825
Remote Config [candidate] (823.612 µs) : 0, 824
Telemetry [baseline] (7.754 ms) : 0, 7754
Telemetry [candidate] (7.877 ms) : 0, 7877
section appsec
BytebuddyAgent [baseline] (944.505 ms) : 0, 944505
BytebuddyAgent [candidate] (951.724 ms) : 0, 951724
GlobalTracer [baseline] (438.303 ms) : 0, 438303
GlobalTracer [candidate] (441.498 ms) : 0, 441498
AppSec [baseline] (206.884 ms) : 0, 206884
AppSec [candidate] (207.182 ms) : 0, 207182
Remote Config [baseline] (784.438 µs) : 0, 784
Remote Config [candidate] (795.89 µs) : 0, 796
Telemetry [baseline] (7.612 ms) : 0, 7612
Telemetry [candidate] (7.816 ms) : 0, 7816
section iast
BytebuddyAgent [baseline] (1.106 s) : 0, 1105952
BytebuddyAgent [candidate] (1.104 s) : 0, 1104317
GlobalTracer [baseline] (414.301 ms) : 0, 414301
GlobalTracer [candidate] (413.673 ms) : 0, 413673
AppSec [baseline] (67.031 ms) : 0, 67031
AppSec [candidate] (66.98 ms) : 0, 66980
Remote Config [baseline] (689.993 µs) : 0, 690
Remote Config [candidate] (674.145 µs) : 0, 674
Telemetry [baseline] (8.009 ms) : 0, 8009
Telemetry [candidate] (9.345 ms) : 0, 9345
IAST [baseline] (18.834 ms) : 0, 18834
IAST [candidate] (17.975 ms) : 0, 17975
section profiling
BytebuddyAgent [baseline] (967.903 ms) : 0, 967903
BytebuddyAgent [candidate] (968.639 ms) : 0, 968639
GlobalTracer [baseline] (543.355 ms) : 0, 543355
GlobalTracer [candidate] (543.24 ms) : 0, 543240
AppSec [baseline] (71.743 ms) : 0, 71743
AppSec [candidate] (71.989 ms) : 0, 71989
Remote Config [baseline] (825.35 µs) : 0, 825
Remote Config [candidate] (822.32 µs) : 0, 822
Telemetry [baseline] (7.944 ms) : 0, 7944
Telemetry [candidate] (8.003 ms) : 0, 8003
ProfilingAgent [baseline] (120.991 ms) : 0, 120991
ProfilingAgent [candidate] (139.376 ms) : 0, 139376
Profiling [baseline] (121.04 ms) : 0, 121040
Profiling [candidate] (139.424 ms) : 0, 139424

Load

Parameters

	Baseline	Candidate
commit	1.22.0-SNAPSHOT~d4ca13f3e4	1.22.0-SNAPSHOT~578a6151e1
config	baseline	candidate
end_time	2023-10-03T11:09:41	2023-10-03T11:34:33
start_time	2023-10-03T11:09:18	2023-10-03T11:34:09

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 insecure-bank

gantt
    title insecure-bank - request duration [CI 0.99] : candidate=1.22.0-SNAPSHOT~578a6151e1, baseline=1.22.0-SNAPSHOT~d4ca13f3e4
    dateFormat X
    axisFormat %s
section baseline
no_agent (445.311 µs) : 417, 474
.   : milestone, 445,
appsec (873.423 µs) : 842, 905
.   : milestone, 873,
iast (557.134 µs) : 525, 589
.   : milestone, 557,
iast_FULL (648.319 µs) : 618, 679
.   : milestone, 648,
iast_INACTIVE (522.735 µs) : 492, 553
.   : milestone, 523,
profiling (532.643 µs) : 501, 564
.   : milestone, 533,
tracing (523.407 µs) : 494, 553
.   : milestone, 523,
section candidate
no_agent (446.432 µs) : 417, 476
.   : milestone, 446,
appsec (875.674 µs) : 846, 905
.   : milestone, 876,
iast (562.218 µs) : 532, 593
.   : milestone, 562,
iast_FULL (647.905 µs) : 617, 679
.   : milestone, 648,
iast_INACTIVE (525.277 µs) : 495, 555
.   : milestone, 525,
profiling (533.886 µs) : 503, 564
.   : milestone, 534,
tracing (524.508 µs) : 494, 555
.   : milestone, 525,

baseline results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	445.311 µs [416.757 µs, 473.865 µs]	-
appsec	873.423 µs [842.145 µs, 904.702 µs]	428.112 µs (96.1%)
iast	557.134 µs [525.462 µs, 588.807 µs]	111.823 µs (25.1%)
iast_FULL	648.319 µs [617.963 µs, 678.674 µs]	203.008 µs (45.6%)
iast_INACTIVE	522.735 µs [492.459 µs, 553.011 µs]	77.424 µs (17.4%)
profiling	532.643 µs [501.318 µs, 563.968 µs]	87.332 µs (19.6%)
tracing	523.407 µs [493.628 µs, 553.187 µs]	78.096 µs (17.5%)

candidate results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	446.432 µs [417.175 µs, 475.689 µs]	-
appsec	875.674 µs [845.851 µs, 905.497 µs]	429.242 µs (96.1%)
iast	562.218 µs [531.697 µs, 592.74 µs]	115.786 µs (25.9%)
iast_FULL	647.905 µs [616.706 µs, 679.104 µs]	201.473 µs (45.1%)
iast_INACTIVE	525.277 µs [495.163 µs, 555.391 µs]	78.845 µs (17.7%)
profiling	533.886 µs [503.443 µs, 564.33 µs]	87.454 µs (19.6%)
tracing	524.508 µs [494.417 µs, 554.599 µs]	78.076 µs (17.5%)

Request duration reports for petclinic

gantt
    title petclinic - request duration [CI 0.99] : candidate=1.22.0-SNAPSHOT~578a6151e1, baseline=1.22.0-SNAPSHOT~d4ca13f3e4
    dateFormat X
    axisFormat %s
section baseline
no_agent (1.667 ms) : 1642, 1691
.   : milestone, 1667,
appsec (2.126 ms) : 2094, 2159
.   : milestone, 2126,
iast (1.816 ms) : 1782, 1849
.   : milestone, 1816,
profiling (1.875 ms) : 1837, 1912
.   : milestone, 1875,
tracing (1.801 ms) : 1769, 1833
.   : milestone, 1801,
section candidate
no_agent (1.665 ms) : 1640, 1690
.   : milestone, 1665,
appsec (2.139 ms) : 2107, 2171
.   : milestone, 2139,
iast (1.83 ms) : 1797, 1864
.   : milestone, 1830,
profiling (1.837 ms) : 1805, 1870
.   : milestone, 1837,
tracing (1.811 ms) : 1778, 1844
.   : milestone, 1811,

baseline results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	1.667 ms [1.642 ms, 1.691 ms]	-
appsec	2.126 ms [2.094 ms, 2.159 ms]	459.638 µs (27.6%)
iast	1.816 ms [1.782 ms, 1.849 ms]	149.064 µs (8.9%)
profiling	1.875 ms [1.837 ms, 1.912 ms]	207.805 µs (12.5%)
tracing	1.801 ms [1.769 ms, 1.833 ms]	134.351 µs (8.1%)

candidate results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	1.665 ms [1.64 ms, 1.69 ms]	-
appsec	2.139 ms [2.107 ms, 2.171 ms]	473.939 µs (28.5%)
iast	1.83 ms [1.797 ms, 1.864 ms]	165.395 µs (9.9%)
profiling	1.837 ms [1.805 ms, 1.87 ms]	172.334 µs (10.4%)
tracing	1.811 ms [1.778 ms, 1.844 ms]	146.042 µs (8.8%)

richardstartin added the comp: profiling Profiling label Oct 3, 2023

richardstartin requested a review from jbachorik October 3, 2023 10:43

richardstartin requested a review from a team as a code owner October 3, 2023 10:43

richardstartin requested review from dougqh and am312 October 3, 2023 10:43

do not record queue time before JFR is initialised

a706c3d

richardstartin force-pushed the rgs/delay-queue-time branch from 578a615 to a706c3d Compare October 3, 2023 11:17

jbachorik approved these changes Oct 3, 2023

View reviewed changes

richardstartin merged commit 10b272f into master Oct 3, 2023
68 of 69 checks passed

richardstartin deleted the rgs/delay-queue-time branch October 3, 2023 12:06

github-actions bot added this to the 1.22.0 milestone Oct 3, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

do not record queue time before JFR is initialised #5977

do not record queue time before JFR is initialised #5977

richardstartin commented Oct 3, 2023

pr-commenter bot commented Oct 3, 2023

do not record queue time before JFR is initialised #5977

do not record queue time before JFR is initialised #5977

Conversation

richardstartin commented Oct 3, 2023

What Does This Do

Motivation

Additional Notes

pr-commenter bot commented Oct 3, 2023

Benchmarks

Startup

Parameters

Summary

Load

Parameters

Summary