search

spring-projects / spring-framework

Spring Framework
https://spring.io/projects/spring-framework
Apache License 2.0
56.75k stars 38.15k forks source link

Immediately compiled SpEL Expression slows down on each use #33837

Closed Fradantim closed 3 weeks ago

Fradantim commented 3 weeks ago

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?

sbrannen commented 3 weeks ago

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