Neo4j server hangs every 2 hours consistently. Please help me understand if something is wrong with the configuration

Question

We have a neo4j graph database with around 60 million nodes and an equivalent relationships.

We have been facing consistent packet drops and delays in processing and a complete hung server after 2 hours. We had to shutdown and restart our servers every time this happens and we are having trouble understanding where we went wrong with our configuration.

We are seeing the following kind of exceptions in the console.log file -

1. java.lang.IllegalStateException: s=DISPATCHED i=true a=null o.e.jetty.server.HttpConnection - HttpConnection@609c1158{FILLING}
2. java.lang.IllegalStateException: s=DISPATCHED i=true a=null o.e.j.util.thread.QueuedThreadPool
3. java.lang.IllegalStateException: org.eclipse.jetty.util.SharedBlockingCallback$BlockerTimeoutException
4. o.e.j.util.thread.QueuedThreadPool - Unexpected thread death: org.eclipse.jetty.util.thread.QueuedThreadPool$3@59d5a975 in qtp1667455214{STARTED,14<=21<=21,i=0,q=58}
5. org.eclipse.jetty.server.Response - Committed before 500 org.neo4j.server.rest.repr.OutputFormat$1@39beaadf
6. o.e.jetty.servlet.ServletHandler - /db/data/cypher java.lang.IllegalStateException: Committed at org.eclipse.jetty.server.Response.resetBuffer(Response.java:1253) ~[jetty-server-9.2.
7. org.eclipse.jetty.server.HttpChannel - /db/data/cypher java.lang.IllegalStateException: Committed at org.eclipse.jetty.server.Response.resetBuffer(Response.java:1253) ~[jetty-server-9.2.
8. org.eclipse.jetty.server.HttpChannel - Could not send response error 500: java.lang.IllegalStateException: Committed o.e.jetty.server.ServerConnector - Stopped
9. o.e.jetty.servlet.ServletHandler - /db/data/cypher org.neo4j.graphdb.TransactionFailureException: Transaction was marked as successful, but unable to commit transaction so rolled back.

We are using neo4j enterprise edition 2.2.5 server in SINGLE/NON CLUSTER mode on Azure D series 8 core CPU,56 GB RAM UBUNTU 14.04 LTS machine with an attached 500GB data disk.

Here is a snapshot of the sizes of neostore files

• 8.5G Oct 2 15:48 neostore.propertystore.db
• 15G Oct 2 15:48 neostore.relationshipstore.db
• 2.5G Oct 2 15:48 neostore.nodestore.db
• 6.9M Oct 2 15:48 neostore.relationshipgroupstore.db
• 3.7K Oct 2 15:07 neostore.schemastore.db
• 145 Oct 2 15:07 neostore.labeltokenstore.db
• 170 Oct 2 15:07 neostore.relationshiptypestore.db

The Neo4j configuration is as follows -

1. Allocated 30GB to file buffer cache (dbms.pagecache.memory=30G)
2. Allocated 20GB to JVM heap memory (wrapper.java.initmemory=20480, wrapper.java.maxmemory=20480)
3. Using the default hpc(High performance) type cache.
4. Forcing the RULE planner by default (dbms.cypher.planner=RULE)
5. Maximum threads processing queries is 16(twice the number of cores) - org.neo4j.server.webserver.maxthreads=16
6. Transaction timeout of 60 seconds - org.neo4j.server.transaction.timeout=60
7. Guard Timeout if query execution time is greater than 10 seconds - org.neo4j.server.webserver.limit.executiontime=10000

Rest of the settings are default

We actually want to setup a cluster of 3 nodes but before that we want to be sure if our basic configuration is correct. Please help us

--------------------------------------------------------------------------

EDITED to ADD Query Sample

Typically our cypher query frequency is 18K queries in an hour with an average of roughly 5-6 queries a second. There are also times when there are about 80 queries per second.

Our Typical Queries look like the ones below

match (a:TypeA {param:{param}})-[:RELA]->(d:TypeD) with distinct d,a skip {skip} limit 100 optional match (d)-[:RELF]->(c:TypeC)<-[:RELF]-(b:TypeB)<-[:RELB]-(a) with distinct d,a,collect(distinct b.bid) as bids,collect(distinct c.param3) as param3Coll optional match (d)-[:RELE]->(p:TypeE)<-[:RELE]-(b1:TypeB)<-[:RELB]-(a) with distinct d as distD,bids+collect(distinct b1.bid) as tbids,param3Coll,collect(distinct p.param4) as param4Coll optional match (distD)-[:RELC]->(f:TypeF) return id(distD),distD.param5,exists((distD)<-[:RELG]-()) as param6, tbids,param3Coll,param4Coll,collect(distinct id(f)) as fids

match (a:TypeA {param:{param}})-[:RELB]->(b) return count(distinct b)

MATCH (a:TypeA{param:{param}})-[r:RELD]->(a1)-[:RELH]->(h) where r.param1=true with a,a1,h match (h)-[:RELL]->(d:TypeI) where (d.param2/2)%2=1 optional match (a)-[:RELB]-(b)-[:RELM {param3:true}]->(c) return a1.param,id(a1),collect(b.bid),c.param5

match (a:TypeA {param:{param}}) match (a)-[:RELB]->(b) with distinct b,a skip {skip} limit 100 match (a)-[:RELH]->(h1:TypeH) match (b)-[:RELF|RELE]->(x)<-[:RELF|RELE]-(h2:TypeH)<-[:RELH]-(a1) optional match (a1)<-[rd:RELD]-(a) with distinct a1,a,h1,b,h2,rd.param1 as param2,collect(distinct x.param3) as param3s,collect(distinct x.param4) as param4s optional match (a1)-[:RELB]->(b1) where b1.param7 in [0,1] and exists((b1)-[:RELF|RELE]->()<-[:RELF|RELE]-(h1)) with distinct a1,a,b,h2,param2,param3s,param4s,b1,case when param2 then false else case when ((a1.param5 in [2,3] or length(param3s)>0) or (a1.param5 in [1,3] or length(param4s)>0)) then case when b1.param7=0 then false else true end else false end end as param8 MERGE (a)-[r2:RELD]->(a1) on create set r2.param6=true on match set r2.param6=case when param8=true and r2.param9=false then true else false end MERGE (b)-[r3:RELM]->(h2) SET r2.param9=param8, r3.param9=param8

MATCH (a:TypeA {param:{param}})-[:RELI]->(g:TypeG {type:'type1'}) match (g)<-[r:RELI]-(a1:TypeA)-[:RELJ]->(j)-[:RELK]->(g) return distinct g, collect(j.displayName), collect(r.param1), g.gid, collect(a1.param),collect(id(a1))

match (a:TypeA {param:{param}})-[r:RELD {param2:true}]->(a1:TypeA)-[:RELH]->(b:TypeE) remove r.param2 return id(a1),b.displayName, b.firstName,b.lastName match (a:TypeA {param:{param}})-[:RELA]->(b:TypeB) return a.param1,count(distinct id(b))

MATCH (a:TypeA {param:{param}}) set a.param1=true;

match (a:TypeE)<-[r:RELE]-(b:TypeB) where a.param4 in {param4s} delete r return count(b);

MATCH (a:TypeA {param:{param}}) return id(a);

---

Adding a few more strange things I have been noticing....

I am have stopped all my webservers. So, currently there are no incoming requests to neo4j. However I see that there are about 40K open file handles in TCP close/wait state implying the client has closed its connection because of time out and Neo4j has not processed it and responded to that request. I also see (from messages.log) that Neo4j server is still processing queries and as it does this, the 40K open file handles is slowly reducing. By the time I write this post there are about 27K open file handles in TCP close/wait state.

Also I see that the queries are not continuously processed. Every once in a while I am seeing a pause in messages.log and I see these messages about log rotation because of some out of order sequence as below

Rotating log version:5630

2015-10-04 05:10:42.712+0000 INFO [o.n.k.LogRotationImpl]: Log Rotation [5630]: Awaiting all transactions closed...

2015-10-04 05:10:42.712+0000 INFO [o.n.k.i.s.StoreFactory]: Waiting for all transactions to close...

committed: out-of-order-sequence:95494483 [95494476]

committing: 95494483

closed: out-of-order-sequence:95494480 [95494246]

2015-10-04 05:10:43.293+0000 INFO [o.n.k.LogRotationImpl]: Log Rotation [5630]: Starting store flush...

2015-10-04 05:10:44.941+0000 INFO [o.n.k.i.s.StoreFactory]: About to rotate counts store at transaction 95494483 to [/datadrive/graph.db/neostore.counts.db.b], from [/datadrive/graph.db/neostore.counts.db.a].

2015-10-04 05:10:44.944+0000 INFO [o.n.k.i.s.StoreFactory]: Successfully rotated counts store at transaction 95494483 to [/datadrive/graph.db/neostore.counts.db.b], from [/datadrive/graph.db/neostore.counts.db.a].

I also see these messages once in a while

2015-10-04 04:59:59.731+0000 DEBUG [o.n.k.EmbeddedGraphDatabase]: NodeCache array:66890956 purge:93 size:1.3485746GiB misses:0.80978173% collisions:1.9829895% (345785) av.purge waits:13 purge waits:0 avg. purge time:110ms

or

2015-10-04 05:10:20.768+0000 DEBUG [o.n.k.EmbeddedGraphDatabase]: RelationshipCache array:66890956 purge:0 size:257.883MiB misses:10.522135% collisions:11.121769% (5442101) av.purge waits:0 purge waits:0 avg. purge time:N/A

All of this is happening when there are no incoming requests and neo4j is processing old pending 40K requests as I mentioned above.

Since, it is a dedicated server, should not the server be processing the queries continuously without such a large pending queue? Am I missing something here? Please help me

Answer 1

Didn't go completely over your queries. You should examine each of the queries you send often by prefixing with PROFILE or EXPLAIN to see the query plan and get an idea how many accesses they cause.

E.g. the second match in the following query looks like being expensive since the two patterns are not connected with each other:

MATCH (a:TypeA{param:{param}})-[r:RELD]->(a1)-[:RELH]->(h) where    r.param1=true with a,a1,h match (m)-[:RELL]->(d:TypeI) where (d.param2/2)%2=1 optional match (a)-[:RELB]-(b)-[:RELM {param3:true}]->(c)  return a1.param,id(a1),collect(b.bid),c.bPhoto

Also enable garbage collection logging in neo4j-wrapper.conf and check if you're suffering from long pauses. If so, consider to reduce heap size.

Answer 2

Looks like that this issue requires more research from your side, but there is some things from my experience.

TL;DR; - I had similar issue with my own unmanaged extension, where transactions were not properly handled.

Language/connector

What language/connector is used in your application?

You should verify that:

• If some popular open-source library is used - your application is using latest version. Probably there is bug in your connector.
• If you have your own, hand-written solution that works with REST API - verify that ALL http request are closed at client side.

Extension/plugins

It's quite easy to mess things up, if custom-written extensions/plugins are used.

What should be checked:

• All transaction are always closed (try-with-resource is used)

Neo4j settings

Verify your server configuration. For example, if you have large value for org.neo4j.server.transaction.timeout and you don't handle properly transaction at client side - you can end up with a lot of running transactions.

Monitoring

You are using Enterprise version. That means that you have access to JMX. It's good idea to check information about active Locks & Transactions.

Another Neo4j version

Maybe you can try another Neo4j version. For example 2.3.0-M03.
This will give answers for questions like:

• Is this Neo4j 2.2.5 bug?
• Is this existing Neo4j installation misconfiguration?

Linux configuration

Check your Linux configuration.

• What is in your /etc/sysctl.conf? Are there any invalid/unrelated settings?

Another server

You can try to spin-up another server (i.e. VM at DigitalOcean), deploy database there and load it with Gatling.
Maybe your server have some invalid configuration?

---

Try to get rid of everything, that can be cause of the problem, to make it easier to find a problem.