Performance Degradation with 1.5.3

[tmohme]

Testing Problem

I'm experiencing a significant performance degradation with 1.5.3 (compared to 1.5.2).
While the overall runtime of the complete test suite roughly doubled (662 tests, ~6'40" => ~13'00"), some tests are hit exceptionally hard: I've identified two classes that went from 6s resp. 8s to 1'40"

A CPU flame-graph of the 6s test class ("TRFP"):

This is the corresponding flame-graph of the same test class running 1'54" with 1.5.3:

Hope this helps to identify the root cause or suggest a workaround.
Please let me know if you need further/other measurements.

[jlink]

Thanks for the catch.

Do your properties or provider methods use Arbitrary.sample() or sampleStream() directly by any chance?

[tmohme]

No, I don't use Arbitrary.sample() or sampleStream() here.
I use Arbitrary.sample() only in one test class were I'm unable to let jqwik control the test execution.

But the Arbitrary involved in both extreme cases is quite complicated: I generate variable long lists of which the entries do have to fulfill some consistency rules. To achieve this, I use an integer arbitrary (for the list length) and the apply flatMap to it (for the entries).

[jlink]

If you find the time could you check if 1.2.4-SNAPSHOT still has the problem.? Just to rule out the obvious.

[tmohme]

• Release 1.5.3: ~1'40"
• Commit 7cbc7fe, main: 1'15"..1'45"
• Commit dc758c7, issue-206-performance-degradation: ~1'45"

I wouldn't overemphasize the variance or further degression, because I didn't invest much time in getting the numbers, just 2..3 runs.

[jlink]

I wouldn't overemphasize the variance or further degression, because I didn't invest much time in getting the numbers, just 2..3 runs.

This rules out my initial assumption. I'll have to dig deeper.

[tmohme]

I had a look at GC with JFR: nothing suspicious there.

[tmohme]

I guess I've found a "smoking gun": I executed just one of the affected tests (to keep things simple) and found that net.jqwik.engine.execution.lifecycle.StoreRepository#get got called 2.054.622 times, effectively doing a linear search over up to 603 elements in the stores set each time.

[tmohme]

Additionally (and without understanding the context), 2M calls to this method look suspicious when the property gets executed "only" 1.000 times.

[tmohme]

By simple local optimizations of the stream processing, I was able to reduce the test execution time down to 1'00"..1'20", which is not at all ground-breaking, but reinforces my suspicion that this method is part of the problem.

[jlink]

Thanks for diving deeper. I hope I can find some time during the weekend.

[tmohme]

Don't worry. We can get along quite good with 1.5.2 for now.

[tmohme]

Is ScopedStore.identifier stable, i.e. can it be used as a key in a HashMap?

[jlink]

At leasst it should be stable.

[jlink]

I think I found the guilty commit: f6a80f4

But that can only be true if the properties in which you're observing the phenomenon uses String generation in some way.

[jlink]

I deployed my assumed fix to "1.5.4-SNAPSHOT". You may want to try if it fixes your problem.

[tmohme]

I tried my pathological test class with your latest 1.5.4-SNAPSHOT (commit 9998697) and came out with the following run-times:

• 1'19"
• 1'22"
• 1'06"
• 0'54"
• 1'40"

So, we probably have some improvement but also a high variance.
I'll try to come up with a slimmed-down version of the arbitrary that probably is essential to reproduce the prolonged run-times (it produces lots of Strings an numbers).

[jlink]

Without the additional improvement from your PR I'd expect some slow down b/c string generation will inject duplicate chars on purpose. The number of calls to StoreRepository#get should have gone down by an order of magnitude though.

[tmohme]

This is a small Kotlin reproducer for the effect: Issue206Reproducer.zip

Measured run-times are

• 1.5.2: 1.5s ~ 2.1s
• 1.5.3: 15s ~ 22s

The generation logic is essentially the same as in my "real" Arbitrary. I just left out business constraints, types, etc.
Maybe I'm simply doing stupid things when trying to generate the data structure . . .

I'll try testing the combination of your and mine improvement later.

[jlink]

So, we probably have some improvement but also a high variance.

If you want to minimize variance you can fix the seed. But you probably know that.

[jlink]

@tmohme I used your reproducer to decide that generated strings will no longer explicitly duplicate characters by default.

There's still s.t. a ~30% performance hit that I currently cannot pin down. Will further investigate.

[jlink]

I can trace the 30% performance hit to a change in ContainerGenerator that I'd like to keep. Can you live with the performance as it is in 1.3.4-SNAPSHOT?

ContainerGenerator has most probably room for performance optimization but it's not on the top of my list, unless someone pushes it there.

[tmohme]

I tested commit 1.5.4-SNAPSHOT (1a8d05e) with good results.
My most impacted test class is back down to 6s (from 1'40" with 1.5.3).
The run-time of whole test suite also is in the same ball-park as before, with 1.5.2.
For me the this is OK 👍

Btw.: The number of calls to StoreRepository#get is still pretty high. I measured values from 800k to 1.5m for the test that ended up with 2.0m mentioned above.

[jlink]

Btw.: The number of calls to StoreRepository#get is still pretty high. I measured values from 800k to 1.5m for the test that ended up with 2.0m

is it higher with 1.5.4-S than with 1.5.2? If so, that will be one more riddle to solve before closing this issue

[tmohme]

A comparison for one test with fixed seed:

version	calls	store entries
1.5.2	827.038	2
1.5.3	2.602.194	589
1.5.4-SN (1a8d05e)	866.459	2

In my interpretation the most important contributors to improvement of the run-time (1.5.4-SN vs. 1.5.3) are

1. the reduced number of store entries
2. the reduced number of calls to StoreRepository#get

With the current 1.5.4-SN, my proposed change to the data-structure is probably even contra-productive as a linear search over only two elements should be faster than a lookup in a HashMap (let alone having to maintain more complicated code).

[jlink]

Still wondering where the 40+ thousand calls come from. But that's peanuts ;-/

With the current 1.5.4-SN, my proposed change to the data-structure is probably even contra-productive as a linear search over only two elements should be faster than a lookup in a HashMap (let alone having to maintain more complicated code).

I guess it doesn't matter for two entries anyway. And the number of entries can grow rapidly as soon as stuff like Arbitrary.injectDuplicates() is being used and combined with flat mapping or builders. So I tend to leave it as is, ie with your suggestion integrated.

[jlink]

Closing as fixed. Reopen if new performance issues show up.