Hello There!
We use lots of SpEL Expressions to manipulate objects and create new instances of objects (mostly strings).
In a recent poc testing performance of differents alternatives to this use case we found out immediately compiled SpelExpression starts quite fast, but after a short time (or some millons of ops) it's throughput halves.
Using Java:
java version "21" 2023-09-19
Java(TM) SE Runtime Environment Oracle GraalVM 21+35.1 (build 21+35-jvmci-23.1-b15)
Java HotSpot(TM) 64-Bit Server VM Oracle GraalVM 21+35.1 (build 21+35-jvmci-23.1-b15, mixed mode, sharing)
Spring
org.springframework.boot:spring-boot-starter-parent:3.3.4 (org.springframework:spring-expression:6.1.13)
public static void main(String... s) {
Map<String, Object> root = Map.of("foo", "bar");
Expression expression = new SpelExpressionParser(new SpelParserConfiguration(SpelCompilerMode.IMMEDIATE, null)).parseExpression("[foo].substring(0,1)");
AtomicInteger expressionOps = new AtomicInteger();
int loopCount = 0;
while (loopCount < 120) {
loopCount++;
expressionOps.set(0);
try {
CompletableFuture.supplyAsync(() -> {
while (true) {
expression.getValue(root);
expressionOps.incrementAndGet();
}
}).get(1, TimeUnit.SECONDS);
} catch (TimeoutException | ExecutionException | InterruptedException e) {
// no op
}
System.out.println(loopCount + "\t" + expressionOps + " ops/sec");
}
}
(I know this may not be the best way to execute a performance test)
result
1 106468809 ops/sec
2 76858700 ops/sec
3 58440833 ops/sec
4 63723883 ops/sec
5 63029349 ops/sec
6 61847942 ops/sec
7 62372654 ops/sec
8 61530194 ops/sec
9 62077340 ops/sec
10 62611521 ops/sec
11 63168501 ops/sec
12 61686067 ops/sec
13 61269262 ops/sec
14 62456026 ops/sec
15 67376736 ops/sec
16 62491016 ops/sec
17 61248502 ops/sec
18 58272199 ops/sec
19 61588422 ops/sec
20 62494339 ops/sec
21 63933284 ops/sec
22 60169862 ops/sec
23 60263788 ops/sec
24 58811820 ops/sec
25 62337873 ops/sec
26 64092402 ops/sec
27 64226228 ops/sec
28 63938694 ops/sec
29 62280862 ops/sec
30 61883910 ops/sec
31 59772020 ops/sec
32 55845966 ops/sec
33 58088455 ops/sec
34 60313176 ops/sec
35 61702904 ops/sec
36 60058085 ops/sec
37 58084405 ops/sec
38 59141274 ops/sec
39 57150345 ops/sec
40 59340823 ops/sec
41 59350710 ops/sec
42 59292279 ops/sec
43 59118264 ops/sec
44 54717859 ops/sec
45 56027505 ops/sec
46 56884413 ops/sec
47 56753541 ops/sec
48 54790069 ops/sec
49 56914703 ops/sec
50 58801666 ops/sec
51 61203990 ops/sec
52 59835119 ops/sec
53 58705683 ops/sec
54 57631493 ops/sec
55 55475370 ops/sec
56 56066452 ops/sec
57 59352852 ops/sec
58 56569769 ops/sec
59 55238780 ops/sec
60 56775104 ops/sec
61 62619808 ops/sec
62 63180309 ops/sec
63 62635372 ops/sec
64 62340839 ops/sec
65 63069140 ops/sec
66 63534674 ops/sec
67 58739326 ops/sec
68 57709071 ops/sec
69 52988673 ops/sec
70 56862452 ops/sec
71 57835487 ops/sec
72 59130428 ops/sec
73 63811116 ops/sec
74 64912248 ops/sec
75 65622490 ops/sec
76 63288306 ops/sec
77 63424435 ops/sec
78 64440044 ops/sec
79 61442975 ops/sec
80 61505119 ops/sec
81 56322460 ops/sec
82 53251012 ops/sec
83 56405411 ops/sec
84 56411554 ops/sec
85 55714282 ops/sec
86 59683349 ops/sec
87 59343053 ops/sec
88 60412439 ops/sec
89 60083218 ops/sec
90 58158879 ops/sec
91 60024897 ops/sec
92 59011061 ops/sec
93 59899315 ops/sec
94 56477961 ops/sec
95 52951155 ops/sec
96 58656927 ops/sec
97 57973760 ops/sec
98 58851680 ops/sec
99 58094087 ops/sec
100 59485404 ops/sec
101 58373482 ops/sec
102 57623260 ops/sec
103 56687019 ops/sec
104 59189517 ops/sec
105 61541489 ops/sec
106 56009505 ops/sec
107 54406023 ops/sec
108 55683797 ops/sec
109 57794844 ops/sec
110 56801866 ops/sec
111 58971439 ops/sec
112 61844510 ops/sec
113 62648223 ops/sec
114 61866733 ops/sec
115 64274086 ops/sec
116 63203469 ops/sec
117 64850860 ops/sec
118 63431436 ops/sec
119 54036480 ops/sec
120 56601604 ops/sec
---
config:
themeVariables:
xyChart:
plotColorPalette: "#ff0000"
---
xychart-beta
title "Throughput of the first 4 seconds"
y-axis "operations" 0 --> 107000000
x-axis "seconds" [1, 2, 3, 4, 5, 6, 7, 8]
line [106468809, 76858700, 58440833, 63723883, 63029349, 61847942, 62372654, 61530194]
Is this not an intended use case?
Can I do something to maintain that initial throughput?
Comment From: sbrannen
Hi @Fradantim,
It appears to me that your "performance test" is suffering from the use of a ForkJoinPool, which is used by default with CompletableFuture.supplyAsync(Supplier<U>).
If you switch to a single-threaded Executor, you should see that the throughput actually increases after the initial loop and quickly stabilizes.
I reworked your example using Executors.newSingleThreadExecutor() as follows.
public static void main(String... s) {
Map<String, Object> root = Map.of("foo", "bar");
SpelParserConfiguration configuration = new SpelParserConfiguration(SpelCompilerMode.IMMEDIATE, null);
SpelExpressionParser parser = new SpelExpressionParser(configuration);
Expression expression = parser.parseExpression("[foo].substring(0,1)");
ExecutorService executor = Executors.newSingleThreadExecutor();
AtomicInteger expressionOps = new AtomicInteger();
for (int loopCount = 0; loopCount < 120; loopCount++) {
expressionOps.set(0);
try {
CompletableFuture.supplyAsync(() -> {
while (true) {
expression.getValue(root);
expressionOps.incrementAndGet();
}
}, executor).get(1, TimeUnit.SECONDS);
}
catch (TimeoutException | ExecutionException | InterruptedException e) {
// no op
}
System.out.println(loopCount + "\t" + expressionOps + " ops/sec");
}
}
When I run that on my machine, I see the following trend.
0 98300504 ops/sec
1 140297605 ops/sec
2 141072144 ops/sec
3 142465356 ops/sec
4 142225512 ops/sec
5 141978597 ops/sec
6 140819864 ops/sec
7 142301147 ops/sec
8 142520190 ops/sec
9 141318892 ops/sec
10 140166873 ops/sec
11 141990514 ops/sec
12 142552508 ops/sec
13 142671503 ops/sec
14 142147598 ops/sec
15 142423959 ops/sec
16 141909586 ops/sec
17 142513922 ops/sec
18 142391894 ops/sec
19 141721314 ops/sec
20 141534411 ops/sec
In light of that, I am closing this issue.
However, if you are able to create a JMH benchmark that proves otherwise, feel free to provide that benchmark here, and we will investigate.
Cheers,
Sam