Skip to content

Speed up binding of @ConfigurationProperties with a large object graph #15760

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
dsyer opened this issue Jan 22, 2019 · 16 comments
Closed

Speed up binding of @ConfigurationProperties with a large object graph #15760

dsyer opened this issue Jan 22, 2019 · 16 comments
Assignees
Labels
theme: performance Issues related to general performance type: enhancement A general enhancement
Milestone

Comments

@dsyer
Copy link
Member

dsyer commented Jan 22, 2019

@snicoll and I were looking at startup times in Initializr - there's a 2 second delay while the InitializrProperties is being bound. Here are some benchmarks:

class                method  prof       size     median    mean      range
PropertiesBenchmarkIT  auto  small      1        3803.788  3946.267  96.863
PropertiesBenchmarkIT  auto  medium     134      62.431    64.536    1.551
PropertiesBenchmarkIT  auto  large      1093     0.641     0.657     0.014

UPDATE: I edited the table above to make the "size" metric actually match the size
of the properties bound (I don't know where JMH gets its counter metrics from sometimes).

The "large" sample above is using the same YAML as production app, and
0.641 ops/sec is getting on for 2 seconds per op (1.5 anyway). So it
sucks.

Looking in Flight Controller I'm seeing GC pressure from ConfigurationPropertyName.buildString().

List of property names passing through ConfigurationPropertyName.buildString() on application start up: prop.txt. We can see that sometimes the method is called multiple times for the same property name (but only for indexed properties), and also that there is a lot of duplication in the indexed properties. Maybe that can be optimized?

@spring-projects-issues spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged label Jan 22, 2019
@dsyer dsyer added the theme: performance Issues related to general performance label Jan 22, 2019
@philwebb
Copy link
Member

Perhaps some cases we fixed in #13414 were missed. @dsyer is that PropertiesBenchmarkIT part of https://github.com/dsyer/spring-boot-startup-bench ? I can't seem to find it.

@dsyer
Copy link
Member Author

dsyer commented Jan 22, 2019

There's a branch of initializr with the benchmark tests here: https://github.com/dsyer/initializr/tree/bench

@philwebb philwebb added type: task A general task and removed status: waiting-for-triage An issue we've not yet triaged labels Jan 22, 2019
@philwebb philwebb added this to the 2.2.x milestone Jan 22, 2019
@dsyer
Copy link
Member Author

dsyer commented Jan 22, 2019

Here's another (different) measurement:

Benchmark                 (prof)  Mode  Cnt  Score   Error  Units
LauncherBenchmarkIT.auto  medium  avgt   10  0.323 ± 0.008   s/op
LauncherBenchmarkIT.auto   small  avgt   10  0.271 ± 0.006   s/op
LauncherBenchmarkIT.auto   large  avgt   10  1.936 ± 0.047   s/op

Where "small", "medium" and "large" mean the same as above. The benchmark this time is the time to start an empty Spring Boot app with just @EnableConfigurationProperties(InitializrProperties.class).

The key point is the difference - "medium" is 60ms "slower" than small, "large" is 1600ms "slower" than "medium". The difference between "large" and "medium" is a factor of roughly 10 in number of properties bound, but it takes more than a factor of 10 longer. However it scales, it's unpleasant.

@dreis2211
Copy link
Contributor

dreis2211 commented Jan 22, 2019

I wonder if the toString() calls inside equals() could be avoided. (Without knowing the stacktrace - so ignore me when this is not the root-cause)

@dsyer
Copy link
Member Author

dsyer commented Jan 22, 2019

That's not the problem. The toString() values are cached. And used as map keys, so they are needed for more than cosmetic purposes.

@wilkinsona
Copy link
Member

wilkinsona commented Jan 23, 2019

Using getThreadAllocatedBytes(long) on com.sun.management.ThreadMXBean, I can see that binding a single instance of InitializrProperties using the large YAML file allocates roughly 12900000 bytes once things have settled down. I can reduce this to roughly 12000000 bytes by making two changes:

  • Reducing ElementsParser.DEFAULT_CAPACITY to 2
  • Sizing the StringBuilder created in ConfigurationPropertyName.buildToString to be 8 times the number of elements

The reduction in allocation also results in a reduction in GC activity with an increases in bindings per GC from 10 to 11..

Before:

[GC (Allocation Failure)  135808K->4344K(482816K), 0.0029441 secs]
Bound io.spring.initializr.metadata.InitializrProperties@53f0a4cb in 514.623635ms, allocating 12888200 bytes
Bound io.spring.initializr.metadata.InitializrProperties@77a7cf58 in 509.089687ms, allocating 12889592 bytes
Bound io.spring.initializr.metadata.InitializrProperties@3d97a632 in 511.324507ms, allocating 12888200 bytes
Bound io.spring.initializr.metadata.InitializrProperties@616fe72b in 511.953273ms, allocating 12888200 bytes
Bound io.spring.initializr.metadata.InitializrProperties@37efd131 in 509.830269ms, allocating 12885512 bytes
Bound io.spring.initializr.metadata.InitializrProperties@7e7b159b in 520.628152ms, allocating 12885512 bytes
Bound io.spring.initializr.metadata.InitializrProperties@7e5d9a50 in 525.064667ms, allocating 12885512 bytes
Bound io.spring.initializr.metadata.InitializrProperties@60957c0f in 511.049757ms, allocating 12885512 bytes
Bound io.spring.initializr.metadata.InitializrProperties@293a5f75 in 517.648054ms, allocating 12885512 bytes
Bound io.spring.initializr.metadata.InitializrProperties@fcb4004 in 517.881954ms, allocating 12885512 bytes
[GC (Allocation Failure)  132856K->4304K(479744K), 0.0035482 secs]

After:

[GC (Allocation Failure)  129368K->4045K(473088K), 0.0036435 secs]
Bound io.spring.initializr.metadata.InitializrProperties@2c7b5824 in 463.770306ms, allocating 11990408 bytes
Bound io.spring.initializr.metadata.InitializrProperties@302a07d in 464.024755ms, allocating 11990408 bytes
Bound io.spring.initializr.metadata.InitializrProperties@5cdd09b1 in 463.594168ms, allocating 11990408 bytes
Bound io.spring.initializr.metadata.InitializrProperties@8c11eee in 463.083125ms, allocating 11990872 bytes
Bound io.spring.initializr.metadata.InitializrProperties@7e8dcdaa in 450.857177ms, allocating 11988232 bytes
Bound io.spring.initializr.metadata.InitializrProperties@681a8b4e in 520.015624ms, allocating 11988104 bytes
Bound io.spring.initializr.metadata.InitializrProperties@5cbe877d in 483.575575ms, allocating 11988104 bytes
Bound io.spring.initializr.metadata.InitializrProperties@5c08c46a in 468.700188ms, allocating 11988104 bytes
Bound io.spring.initializr.metadata.InitializrProperties@4cf8b2dc in 486.614003ms, allocating 11988104 bytes
Bound io.spring.initializr.metadata.InitializrProperties@708400f6 in 466.097654ms, allocating 11988104 bytes
Bound io.spring.initializr.metadata.InitializrProperties@5829e4f4 in 459.904762ms, allocating 11988104 bytes
[GC (Allocation Failure)  126925K->4037K(470528K), 0.0006947 secs]

There also appears to be some improvement in overall performance. Note that the timings above appear relatively fast due to the JIT.

I'm not yet convinced that the changes are generally suitable. The two changes may be quicker for the large YAML file but slower for other files with different property structure and property name lengths.

@wilkinsona
Copy link
Member

There's a bug in ConfigurationPropertyName.ElementsParser that means it will expand its storage whenever the source is 6 or more characters long, irrespective of how many elements that source contains:

I think it should be using the size instead:

if (this.start.length == this.size) {

With just this change in place, we see a drop in allocated bytes to roughly 12300000:

[GC (Allocation Failure)  129304K->3952K(473088K), 0.0029577 secs]
Bound io.spring.initializr.metadata.InitializrProperties@3b0c9195 in 478.402291ms, allocating 12285272 bytes
Bound io.spring.initializr.metadata.InitializrProperties@366c4480 in 473.533618ms, allocating 12285272 bytes
Bound io.spring.initializr.metadata.InitializrProperties@2c7b5824 in 473.792384ms, allocating 12285272 bytes
Bound io.spring.initializr.metadata.InitializrProperties@302a07d in 474.496672ms, allocating 12285272 bytes
Bound io.spring.initializr.metadata.InitializrProperties@5cdd09b1 in 462.404756ms, allocating 12285272 bytes
Bound io.spring.initializr.metadata.InitializrProperties@8c11eee in 477.309288ms, allocating 12285736 bytes
Bound io.spring.initializr.metadata.InitializrProperties@7e8dcdaa in 476.518623ms, allocating 12283096 bytes
Bound io.spring.initializr.metadata.InitializrProperties@681a8b4e in 485.739673ms, allocating 12282968 bytes
Bound io.spring.initializr.metadata.InitializrProperties@5cbe877d in 503.086719ms, allocating 12282968 bytes
Bound io.spring.initializr.metadata.InitializrProperties@5c08c46a in 485.289794ms, allocating 12282968 bytes
Bound io.spring.initializr.metadata.InitializrProperties@4cf8b2dc in 477.006301ms, allocating 12282968 bytes
[GC (Allocation Failure)  126832K->3976K(470528K), 0.0009202 secs]

@dsyer
Copy link
Member Author

dsyer commented Jan 23, 2019

Every little helps I guess. I tried those changes in the benchmarks and didn't see a huge improvement:

class, method, prof, size, median, mean, range
io.spring.initializr.bench.PropertiesBenchmarkIT, auto, medium, 134.000, 64.169, 66.139, 1.607
io.spring.initializr.bench.PropertiesBenchmarkIT, auto, small, 1.000, 3790.730, 3944.499, 114.667
io.spring.initializr.bench.PropertiesBenchmarkIT, auto, large, 1093.000, 0.657, 0.674, 0.017
Benchmark                 (prof)  Mode  Cnt  Score   Error  Units
LauncherBenchmarkIT.auto  medium  avgt   10  0.320 ± 0.011   s/op
LauncherBenchmarkIT.auto   small  avgt   10  0.270 ± 0.007   s/op
LauncherBenchmarkIT.auto   large  avgt   10  1.878 ± 0.029   s/op

@wilkinsona
Copy link
Member

We can buy ourselves another ~170000 bytes by combining the start and end arrays into a single int[][] of ranges where int[i][0] is the start and int[i][1] is the end. However, it appears to make things slower (in the JITed case at least):

[GC (Allocation Failure)  132448K->3992K(479232K), 0.0031696 secs]
Bound io.spring.initializr.metadata.InitializrProperties@2dd29a59 in 490.183025ms, allocating 12112824 bytes
Bound io.spring.initializr.metadata.InitializrProperties@784c3487 in 517.195886ms, allocating 12112824 bytes
Bound io.spring.initializr.metadata.InitializrProperties@53142455 in 486.424706ms, allocating 12112824 bytes
Bound io.spring.initializr.metadata.InitializrProperties@40dff0b7 in 489.886207ms, allocating 12112824 bytes
Bound io.spring.initializr.metadata.InitializrProperties@7966baa7 in 493.832087ms, allocating 12112824 bytes
Bound io.spring.initializr.metadata.InitializrProperties@60975100 in 492.446865ms, allocating 12112824 bytes
Bound io.spring.initializr.metadata.InitializrProperties@1253e7cb in 519.923877ms, allocating 12112824 bytes
Bound io.spring.initializr.metadata.InitializrProperties@2d36e77e in 511.246312ms, allocating 12112824 bytes
Bound io.spring.initializr.metadata.InitializrProperties@61c9c3fd in 506.555577ms, allocating 12112824 bytes
Bound io.spring.initializr.metadata.InitializrProperties@3b0c9195 in 508.758904ms, allocating 12112824 bytes
Bound io.spring.initializr.metadata.InitializrProperties@366c4480 in 496.369436ms, allocating 12112824 bytes
[GC (Allocation Failure)  129432K->4065K(473088K), 0.0034438 secs]

@wilkinsona
Copy link
Member

I've started collecting some commits on this branch that improve things a little and, I believe, are not optimising specifically for Initializr's use of YAML.

@wilkinsona
Copy link
Member

Some new numbers based on the current head of this branch:

[GC (Allocation Failure)  126760K->3936K(470528K), 0.0008032 secs]
Bound io.spring.initializr.metadata.InitializrProperties@c35172e in 454.444681ms, allocating 11566488 bytes
Bound io.spring.initializr.metadata.InitializrProperties@c2db68f in 460.872833ms, allocating 11566488 bytes
Bound io.spring.initializr.metadata.InitializrProperties@3cc41abc in 459.366374ms, allocating 11566488 bytes
Bound io.spring.initializr.metadata.InitializrProperties@4566d049 in 463.971321ms, allocating 11566488 bytes
Bound io.spring.initializr.metadata.InitializrProperties@61ce23ac in 474.967192ms, allocating 11566488 bytes
Bound io.spring.initializr.metadata.InitializrProperties@3668d4 in 468.38851ms, allocating 11566488 bytes
Bound io.spring.initializr.metadata.InitializrProperties@1c3b9394 in 506.037068ms, allocating 11566488 bytes
Bound io.spring.initializr.metadata.InitializrProperties@6f2cfcc2 in 472.942437ms, allocating 11566488 bytes
Bound io.spring.initializr.metadata.InitializrProperties@7f6f61c8 in 461.681775ms, allocating 11566488 bytes
Bound io.spring.initializr.metadata.InitializrProperties@4c2cc639 in 454.967065ms, allocating 11566488 bytes
Bound io.spring.initializr.metadata.InitializrProperties@ccb4b1b in 452.66392ms, allocating 11564440 bytes
[GC (Allocation Failure)  124256K->3944K(475136K), 0.0007865 secs]

@wilkinsona
Copy link
Member

And some numbers from the Launcher Benchmark:

Before:

Benchmark                 (prof)  Mode  Cnt  Score   Error  Units
LauncherBenchmarkIT.auto  medium  avgt   10  0.546 ± 0.060   s/op
LauncherBenchmarkIT.auto   small  avgt   10  0.441 ± 0.046   s/op
LauncherBenchmarkIT.auto   large  avgt   10  1.655 ± 0.187   s/op

After:

Benchmark                 (prof)  Mode  Cnt  Score   Error  Units
LauncherBenchmarkIT.auto  medium  avgt   10  0.532 ± 0.036   s/op
LauncherBenchmarkIT.auto   small  avgt   10  0.436 ± 0.041   s/op
LauncherBenchmarkIT.auto   large  avgt   10  1.631 ± 0.145   s/op

There's no discernible difference. Given that the benchmark measures a single cold-start binding, the changes are focussed on reducing allocations and, therefore, GC pressure, and that the properties can be bound 10 times before the GC runs, this isn't entirely surprising.

The changes provided thus far don't appear to do any harm, and will hopefully provide more benefit with small heap sizes, but if we want to make this faster in the cold-start case, I think we'll need to look for changes that aren't specifically focussed on reducing GC pressure as I don't think GC is a major contributing factor to the performance.

@dsyer dsyer changed the title GC pressure from ConfigurationPropertyName Slow binding of @ConfigurationProperties with large object graph Jan 24, 2019
@wilkinsona
Copy link
Member

Here's some numbers gathered with a new harness comparing the current head of master with the current head of this branch:

Large YAML file

Baseline New
2.485 1.971
2.013 2.052
2.343 2.005
2.512 2.170
2.395 2.059
2.366 2.128
2.180 2.203
2.168 2.396
2.152 1.963
2.242 1.977
Mean 2.286 2.092
Range 0.499 0.433

Small YAML file

Baseline New
0.736 0.739
0.738 0.729
0.731 0.732
0.738 0.721
0.749 0.744
0.738 0.730
0.753 0.732
0.734 0.743
0.735 0.739
0.753 0.750
Mean 0.741 0.736
Range 0.022 0.029

@wilkinsona
Copy link
Member

wilkinsona commented Jan 25, 2019

And here's a comparison of the changes proposed in #15782 (baseline) and the changes proposed in #15782 combined with those proposed here (new) for the large YAML file:

Baseline New
1.922 1.479
1.734 1.340
1.549 1.343
1.683 1.281
1.684 1.301
1.485 1.522
1.624 1.337
1.357 1.317
1.510 1.245
1.383 1.330
Mean 1.593 1.350
Range 0.565 0.277

@dreis2211
Copy link
Contributor

Pretty impressive results when we combine your and my work compared to the initial timings, @wilkinsona 👍

@wilkinsona wilkinsona self-assigned this Jan 28, 2019
wilkinsona added a commit that referenced this issue Jan 28, 2019
Previously, ElementsParser would expand its internal storage when the
size of the storage was <= the end index of the element being parsed,
irrespective of how many elements had been stored. This led to
expansion of the storage, even for a source that contains a single
element, if the end of the element was at an index greater than the
size of the storage.

This commit updates ElementsParser to resize its storage when the size
(the number of elements that have been stored) is equal to the size of
the storage.

See gh-15760
wilkinsona added a commit that referenced this issue Jan 28, 2019
Previously, the ElementsParser would be created using its default
capacity of 6 even when parsing a String that is expected to
produce a single element.

This commit updates ConfigurationPropertyName to create an
ElementsParser with a capacity of 1 when parsing a String that should
contain only a single element.

See gh-15760
wilkinsona added a commit that referenced this issue Jan 28, 2019
Previously, when ConfigurationPropertyName was building the String
returned from toString() it would use a StringBuilder with the
default initial capacity of 16. For properties with several
elements this was likely to be too small resulting in the builder's
buffer being resized.

This commit sizes the StringBuilder as a multiple of the number of
elements in the name, attempting to strike a balance between
allocating a StringBuilder with an initial capacity that's too
large and wastes memory and an initial capacity that's too small
and requires resizing.

See gh-15760
@wilkinsona wilkinsona removed this from the 2.2.x milestone Jan 28, 2019
@wilkinsona wilkinsona added this to the 2.2.0.M1 milestone Jan 28, 2019
@wilkinsona
Copy link
Member

Yeah, I'm really pleased with the improvements. Thanks for your help here, @dreis2211. It's greatly appreciated.

A final set of numbers comparing 2.1.2.RELEASE and 2.2.0 snapshots with all the changes in place (
9e43ee1):

Baseline New
2.408 1.312
2.295 1.323
2.063 1.584
2.427 1.555
2.292 1.379
2.102 1.305
2.389 1.448
2.401 1.296
2.171 1.377
2.400 1.276
Mean 2.295 1.386
Range 0.364 0.308

That's a 39.6% reduction in the mean startup time of an app that just binds the large YAML file to InitializrProperties.

@wilkinsona wilkinsona changed the title Slow binding of @ConfigurationProperties with large object graph Speed up binding of @ConfigurationProperties with a large object graph Mar 8, 2019
@wilkinsona wilkinsona added type: enhancement A general enhancement and removed type: task A general task labels Mar 8, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
theme: performance Issues related to general performance type: enhancement A general enhancement
Projects
None yet
Development

No branches or pull requests

5 participants