ReflectivePropertyAccessor should cache sorted methods [SPR-16882]

[spring-projects-issues]

Pavel Khokhlov opened SPR-16882 and commented

After migration from SPEL 4.3.9.RELEASE -> 4.3.10.RELEASE we noticed performance degradation with SPEL Expression (at least 2.5x times).

In attachment you can find [^benchmark.zip]

You can see JMH report (I used jdk1.8.0_151)

This is 4.3.10.RELEASE

/Library/Java/JavaVirtualMachines/jdk1.8.0_151.jdk/Contents/Home/bin/java -Dfile.encoding=UTF-8 -classpath /Users/pkhokhlov/JProjects/benchmark/target/test-classes:/Users/pkhokhlov/.m2/repository/org/openjdk/jmh/jmh-core/1.21/jmh-core-1.21.jar:/Users/pkhokhlov/.m2/repository/net/sf/jopt-simple/jopt-simple/4.6/jopt-simple-4.6.jar:/Users/pkhokhlov/.m2/repository/org/apache/commons/commons-math3/3.2/commons-math3-3.2.jar:/Users/pkhokhlov/.m2/repository/org/openjdk/jmh/jmh-generator-annprocess/1.21/jmh-generator-annprocess-1.21.jar:/Users/pkhokhlov/.m2/repository/org/springframework/spring-expression/4.3.10.RELEASE/spring-expression-4.3.10.RELEASE.jar:/Users/pkhokhlov/.m2/repository/org/springframework/spring-core/4.3.10.RELEASE/spring-core-4.3.10.RELEASE.jar:/Users/pkhokhlov/.m2/repository/commons-logging/commons-logging/1.2/commons-logging-1.2.jar org.openjdk.jmh.Main org.spel.bug.SpelBenchmark.*
1. JMH version: 1.21
1. VM version: JDK 1.8.0_151, Java HotSpot(TM) 64-Bit Server VM, 25.151-b12
1. VM invoker: /Library/Java/JavaVirtualMachines/jdk1.8.0_151.jdk/Contents/Home/jre/bin/java
1. VM options: -Dfile.encoding=UTF-8
1. Warmup: 2 iterations, 10 s each
1. Measurement: 2 iterations, 10 s each
1. Timeout: 10 min per iteration
1. Threads: 1 thread, will synchronize iterations
1. Benchmark mode: Throughput, ops/time
1. Benchmark: org.spel.bug.SpelBenchmark.spel# Run progress: 0.00% complete, ETA 00:00:40
1. Fork: 1 of 1
1. Warmup Iteration   1: 197599.695 ops/s
1. Warmup Iteration   2: 225828.094 ops/s
Iteration   1: 225044.963 ops/s
Iteration   2: 228451.901 ops/s
Result "org.spel.bug.SpelBenchmark.spel":
  226748.432 ops/s
1. Run complete. Total time: 00:00:40REMEMBER: The numbers below are just data. To gain reusable insights, you need to follow up on
why the numbers are the way they are. Use profilers (see -prof, -lprof), design factorial
experiments, perform baseline and negative tests that provide experimental control, make sure
the benchmarking environment is safe on JVM/OS/HW level, ask for reviews from the domain experts.
Do not assume the numbers tell you what you want them to tell.Benchmark            Mode  Cnt       Score   Error  Units
SpelBenchmark.spel  thrpt    2  226748.432          ops/s

This is 4.3.9.RELEASE

/Library/Java/JavaVirtualMachines/jdk1.8.0_151.jdk/Contents/Home/bin/java -Dfile.encoding=UTF-8 -classpath /Users/pkhokhlov/JProjects/benchmark/target/test-classes:/Users/pkhokhlov/.m2/repository/org/openjdk/jmh/jmh-core/1.21/jmh-core-1.21.jar:/Users/pkhokhlov/.m2/repository/net/sf/jopt-simple/jopt-simple/4.6/jopt-simple-4.6.jar:/Users/pkhokhlov/.m2/repository/org/apache/commons/commons-math3/3.2/commons-math3-3.2.jar:/Users/pkhokhlov/.m2/repository/org/openjdk/jmh/jmh-generator-annprocess/1.21/jmh-generator-annprocess-1.21.jar:/Users/pkhokhlov/.m2/repository/org/springframework/spring-expression/4.3.9.RELEASE/spring-expression-4.3.9.RELEASE.jar:/Users/pkhokhlov/.m2/repository/org/springframework/spring-core/4.3.9.RELEASE/spring-core-4.3.9.RELEASE.jar:/Users/pkhokhlov/.m2/repository/commons-logging/commons-logging/1.2/commons-logging-1.2.jar org.openjdk.jmh.Main org.spel.bug.SpelBenchmark.*
1. JMH version: 1.21
1. VM version: JDK 1.8.0_151, Java HotSpot(TM) 64-Bit Server VM, 25.151-b12
1. VM invoker: /Library/Java/JavaVirtualMachines/jdk1.8.0_151.jdk/Contents/Home/jre/bin/java
1. VM options: -Dfile.encoding=UTF-8
1. Warmup: 2 iterations, 10 s each
1. Measurement: 2 iterations, 10 s each
1. Timeout: 10 min per iteration
1. Threads: 1 thread, will synchronize iterations
1. Benchmark mode: Throughput, ops/time
1. Benchmark: org.spel.bug.SpelBenchmark.spel# Run progress: 0.00% complete, ETA 00:00:40
1. Fork: 1 of 1
1. Warmup Iteration   1: 511243.723 ops/s
1. Warmup Iteration   2: 564409.791 ops/s
Iteration   1: 579457.251 ops/s
Iteration   2: 582177.903 ops/s
Result "org.spel.bug.SpelBenchmark.spel":
  580817.577 ops/s
