9 second query became 5 minute query during neo4j upgrade

[satish]

Hi,

We upgraded our neo4j community edition 3.4.7 to 3.5.14. Do we need to be aware of any performance differences here?

uname for 3.4.7 - Linux ip-10-1-3-221 4.4.0-186-generic #216-Ubuntu SMP Wed Jul 1 05:34:05 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux -- r4.2xlarge -- "/etc/neo4j/neo4j.conf" [readonly] 341L, 14768C

uname for 3.5.14 - Linux ip-10-1-49-33 5.3.0-1032-aws #34~18.04.2-Ubuntu SMP Fri Jul 24 10:06:28 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux -- r5.2xlarge -- "/etc/neo4j/neo4j.conf" [readonly] 384L, 17235C

We tried to profile query on both versions, odd thing, the 2 neo4j indicate different profiling plans. Is that expected?

Java version is same on both instances: openjdk version "1.8.0_265"

OpenJDK Runtime Environment (build 1.8.0_265-8u265-b01-0ubuntu2~18.04-b01)

OpenJDK 64-Bit Server VM (build 25.265-b01, mixed mode)

Can you please help us, what else we can try?

thanks

[Cobra]

Hello @satish

Normally, there should be no difference.
Could you provide us both profile plans?

Regards,
Cobra

[satish]

Hello Cobra

Here is the plan for the older instance. (first 100 lines) please let us know if you want to see full file. thanks

5689 rows available after 8 ms, consumed after another 5957 ms

and newer instance:

+----------------------------------------------------------------------------------------------+
| Plan | Statement | Version | Planner | Runtime | Time | DbHits | Rows |
+----------------------------------------------------------------------------------------------+
| "PROFILE" | "READ_ONLY" | "CYPHER 3.5" | "COST" | "INTERPRETED" | 163223 | 165111372 | 5689 |
+----------------------------------------------------------------------------------------------+

+------------------------+----------------+----------+----------+-----------+-----------------------------------------------------+------------------+----------------------------------------------------------------------------------------------------------------------------+
| Operator | Estimated Rows | Rows | DB Hits | Cache H/M | Identifiers | Ordered by | Other |
+------------------------+----------------+----------+----------+-----------+-----------------------------------------------------+------------------+----------------------------------------------------------------------------------------------------------------------------+
| +ProduceResults | 29 | 5689 | 0 | 0/0 | t, ssid, Effect_size, Standard_error, dataset, r, d | dataset ASC | |
| | +----------------+----------+----------+-----------+-----------------------------------------------------+------------------+----------------------------------------------------------------------------------------------------------------------------+
| +Projection | 29 | 5689 | 17067 | 0/0 | t, ssid, Effect_size, Standard_error, dataset, r, d | dataset ASC | {dataset : cached[d.Study_name], ssid : t.StrainSelect_ID, Effect_size : r.Effect_size, Standard_error : r.Standard_error} |
| | +----------------+----------+----------+-----------+-----------------------------------------------------+------------------+----------------------------------------------------------------------------------------------------------------------------+
| +Filter | 29 | 5689 | 82556463 | 0/0 | cached[d.Study_name], d, r, t | d.Study_name ASC | not r.Methods_notes CONTAINS ` AUTOSTRING0` | | | +----------------+----------+----------+-----------+-----------------------------------------------------+------------------+----------------------------------------------------------------------------------------------------------------------------+ | +Expand(All) | 54614 | 82537763 | 82537776 | 0/0 | cached[d.Study_name], d, r, t | d.Study_name ASC | (d)-[r:]->(t) | | | +----------------+----------+----------+-----------+-----------------------------------------------------+------------------+----------------------------------------------------------------------------------------------------------------------------+ | +Filter | 0 | 13 | 32 | 0/0 | cached[d.Study_name], d | d.Study_name ASC | d.Biospecimen_type = AUTOSTRING2 |
| | +----------------+----------+----------+-----------+-----------------------------------------------------+------------------+----------------------------------------------------------------------------------------------------------------------------+
| +NodeIndexContainsScan | 0 | 32 | 34 | 0/0 | cached[d.Study_name], d | d.Study_name ASC | $ AUTOSTRING1; :Dataset(Study_name) |
+------------------------+----------------+----------+----------+-----------+-----------------------------------------------------+------------------+----------------------------------------------------------------------------------------------------------------------------+

5689 rows available after 267 ms, consumed after another 162956 ms

[andrew_bowman]

Full files of the PROFILEs of both runs (3.4.7 vs 3.5.14) are needed to figure out what's going on (likely a change in the plan being executed) and how to fix.

Also the query itself.

[Cobra]

Don't you have a screenshot?

Can we also see the query?