Neo4j performance slow when merging (high GC times)

[afattahian]

Platform: MacBook 2.9 GHz i7, 16 Gigs RAM
Neo4j 3.5.6 Community Edition.

Using the following python code to perform cypher merges concurrently:

with get_bolt_session():
    pass
if parameters is not None:
    kw_params.update(parameters)
num_workers = mp.cpu_count() * 5  
with ThreadPoolExecutor(max_workers=num_workers) as executor:
    future_results = [executor.submit(neo4j_worker, i, kw_params)
                      for i in cypher_query]

cypher_query list has approximately 600 MERGE cypher commands. Initially merges are completing quickly. After approximately 15 second start seeing "Detected VM stop-the-world pause" messages in neo4j debug.log file and merges in each worker thread starts to slow down until everything comes to halt. At that point GC times are extremely high

2019-07-28 22:27:47.030+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=127361, gcTime=325855, gcCount=102}
2019-07-28 22:30:17.436+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=244495, gcTime=34552, gcCount=12}
2019-07-28 22:32:14.519+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=174950, gcTime=209821, gcCount=62}
2019-07-28 22:34:57.055+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=150598, gcTime=127222, gcCount=39}
2019-07-28 22:40:58.366+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=162481, gcTime=361129, gcCount=108}
2019-07-28 22:45:35.778+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=464546, gcTime=266117, gcCount=77}
2019-07-28 22:47:08.909+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=139166, gcTime=139252, gcCount=42}
2019-07-28 22:51:39.954+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=139911, gcTime=258582, gcCount=80}
2019-07-28 22:56:11.614+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=189317, gcTime=118682, gcCount=37}
2019-07-28 22:57:22.091+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=295090, gcTime=235389, gcCount=71}
2019-07-28 23:00:07.338+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=164734, gcTime=188594, gcCount=62}
2019-07-28 23:05:49.912+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=83270, gcTime=283600, gcCount=82}

Why does GC time keep increasing? It seems like neo4j never recovers once GC kicks in. It would be greatly appreciated if someone can explain why GC times keep getting higher and neo4j can't recover. Also I have not been able to find anywhere in documentation explaining what gcCount is.

Thanks

[andrew_bowman]

I believe gcCount is the number of garbage collection events, and they collectively contribute to the gcTime, which is a component of the pauseTime.

The issue you're seeing is common when you are using MERGE when you don't have supporting indexes and/or unique constraints. Remember that MERGE acts like a MATCH, and if no match is found, a CREATE, so without supporting indexes, your query would need to do a label scan of all nodes of the label and do property access to see if it matches what you're looking for, and this happens with EVERY MERGE for every row, so it becomes an increasingly expensive and memory inefficient operation as more nodes are added of that label.

You haven't provided your query here, so my general advice is to ensure you have a supporting index and/or unique constraint, and verify that it will be used by doing an EXPLAIN of the query.

Also, you may not be doing efficient batching. Using single transactions for a single MERGE each isn't efficient. Please see this blog entry on performing efficient batching operations.

[afattahian]

Thanks Andrew for the response link you provided for more efficient batching of operations. Are there any guidelines we should follow when setting up heap space and JVM setting in neo4j.conf file?