Major performance issue in case of many new entities

[patric-r]

Eclipselink has a major performance issue in case of many new (persisted) entities (e.g. >10000) within one entitymanager transaction/UnitOfWork .

I did a detailed investigation and 95% of the time in my application is spent within org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.getObjectFromNewObjects(Class, Object)

When looking into this method, you can see that all new entities are gone through a sequential search and for each entry (new entity), a costly PK extraction is taken.

Instead, a proper hash-based caching mechanism should be implemented, looking up the object by class and pk in constant time.

Problematic stacktrace:

org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.getObjectFromNewObjects(Class, Object) UnitOfWorkImpl.java:2536
org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.checkCacheForObject(AbstractRecord, AbstractSession) ExpressionQueryMechanism.java:962
org.eclipse.persistence.queries.ReadObjectQuery.checkEarlyReturnLocal(AbstractSession, AbstractRecord) ReadObjectQuery.java:262
org.eclipse.persistence.queries.ObjectLevelReadQuery.checkEarlyReturn(AbstractSession, AbstractRecord) ObjectLevelReadQuery.java:923
org.eclipse.persistence.queries.DatabaseQuery.execute(AbstractSession, AbstractRecord) DatabaseQuery.java:848
org.eclipse.persistence.queries.ObjectLevelReadQuery.execute(AbstractSession, AbstractRecord) ObjectLevelReadQuery.java:1191
org.eclipse.persistence.queries.ReadObjectQuery.execute(AbstractSession, AbstractRecord) ReadObjectQuery.java:447
org.eclipse.persistence.queries.ObjectLevelReadQuery.executeInUnitOfWork(UnitOfWorkImpl, AbstractRecord) ObjectLevelReadQuery.java:1279
org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.internalExecuteQuery(DatabaseQuery, AbstractRecord) UnitOfWorkImpl.java:2983
org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(DatabaseQuery, AbstractRecord, int) AbstractSession.java:1898
org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(DatabaseQuery, AbstractRecord) AbstractSession.java:1880
org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(DatabaseQuery) AbstractSession.java:1830
[...]

[patric-r]

~~Usingthe hint eclipselink.cache-usage=DoNotCheckCache on the operation in question works around this problem (and confirms the bug)~~.

~~With this, performance is back to normal (20x times higher throughput)~~

EDIT: Workaround is broken. See separate comment.

It's a scary bug which needs to get fixed.

[patric-r]

I just realized the workaround proposed above doesn't work, as it causes em.find() to NOT find a previously persisted entity (which has not been flushed to the database yet). :(

@lukasj Any ideas?

[edbratt]

Is this a new problem? What version are you using now?

[patric-r]

@edbratt I'm currently using version 2.7.7.

However, when looking at the source and its history, it looks this behavior is very old, most probably originating from the early Toplink days:

https://github.com/eclipse-ee4j/eclipselink/blame/master/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/sessions/UnitOfWorkImpl.java#L2536

[ymajoros]

What do you mean by 'a costly PK extraction is taken'? Are you sure the problem isn't in the way your @Id is setup in your entity (is that maybe costly for some reason?).

[patric-r]

@ymajoros objectBuilder.extractPrimaryKeyFromObject() is not a free operation, it involves reflection.

But: In the first place, forget about PK extraction for a moment here. The main issue is the linear search (for loop in this method). IMHO, we need a hash-based lookup here with a composite hash key of entity class and PK.

[ymajoros]

Sure, that can all be optimized, but even with 100K objects, the current implementation should still be a matter of nanoseconds.

I suspect an additional problem in your entities that makes the performance of PK extraction on your specific entity model an order of magnitude worse than what it should be.

[patric-r]

It's not, it's a matter of seconds or even minutes :) Our field-annotated @Id is a plain Long value.

[ymajoros]

How many queries are involved that need to go through that search? Reflection itself isn't that costly (lookup of a field by name is, but that doesn't seem to be the problem here). Extracting the PK from objects, even 10K times, even with that inefficient search, shouldn't even be noticeable... unless it's done a lot of times of course. Not saying it shouldn't be improved, but I'm just trying to understand where the perf hit really comes from.

[patric-r]

You can easily reproduce this by yourself. Ideally you have a persistence unit with an Entity, e.g. MyTestEntity which has a Long @Id-annotated pk field

 @Test
 public void eclipseLinkBug1596()
 {
   for (int i = 0; i < 100_000; i++)
   {
     MyTestEntity entity = new MyTestEntity();
     em.persist(entity);

	  //we need to find something which isn't in the UnitOfWork's IdentityMap to hit the problematic method
	  //easiest way to do this is to find an entity which does neither exist in the UnitOfWork nor in the database,
	  //however other ways (e.g. issuing a jpql query with disabled query cache) are possible as well

	  //this will cost ~56% of the time (if you increase iteration count, this percentage will be even higher),
	  //~95% for that ~56% are spent within  
	  //org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.getObjectFromNewObjects(Class, Object)
     MyTestEntity obj = em.find(MyTestEntity.class, 99999999999L);  
   }  
 }

