Weird performance problems querying with projections (too extensive queries)

[wikistorichris]

SDN is somehow changing behaviour during runtime. I've been struggeling with performance problems for quite some time, but thought it was a bad design of my multilevel projections, causing SDN to load too much of the graph. That was partly true, but now I experience a really weird problem:

After starting my application queries work just fine, I get a result within a fraction of a second. I can do many read-queries on different nodes without the problem appearing.
When I have done the first query to change data (change field value, add relationship) using template.saveAs(dto, projectionclass), the queries suddenly become very slow. The data change can be on nodes and relationships completely unrelated to the nodes being queried for reading.

A restart of the application fixes the problem - until I do the first write operation on the database again. It appears only to happen, if it is a write-change on a node having the same label as the one read-queried, and only when there is a certain amount of nesting.
While I write this I found out: the problem also seems to disappear after a couple of minutes without doing queries. Some caching problem?

I have set up cypher query logging and there it shows, that the querying behaviour is different. First the queries are "normal" querying the root node and then going through the relations as set up by the projections, e. g.:

2023-06-28 17:35:05.635 DEBUG 94748 --- [io-8080-exec-14] org.springframework.data.neo4j.cypher    : Executing:
MATCH (event:`Event`) WHERE id(event) = $id WITH collect(id(event)) AS __sn__ RETURN __sn__
2023-06-28 17:35:05.640 DEBUG 94748 --- [io-8080-exec-14] org.springframework.data.neo4j.cypher    : Executing:
MATCH (event:`Event`) WHERE id(event) = $id OPTIONAL MATCH (event)-[__sr__:`HAPPENED_AT`]->(__srn__:`Location`) WITH collect(id(event)) AS __sn__, collect(id(__srn__)) AS __srn__, collect(id(__sr__)) AS __sr__ RETURN __sn__, __srn__, __sr__
2023-06-28 17:35:05.645 DEBUG 94748 --- [io-8080-exec-14] org.springframework.data.neo4j.cypher    : Executing:
MATCH (event:`Event`) WHERE id(event) = $id OPTIONAL MATCH (event)-[__sr__:`CONFLICTS_WITH`]->(__srn__:`Event`) WITH collect(id(event)) AS __sn__, collect(id(__srn__)) AS __srn__, collect(id(__sr__)) AS __sr__ RETURN __sn__, __srn__, __sr__
2023-06-28 17:35:05.649 DEBUG 94748 --- [io-8080-exec-14] org.springframework.data.neo4j.cypher    : Executing:
MATCH (event:`Event`) WHERE id(event) = $id OPTIONAL MATCH (event)-[__sr__:`INVOLVES`]->(__srn__:`Person`) WITH collect(id(event)) AS __sn__, collect(id(__srn__)) AS __srn__, collect(id(__sr__)) AS __sr__ RETURN __sn__, __srn__, __sr__
2023-06-28 17:35:05.655 DEBUG 94748 --- [io-8080-exec-14] org.springframework.data.neo4j.cypher    : Executing:
MATCH (person:`Person`) WHERE id(person) IN $__ids__ OPTIONAL MATCH (person)-[__sr__:`TAGGED_WITH`]->(__srn__:`Tag`) WITH collect(id(person)) AS __sn__, collect(id(__srn__)) AS __srn__, collect(id(__sr__)) AS __sr__ RETURN __sn__, __srn__, __sr__
2023-06-28 17:35:05.660 DEBUG 94748 --- [io-8080-exec-14] org.springframework.data.neo4j.cypher    : Executing:
MATCH (event:`Event`) WHERE id(event) = $id OPTIONAL MATCH (event)-[__sr__:`TRANSLATED`]->(__srn__:`EventTranslation`) WITH collect(id(event)) AS __sn__, collect(id(__srn__)) AS __srn__, collect(id(__sr__)) AS __sr__ RETURN __sn__, __srn__, __sr__
2023-06-28 17:35:05.665 DEBUG 94748 --- [io-8080-exec-14] org.springframework.data.neo4j.cypher    : Executing:
MATCH (event:`Event`) WHERE id(event) = $id OPTIONAL MATCH (event)-[__sr__:`TAGGED_WITH`]->(__srn__:`Tag`) WITH collect(id(event)) AS __sn__, collect(id(__srn__)) AS __srn__, collect(id(__sr__)) AS __sr__ RETURN __sn__, __srn__, __sr__
2023-06-28 17:35:05.671 DEBUG 94748 --- [io-8080-exec-14] org.springframework.data.neo4j.cypher    : Executing:
MATCH (event:`Event`) WHERE id(event) = $id OPTIONAL MATCH (event)-[__sr__:`IN_SOURCE`]->(__srn__:`Source`) WITH collect(id(event)) AS __sn__, collect(id(__srn__)) AS __srn__, collect(id(__sr__)) AS __sr__ RETURN __sn__, __srn__, __sr__
2023-06-28 17:35:05.675 DEBUG 94748 --- [io-8080-exec-14] org.springframework.data.neo4j.cypher    : Executing:
MATCH (source:`Source`) WHERE id(source) IN $__ids__ OPTIONAL MATCH (source)-[__sr__:`IS_PUBLICATION_TYPE`]->(__srn__:`PublicationType`) WITH collect(id(source)) AS __sn__, collect(id(__srn__)) AS __srn__, collect(id(__sr__)) AS __sr__ RETURN __sn__, __srn__, __sr__
2023-06-28 17:35:05.681 DEBUG 94748 --- [io-8080-exec-14] org.springframework.data.neo4j.cypher    : Executing:
MATCH (source:`Source`) WHERE id(source) IN $__ids__ OPTIONAL MATCH (source)-[__sr__:`TAGGED_WITH`]->(__srn__:`Tag`) WITH collect(id(source)) AS __sn__, collect(id(__srn__)) AS __srn__, collect(id(__sr__)) AS __sr__ RETURN __sn__, __srn__, __sr__
2023-06-28 17:35:05.685 DEBUG 94748 --- [io-8080-exec-14] org.springframework.data.neo4j.cypher    : Executing:
MATCH (source:`Source`) WHERE id(source) IN $__ids__ OPTIONAL MATCH (source)-[__sr__:`AUTHOR`]->(__srn__:`Person`) WITH collect(id(source)) AS __sn__, collect(id(__srn__)) AS __srn__, collect(id(__sr__)) AS __sr__ RETURN __sn__, __srn__, __sr__
2023-06-28 17:35:05.690 DEBUG 94748 --- [io-8080-exec-14] org.springframework.data.neo4j.cypher    : Executing:
MATCH (source:`Source`) WHERE id(source) IN $__ids__ OPTIONAL MATCH (source)-[__sr__:`HAS_SECTION`]->(__srn__:`SourceSection`) WITH collect(id(source)) AS __sn__, collect(id(__srn__)) AS __srn__, collect(id(__sr__)) AS __sr__ RETURN __sn__, __srn__, __sr__
2023-06-28 17:35:05.694 DEBUG 94748 --- [io-8080-exec-14] org.springframework.data.neo4j.cypher    : Executing:
MATCH (event:`Event`) WHERE id(event) = $id OPTIONAL MATCH (event)-[__sr__:`POSSIBLE_DUPE`]->(__srn__:`Event`) WITH collect(id(event)) AS __sn__, collect(id(__srn__)) AS __srn__, collect(id(__sr__)) AS __sr__ RETURN __sn__, __srn__, __sr__
2023-06-28 17:35:05.697 DEBUG 94748 --- [io-8080-exec-14] org.springframework.data.neo4j.cypher    : Executing:
MATCH (rootNodeIds) WHERE id(rootNodeIds) IN $rootNodeIds WITH collect(rootNodeIds) AS n OPTIONAL MATCH ()-[relationshipIds]-() WHERE id(relationshipIds) IN $relationshipIds WITH n, collect(DISTINCT relationshipIds) AS __sr__ OPTIONAL MATCH (relatedNodeIds) WHERE id(relatedNodeIds) IN $relatedNodeIds WITH n, __sr__ AS __sr__, collect(DISTINCT relatedNodeIds) AS __srn__ UNWIND n AS rootNodeIds WITH rootNodeIds AS event, __sr__, __srn__ RETURN event AS __sn__, __sr__, __srn__

