Skip to content

Commit ad2a8f5

Browse files
KarmKarm
authored
Merge pull request #373 from roberttoyonaga/correct-log-text
Correct log text for JFR perf test thresholds
2 parents ce4a7f4 + d089e0d commit ad2a8f5

File tree

3 files changed

+92
-47
lines changed

3 files changed

+92
-47
lines changed

‎README.md‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -138,6 +138,12 @@ e.g.
138138
linux.jvm.time.to.finish.threshold.ms=6924
139139
linux.native.time.to.finish.threshold.ms=14525
140140
```
141+
Most thresholds are defined as absolute values. However, there are some thresholds that are percentages. These types of thresholds are used for tests where two versions are compared against eachother. This means the % difference between the versions must not exceed the defined threshold. Such cases look like the example below.
142+
143+
```
144+
linux.diff_native.RSS.threshold.percent=35
145+
linux.diff_native.executable.size.threshold.percent=20
146+
```
141147

142148
The current `.conf` format enhances `.properties` format with the power of using the
143149
annotation strings, see:

‎apps/jfr-native-image-performance/threshold.conf‎

Lines changed: 19 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -1,23 +1,23 @@
1-
linux.diff_native.time.to.first.ok.request.threshold.ms=80
2-
linux.diff_native.RSS.threshold.kB=35
3-
linux.diff_native.executable.size.threshold.kB=20
4-
linux.diff_native.p50.latency=50
5-
linux.diff_native.mean.latency=50
6-
linux.diff_native.p90.latency=78
1+
linux.diff_native.time.to.first.ok.request.threshold.percent=80
2+
linux.diff_native.RSS.threshold.percent=35
3+
linux.diff_native.executable.size.threshold.percent=20
4+
linux.diff_native.p50.latency.percent=50
5+
linux.diff_native.mean.latency.percent=50
6+
linux.diff_native.p90.latency.percent=78
77

8-
macos.diff_native.time.to.first.ok.request.threshold.ms=40
9-
macos.diff_native.RSS.threshold.kB=38
10-
macos.diff_native.executable.size.threshold.kB=0
11-
macos.diff_native.p50.latency=30
12-
macos.diff_native.mean.latency=30
13-
macos.diff_native.p90.latency=30
8+
macos.diff_native.time.to.first.ok.request.threshold.percent=40
9+
macos.diff_native.RSS.threshold.percent=38
10+
macos.diff_native.executable.size.threshold.percent=0
11+
macos.diff_native.p50.latency.percent=30
12+
macos.diff_native.mean.latency.percent=30
13+
macos.diff_native.p90.latency.percent=30
1414

15-
linux.container.diff_native.time.to.first.ok.request.threshold.ms=80
16-
linux.container.diff_native.RSS.threshold.kB=50
17-
linux.container.diff_native.executable.size.threshold.kB=20
18-
linux.container.diff_native.p50.latency=80
19-
linux.container.diff_native.mean.latency=50
20-
linux.container.diff_native.p90.latency=100
15+
linux.container.diff_native.time.to.first.ok.request.threshold.percent=80
16+
linux.container.diff_native.RSS.threshold.percent=50
17+
linux.container.diff_native.executable.size.threshold.percent=20
18+
linux.container.diff_native.p50.latency.percent=80
19+
linux.container.diff_native.mean.latency.percent=50
20+
linux.container.diff_native.p90.latency.percent=100
2121

2222
@IfQuarkusVersion(min ="3.7.0")
23-
linux.container.diff_native.RSS.threshold.kB=57
23+
linux.container.diff_native.RSS.threshold.percent=57

‎testsuite/src/it/java/org/graalvm/tests/integration/utils/Logs.java‎

Lines changed: 67 additions & 28 deletions
Original file line numberDiff line numberDiff line change
@@ -47,6 +47,9 @@
4747
* @author Michal Karm Babacek <[email protected]>
4848
*/
4949
public class Logs {
50+
private static final String KB_prefix = ".kB";
51+
private static final String MS_prefix = ".ms";
52+
private static final String PERCENT_prefix = ".percent";
5053
private static final Logger LOGGER = Logger.getLogger(Logs.class.getName());
5154
private static final Pattern WARN_ERROR_DETECTION_PATTERN = Pattern.compile("(?i:.*(ERROR|SEVERE|WARN|No such file|Not found|unknown).*)");
5255
public static final long SKIP = -1L;
@@ -95,12 +98,12 @@ public String toString() {
9598
}
9699
}
97100

98-
public static void checkThreshold(Apps app, Mode mode, long executableSizeKb, long rssKb, long timeToFirstOKRequest,
101+
public static void checkThreshold(Apps app, Mode mode, long executableSize, long rss, long timeToFirstOKRequest,
99102
long timeToFinishMs, long mean, long p50, long p90) {
100103

101104
final Path properties = Path.of(BASE_DIR, app.dir, "threshold.conf");
102105
if (app.thresholdProperties.isEmpty() &&
103-
(executableSizeKb != SKIP || rssKb != SKIP || timeToFirstOKRequest != SKIP || timeToFinishMs != SKIP)) {
106+
(executableSize != SKIP || rss != SKIP || timeToFirstOKRequest != SKIP || timeToFinishMs != SKIP)) {
104107
LOGGER.warn("It seem there is no " +properties +
105108
". Skipping checking thresholds.");
106109
return;
@@ -110,44 +113,62 @@ public static void checkThreshold(Apps app, Mode mode, long executableSizeKb, lo
110113
((mode != Mode.NONE) ? "." + mode : "");
111114
final List<String> failures = new ArrayList<>();
112115

113-
if (executableSizeKb != SKIP) {
114-
final String key = propPrefix + ".executable.size.threshold.kB";
115-
if (app.thresholdProperties.containsKey(key)) {
116-
long executableSizeThresholdKb = app.thresholdProperties.get(key);
117-
assertThreshold(failures, executableSizeKb <= executableSizeThresholdKb,
116+
if (executableSize != SKIP) {
117+
final String key = propPrefix + ".executable.size.threshold";
118+
if (app.thresholdProperties.containsKey(key + KB_prefix)) {
119+
long executableSizeThreshold = app.thresholdProperties.get(key + KB_prefix);
120+
assertThreshold(failures, executableSize <= executableSizeThreshold,
118121
"Application " + app + (mode != null ? " in mode " + mode : "") + " executable size " +
119122
((mode == Mode.DIFF_JVM || mode == Mode.DIFF_NATIVE) ? "overhead is" : "is ") +
120-
executableSizeKb + " kB, which is over " +
121-
executableSizeThresholdKb + " kB threshold by " + percentageValOverTh(executableSizeKb, executableSizeThresholdKb) + "%.", false);
123+
executableSize + " kB, which is over " +
124+
executableSizeThreshold + " kB threshold by " + percentageValOverTh(executableSize, executableSizeThreshold) + "%.", false);
125+
} else if (app.thresholdProperties.containsKey(key + PERCENT_prefix)) {
126+
long executableSizeThreshold = app.thresholdProperties.get(key + PERCENT_prefix);
127+
assertThreshold(failures, executableSize <= executableSizeThreshold,
128+
"Application " + app + (mode != null ? " in mode " + mode : "") + " executable size " +
129+
executableSize + " % more than the control, which is over the " +
130+
executableSizeThreshold + " % threshold", false);
122131
} else {
123-
LOGGER.error("executableSizeKb was to be checked, but there is no " + key + " in " + properties);
132+
LOGGER.error("executableSize was to be checked, but there is no " + key + KB_prefix+ " or " + key + PERCENT_prefix + " in " + properties);
124133
}
125134
}
126135

127136
if (timeToFirstOKRequest != SKIP) {
128-
final String key = propPrefix + ".time.to.first.ok.request.threshold.ms";
129-
if (app.thresholdProperties.containsKey(key)) {
130-
long timeToFirstOKRequestThresholdMs = app.thresholdProperties.get(key);
131-
assertThreshold(failures, timeToFirstOKRequest <= timeToFirstOKRequestThresholdMs,
137+
final String key = propPrefix + ".time.to.first.ok.request.threshold";
138+
if (app.thresholdProperties.containsKey(key + MS_prefix)) {
139+
long timeToFirstOKRequestThreshold = app.thresholdProperties.get(key + MS_prefix);
140+
assertThreshold(failures, timeToFirstOKRequest <= timeToFirstOKRequestThreshold,
132141
"Application " + app + (mode != null ? " in mode " + mode : "") +
133142
" took " + timeToFirstOKRequest + " ms " + ((mode == Mode.DIFF_JVM || mode == Mode.DIFF_NATIVE) ? "more " : "") +
134143
"to get the first OK request, which is over " +
135-
timeToFirstOKRequestThresholdMs + " ms threshold by " + percentageValOverTh(timeToFirstOKRequest, timeToFirstOKRequestThresholdMs) + "%.", true);
144+
timeToFirstOKRequestThreshold + " ms threshold by " + percentageValOverTh(timeToFirstOKRequest, timeToFirstOKRequestThreshold) + "%.", true);
145+
} else if (app.thresholdProperties.containsKey(key + PERCENT_prefix)) {
146+
long timeToFirstOKRequestThreshold = app.thresholdProperties.get(key + PERCENT_prefix);
147+
assertThreshold(failures, timeToFirstOKRequest <= timeToFirstOKRequestThreshold,
148+
"Application " + app + (mode != null ? " in mode " + mode : "") +
149+
" took " + timeToFirstOKRequest + " % longer than the control to get the first OK request, which is over " +
150+
timeToFirstOKRequestThreshold + " % threshold", true);
136151
} else {
137-
LOGGER.error("timeToFirstOKRequest was to be checked, but there is no " + key + " in " + properties);
152+
LOGGER.error("timeToFirstOKRequest was to be checked, but there is no " + key + MS_prefix + " or " + key + PERCENT_prefix + " in " + properties);
138153
}
139154
}
140155

141-
if (rssKb != SKIP) {
142-
final String key = propPrefix + ".RSS.threshold.kB";
143-
if (app.thresholdProperties.containsKey(key)) {
144-
long rssThresholdKb = app.thresholdProperties.get(key);
145-
assertThreshold(failures, rssKb <= rssThresholdKb,
156+
if (rss != SKIP) {
157+
final String key = propPrefix + ".RSS.threshold";
158+
if (app.thresholdProperties.containsKey(key + KB_prefix)) {
159+
long rssThreshold = app.thresholdProperties.get(key + KB_prefix);
160+
assertThreshold(failures, rss <= rssThreshold,
146161
"Application " + app + (mode != null ? " in mode " + mode : "") +
147-
" consumed " + rssKb + " kB of RSS memory " + ((mode == Mode.DIFF_JVM || mode == Mode.DIFF_NATIVE) ? "more " : "") + ", which is over " +
148-
rssThresholdKb + " kB threshold by " + percentageValOverTh(rssKb, rssThresholdKb) + "%.", false);
149-
} else {
150-
LOGGER.error("rssKb was to be checked, but there is no " + key + " in " + properties);
162+
" consumed " + rss + " kB of RSS memory " + ((mode == Mode.DIFF_JVM || mode == Mode.DIFF_NATIVE) ? "more " : "") + ", which is over " +
163+
rssThreshold + " kB threshold by " + percentageValOverTh(rss, rssThreshold) + "%.", false);
164+
} else if (app.thresholdProperties.containsKey(key + PERCENT_prefix)) {
165+
long rssThreshold = app.thresholdProperties.get(key + PERCENT_prefix);
166+
assertThreshold(failures, rss <= rssThreshold,
167+
"Application " + app + (mode != null ? " in mode " + mode : "") +
168+
" consumed " + rss + " % more RSS memory than the control, which is over the " +
169+
rssThreshold + " % threshold", false);
170+
}else {
171+
LOGGER.error("rss was to be checked, but there is no " + key + KB_prefix + " or " + key + PERCENT_prefix + " in " + properties);
151172
}
152173
}
153174

@@ -172,8 +193,14 @@ public static void checkThreshold(Apps app, Mode mode, long executableSizeKb, lo
172193
"Application " + app + (mode != null ? " in mode " + mode : "") + " has mean response latency " +
173194
mean + ((mode == Mode.DIFF_JVM || mode == Mode.DIFF_NATIVE) ? " more" : " ") + ", which is over " +
174195
meanThreshold + " threshold by " + percentageValOverTh(mean, meanThreshold) + "%.", true);
196+
} else if (app.thresholdProperties.containsKey(key + PERCENT_prefix)) {
197+
long meanThreshold = app.thresholdProperties.get(key + PERCENT_prefix);
198+
assertThreshold(failures, mean <= meanThreshold,
199+
"Application " + app + (mode != null ? " in mode " + mode : "") + " has mean response latency " +
200+
mean + "% more than the control, which is over " +
201+
meanThreshold + " % threshold.", true);
175202
} else {
176-
LOGGER.error("mean was to be checked, but there is no " + key + " in " + properties);
203+
LOGGER.error("mean was to be checked, but there is no " + key + " or " + key + PERCENT_prefix + " in " + properties);
177204
}
178205
}
179206

@@ -185,8 +212,14 @@ public static void checkThreshold(Apps app, Mode mode, long executableSizeKb, lo
185212
"Application " + app + (mode != null ? " in mode " + mode : "") + " has p50 response latency " +
186213
p50 + ((mode == Mode.DIFF_JVM || mode == Mode.DIFF_NATIVE) ? " more" : "") + ", which is over " +
187214
p50Threshold + " threshold by " + percentageValOverTh(p50, p50Threshold) + "%.", true);
215+
} else if (app.thresholdProperties.containsKey(key + PERCENT_prefix)) {
216+
long p50Threshold = app.thresholdProperties.get(key + PERCENT_prefix);
217+
assertThreshold(failures, p50 <= p50Threshold,
218+
"Application " + app + (mode != null ? " in mode " + mode : "") + " has p50 response latency " +
219+
p50 + "% more than the control, which is over " +
220+
p50Threshold + " % threshold", true);
188221
} else {
189-
LOGGER.error("p99 was to be checked, but there is no " + key + " in " + properties);
222+
LOGGER.error("p99 was to be checked, but there is no " + key + " or " + key + PERCENT_prefix + " in " + properties);
190223
}
191224
}
192225

@@ -198,8 +231,14 @@ public static void checkThreshold(Apps app, Mode mode, long executableSizeKb, lo
198231
"Application " + app + (mode != null ? " in mode " + mode : "") + " has p90 response latency " +
199232
p90 + ((mode == Mode.DIFF_JVM || mode == Mode.DIFF_NATIVE) ? " more" : "") + ", which is over " +
200233
p90Threshold + " threshold by " + percentageValOverTh(p90, p90Threshold) + "%.", true);
234+
} else if (app.thresholdProperties.containsKey(key + PERCENT_prefix)) {
235+
long p90Threshold = app.thresholdProperties.get(key + PERCENT_prefix);
236+
assertThreshold(failures, p90 <= p90Threshold,
237+
"Application " + app + (mode != null ? " in mode " + mode : "") + " has p90 response latency " +
238+
p90 + " % more than the control, which is over " +
239+
p90Threshold + " % threshold", true);
201240
} else {
202-
LOGGER.error("p90 was to be checked, but there is no " + key + " in " + properties);
241+
LOGGER.error("p90 was to be checked, but there is no " + key + " or " + key + PERCENT_prefix + "in " + properties);
203242
}
204243
}
205244

0 commit comments

Comments
 (0)