1. Run complete. Total time: 00:00:40REMEMBER: The numbers below are just data. To gain reusable insights, you need to follow up on
why the numbers are the way they are. Use profilers (see -prof, -lprof), design factorial
experiments, perform baseline and negative tests that provide experimental control, make sure
the benchmarking environment is safe on JVM/OS/HW level, ask for reviews from the domain experts.
Do not assume the numbers tell you what you want them to tell.Benchmark            Mode  Cnt       Score   Error  Units
SpelBenchmark.spel  thrpt    2  580817.577          ops/s

 

---

Affects: 4.3.10

Attachments:

• benchmark.zip (2.76 kB)

Issue Links:

• PropertyOrFieldReference invalidly reuses cached PropertyAccessor [SPR-15769] #20324 PropertyOrFieldReference invalidly reuses cached PropertyAccessor
• Performance degradation in SpEL expression evaluation [SPR-16942] #21481 Performance degradation in SPEL expression evaluation

Referenced from: commits 4a6e9a5, bfcc1a1, da049f4, e2ccd55

Backported to: 4.3.18

0 votes, 5 watchers

[spring-projects-issues]

Pavel Khokhlov commented

Probably problem in method getSortedClassMethods

spring-framework/spring-expression/src/main/java/org/springframework/expression/spel/support/ReflectivePropertyAccessor.java

Line 433 in c44de3c

private Method[] getSortedClassMethods(Class<?> clazz) {

it calls too often and should be cached.

[spring-projects-issues]

Pavel Khokhlov commented

@Juergen Hoeller 

I have a question. I've checked release version 4.3.18 and I didn't find significant difference, look:

4.3.18.RELEASE

1. JMH version: 1.21
1. VM version: JDK 1.8.0_172, Java HotSpot(TM) 64-Bit Server VM, 25.172-b11
1. VM invoker: /Library/Java/JavaVirtualMachines/jdk1.8.0_172.jdk/Contents/Home/jre/bin/java
1. VM options: -javaagent:/Applications/IntelliJ IDEA.app/Contents/lib/idea_rt.jar=61697:/Applications/IntelliJ IDEA.app/Contents/bin -Dfile.encoding=UTF-8
1. Warmup: 2 iterations, 10 s each
1. Measurement: 2 iterations, 10 s each
1. Timeout: 10 min per iteration
1. Threads: 1 thread, will synchronize iterations
1. Benchmark mode: Throughput, ops/time
1. Benchmark: org.benchmark.dbg.spel.SpelBenchmark.spel# Run progress: 0.00% complete, ETA 00:00:40
1. Fork: 1 of 1
1. Warmup Iteration   1: 227388.780 ops/s
1. Warmup Iteration   2: 256747.696 ops/s
Iteration   1: 257249.790 ops/s
Iteration   2: 256228.128 ops/s
Result "org.benchmark.dbg.spel.SpelBenchmark.spel":
  256738.959 ops/s

256738.959 ops/s

 

4.3.9.RELEASE

1. JMH version: 1.21
1. VM version: JDK 1.8.0_172, Java HotSpot(TM) 64-Bit Server VM, 25.172-b11
1. VM invoker: /Library/Java/JavaVirtualMachines/jdk1.8.0_172.jdk/Contents/Home/jre/bin/java
1. VM options: -javaagent:/Applications/IntelliJ IDEA.app/Contents/lib/idea_rt.jar=61682:/Applications/IntelliJ IDEA.app/Contents/bin -Dfile.encoding=UTF-8
1. Warmup: 2 iterations, 10 s each
1. Measurement: 2 iterations, 10 s each
1. Timeout: 10 min per iteration
1. Threads: 1 thread, will synchronize iterations
1. Benchmark mode: Throughput, ops/time
1. Benchmark: org.benchmark.dbg.spel.SpelBenchmark.spel# Run progress: 0.00% complete, ETA 00:00:40
1. Fork: 1 of 1
1. Warmup Iteration   1: 533753.413 ops/s
1. Warmup Iteration   2: 589956.066 ops/s
Iteration   1: 585124.048 ops/s
Iteration   2: 583993.328 ops/s
Result "org.benchmark.dbg.spel.SpelBenchmark.spel":
  584558.688 ops/s

584558.688 ops/s

So what was fixed? Could you explain it please?

 

[spring-projects-issues]

Juergen Hoeller commented

The change was in the sorted method handling that you pointed out above... we're caching the sorted method array now.

I suppose there is some other hotspot involved too then?

[spring-projects-issues]

Kanthi Vaidya commented

Hi Juergen, I saw your code changes for caching the SortedMethods. We don't benefit much if you don't make your ConcurrentHashMap of sorted methods  a static variable.

Even after making the ConcurrentHashMap a static variable, we still don't get back the original performance of the prior spring versions. It definitely helps of course.

This is just one hotspot. More benchmarking and profiling is needed to identify other hot spots. And it probably makes sense to add a test case to the CI infrastructure to catch any such degradations.

This performance degradation, is preventing us from migration to Spring 5.

[spring-projects-issues]

Kanthi Vaidya commented

@juergen.hoeller can you please reopen this issue?

[spring-projects-issues]

Juergen Hoeller commented

Please create a new issue as a follow-up to this one. I'll schedule that new issue for 5.1 RC1 then.

Being at it, I'll rename this issue here to specifically cover the sorted methods cache that has been introduced in 4.3.18.