But after the write operations the querying becomes much more extensive. It appears as if to load all the related nodes recursively. I'm not putting the log in here, because it amounts to over 650 lines of output.

I have tried it with different versions of spring-boot-starter-data-neo4j, starting from
2.7.13
up to
3.1.1

neo4j v4 on Aura
neo4j v4.4 locally

[meistermeier]

Thanks for reaching out.
The only caching that we have in place is the caching of classes to (metadata containing) entities. I would rule this out for now.
The provided log output at least shows that you are working with a cyclic domain model. Coming to the huge amount of queries might be possible if the write query adds a "missing" relationship, your domain model defines but was never filled before.
I haven't found any place in the code that might describe your observation regarding

seems to disappear after a couple of minutes without doing queries

Would it be possible for you to create a reproducer? You know best about the relationship and mapping than I can just guess from the logs.

A note on projections: DTO projections don't support multi-level projection https://docs.spring.io/spring-data/neo4j/docs/current/reference/html/#projections.dtos

[wikistorichris]

It's hard to create a reproducer - especially due to the amount of data probably needed to reproduce this. But concerning the time I've already spent refactoring around this issue, I probably should give it a try.
As a first attempt, I made a short video (in german) demonstrating the issue, showing some of the interface projections as well. Unfortunately the code is hard to read, due to video compression - but maybe this gives you an idea where the problem could be.
https://www.youtube.com/watch?v=IIM14v4YiHY

