Immediately compiled SpEL Expression slows down on each use

[Fradantim]

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]

Loading

Is this not an intended use case?

Can I do something to maintain that initial throughput?

[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