JFR profiling results:

[patric-r]

wall-time call tree of the same test (measured with another sampling profiler, YourKit), showing 81% time consumption of the method:

[lukasj]

Is weaving leading to simple get (1 instruction call) on or off?

[patric-r]

Yes, the entity has been statically weaved.

[patric-r]

@lukasj @edbratt do you need further information? Any chance to get this fixed?

[rfelcman]

Hello,

I created test case to simulate this issue, but I have following additional questions:

Is it entity really weaved? From the provided pictures it looks, that no. In case of weaved entity there should be something like ......MyTestEntity._persistence_get () See my attached pictures:

visualVM_NO_weaving.jpg

visualVM_weaving.jpg

From the provided code is unclear how entity Id value initiated. Could You please provide details about this?

visualVM_NO_weaving_NO_id.jpg

Next attached file contains my test case. Feel free to check it modify and upload back. It's designed against Apache Derby database (In-Memory mode) which net listener should be started by mvn derby:run in the project directory.

jpa-bug-1596-MajorPerformanceIssueInCaseOfManyNewEntities.tar.gz

[patric-r]

Hi @rfelcman,

Many thanks for your investigation. I am currently on leave and therefore can't provide much details before return but I can definitely say that my entities are statically weaved in the environments in which I initially discovered this issue.

What I currently can't 100% confirm is if the profiler screenshots (an isolated unit test case with a test persistence unit) above really uses a weaved pu (but I'm quite confident).

But at the end, the problem is neither the weaving nor the PK extraction. It's the fact the eclipselink does a linear search while it should use a hash-based data structure in order to determine the existence of a known new entitiy in constant time. Your own profiling screenshot "with weaving" shows 70% of the time is consumed by getObjectFromNewObjects() while in the "no weaving"-scenario, it consumes 75% of the time - so the impact of weaving is neglectable here.

Regarding your unit test case: Can you hint me how to set up a working eclipselink development environment to run your (and the other existing test cases)? I tried but I failed - one issue was that eclipselink strangely has dependencies to Eclipse PDE and there where some conflicts which I wasn't able to resolve quickly. Thanks!

[rfelcman]

About: Regarding your unit test case: Can you hint me how to set up a working eclipselink development environment to run your (and the other existing test cases)? I tried but I failed - one issue was that eclipselink strangely has dependencies to Eclipse PDE and there where some conflicts which I wasn't able to resolve quickly. Thanks!

This is pure Maven project. Maven will handle all dependencies. As I mentioned above mvn derby:run in project directory will start Derby DB net listener. My provided test is targeted to this DB by persistence.xml.

[patric-r]

Is it possible to import to those maven project(s) into eclipse? I was never able to get it to work. Just tried it for another time: checked out master branch, in eclipse, selected import existing maven projects and after import, I choose Update Maven project on the parent project.

This results in many erros, e.g.:

[rfelcman]

About Eclipse IDE. Sorry in this case I can't help You as I don't use it. We are using IntelliJ IDEA or pure command line. Sometimes we used NetBeans.

[patric-r]

Okay, no worries. I will try setting it up with IDEA after my return. But until then, I can't review your testcase.

In any case from what I can see in your screenshots, it looks like you have reproduced the issue. If you can provide a fix, I am happy to test it.

[ymajoros]

Sure, that can all be optimized, but even with 100K objects, the current implementation should still be a matter of nanoseconds.

I suspect an additional problem in your entities that makes the performance of PK extraction on your specific entity model an order of magnitude worse than what it should be.

Le mer. 24 août 2022 à 11:48, patric-r @.***> a écrit :

@ymajoros https://github.com/ymajoros objectBuilder.extractPrimaryKeyFromObject() is not a free operation, it involves reflection.

But: In the first place, forget about PK extraction for a moment here. The main issue is the linear search (for loop in this method). IMHO, we need a hash-based lookup here with a composite hash key of entity class and PK.

— Reply to this email directly, view it on GitHub https://github.com/eclipse-ee4j/eclipselink/issues/1596#issuecomment-1225488760, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAWBMUCGYVODCLRPJSR7FALV2XVWRANCNFSM54ITQM6Q . You are receiving this because you were mentioned.Message ID: @.***>

-- Yannick Majoros Valuya sprl

[patric-r]

@ymajoros when you look at my profiling results, you can see that PK extraction itself is not the culprit here. And even if this would be the cause, how should I fix it? I'm using the simplest possible form of a PK, a field-based Long field.

In my testcase we have 100k new entities but we're calling each iteration/PK extraction roughly 100k*100k = ~10M times. This means we have O(n²) complexity and I think we can do better here.

And btw, according to @rfelcman comment, it seems that he has reproduced the issue with his testcase.

[patric-r]

Any updates?