As said in the video: I use multilevel projections only for loading. To save a node and its relations, I use ModelMapper to create a DTO and then save it. But I expect only changes in the root node and its relations to be saved. Could that contribute to the problem? I need DTOs in some cases (but I use them everywhere due to my use of generics) - if that causes the problem, I could refactor to use wrappers around the proxy-objects or find some other way to eliminate DTOs (and the ModelMapper, which causes a lot of hustle and boilerplate code).

I tried to reproduce the problem going away by itself when not using the application. I could not reproduce it using an interval of 30 minutes. I'll try again in about 3 hours, but probably it was my error.

[wikistorichris]

So 4 hours later without using the application the problem still exists. So I was wrong saying that it goes away over time by itself.

[meistermeier]

Thanks for the video. This gives me a lot of context.
Unfortunately the output did not scroll, so I cannot see the query (and parameters) for the save.
Also the quality does not help me to see the problematic cascade of queries.
My assumption is, comparing it with the expected output, we might uncover the "path" where SDN thinks might be a good idea to follow because there is somehow data now.

I have no experience with ModelMapper and let's just agree that the documentation is very short.
As you have already pointed out in the video, it might be related to interface -> DTO conversion and you suddenly get more into the (ModelMapper created) DTO filter for the save.
In general the rule in SDN is that at the moment you have a second level or SDN cannot map a field directly to a property of the entity class behind the (DTO) projection, it will treat it is the real entity and try to save/update every reachable path.
TBH, it's still a mystery to me why a simple change of the title in a (at least visible) unrelated node might influence the other node.

Maybe unrelated but there is also a PersonListInterface included. I've seen that there is no Person on the simple event, but just wanted to point out that there might also be some more nesting or even cyclic mapping.

[spring-projects-issues]

If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.

[wikistorichris]

An update on the issue: I have stripped the application down to create a reproducer. I got rid of everything including the DTOs and the problem is gone. I'm loading the events to proxy objects, then I change the title attribute of one of the objects, create domain objects via constructors (no more ModelMapper) and save it.
eventService.saveAs(new Event(simpleEvent), EventShallowInterface.class); which ultimately calls template.saveAs(domainObject, projectionClass);
Having done this, I think I could get rid of DTOs in my main application altogether and just use interface projections and domain objects. This is probably the way to go, since the problem seems to be related to the way I create or save the DTOs.

I ran into problems though writing a test to reproduce the problem. I exported parts of my graph like this

CALL apoc.export.cypher.query(
"MATCH(root:Event)-[]-(leaf)
 MATCH(leaf)-[]-(subleaf)
    WHERE ID(root) = 9106
 RETURN root, leaf, subleaf");

But I did not find a good way to run the Cypher export when setting up the database with the test harness. I would appreciate a tip on how to import complex fixtures when using the test harness. I could not get the APOC library to load when setting up the test database, nor find an easy way to execute the statements generated by the call above. So at the moment I'm running tests against a neo4j docker container running on my machine with a copy of my production DB.

[jrsperry]

I'd just like to add that I too am experiencing similar issues, although I haven't been able to pin down when it happens, other than that it doesn't happen when I have additional driver logging set up.

With the following env vars set
logging.level.org.neo4j.driver.GraphDatabase: debug
logging.level.org.neo4j.driver.Driver: debug

I get responses to many complex reads VERY quickly, within 0.5 seconds. Without it, I believe I've getting the same recursive stuff as mentioned above, which ultimately results in a There is not enough memory to perform the current task. Please try increasing 'dbms.memory.heap.max_size' error being thrown (I'm loading 500 complex objects at time to get this error). What's bizarre is just how fast it is when those log levels are set. I highly doubt those log levels have to deal with anything, but I've done like 10 tests now alternating and that's the behavior I'm seeing. I had a slightly different project which was also very fast, and those logs levels were not set. In this particular project it’s just what pushed it to the edge. I'd love to know what I actually need to do to prevent these horrible queries.

I just added the logging around cypher queries and have the queries for when the SDN freaks out and causes OOM. That being said the slow queries look similar to those posted by OP. Unfortunately, when I enable the cypher logging and the previously mentioned logging levels, I only get the slow queries. So I don't actually know what's it's generating when it runs fast. I can switch from the community version to a local developer enterprise edition to find out what queries are actually being run.

I'm using spring boot 3.1.2 and spring data neo4j 7.1.2 with neo4j 4.4.20.