Getting could not acquire server lock when stress testing using go-driver
could not acquire server lock in time when cleaning up pool after TransactionExecutionLimit: Timeout after 5 attempts, last error: could not acquire server lock in time when computing server penalties
We make close to 139 requests in 2min and 30% fail with the above neo4j error.
running (2m00.0s), 000/100 VUs, 139 complete and 97 interrupted iterations
default ✓ [==========================] 100 VUs 1m30s
data_received..................: 896 kB 7.5 kB/s
data_sent......................: 86 kB 716 B/s
http_req_blocked...............: avg=2.59ms min=2µs med=3.36ms max=5.65ms p(90)=4.16ms p(95)=4.29ms
http_req_connecting............: avg=1.72ms min=0s med=2.4ms max=3.11ms p(90)=2.61ms p(95)=2.71ms
http_req_duration..............: avg=49.15s min=9.11s med=59.99s max=1m0s p(90)=1m0s p(95)=1m0s
{ expected_response:true }...: avg=21.35s min=9.11s med=22.31s max=43.29s p(90)=28.96s p(95)=31.36s
http_req_failed................: 71.94% ✓ 100 ✗ 39
http_req_receiving.............: avg=266.79µs min=0s med=0s max=21.65ms p(90)=251µs p(95)=652.29µs
http_req_sending...............: avg=67.87µs min=7µs med=25µs max=1.03ms p(90)=193.4µs p(95)=252.39µs
http_req_tls_handshaking.......: avg=0s min=0s med=0s max=0s p(90)=0s p(95)=0s
http_req_waiting...............: avg=49.15s min=9.11s med=59.99s max=1m0s p(90)=1m0s p(95)=1m0s
http_reqs......................: 139 1.158161/s
iteration_duration.............: avg=49.16s min=9.12s med=1m0s max=1m0s p(90)=1m0s p(95)=1m0s
iterations.....................: 139 1.158161/s
vus............................: 97 min=97 max=100
vus_max........................: 100 min=100 max=100
I have tried configuring the timeouts as below, also we are not able to require the locks after the timeout. We have also checked the access modes and we are closing the session after the query is complete.
- NEO4J_db_transaction_timeout=20s
- NEO4J_db_lock_acquisition_timeout=20s
Here are the logs
Sample of Query log
RETURN n
ORDER BY n.id
- {id: '3Znb7js1BLKMJrYwVf3J'} - runtime=null - {}
2022-12-21 02:29:50.365+0000 INFO Query started: id:5662 - transaction id:5662 - 1 ms: (planning: 1, waiting: 0) - 0 B - 0 page hits, 0 page faults - bolt-session bolt Go Driver/5.0 client/172.18.0.5:53196 server/172.18.0.3:7687> neo4j - neo4j -
MATCH
(:NetworkGroup {id:$id})-[r:IN_GROUP]->(n:Network)
RETURN n
ORDER BY n.id
- {id: 'JiMaQUf1pFQonIiteIJC'} - runtime=null - {}
2022-12-21 02:29:50.572+0000 INFO id:5659 - transaction id:5659 - 238 ms: (planning: 237, waiting: 0) - 512 B - 89 page hits, 0 page faults - bolt-session bolt Go Driver/5.0 client/172.18.0.5:53092 server/172.18.0.3:7687> neo4j - neo4j -
MATCH
(:NetworkGroup {id:$id})-[r:IN_GROUP]->(n:Network)
RETURN n
ORDER BY n.id
- {id: '3Znb7js1BLKMJrYwVf3J'} - runtime=pipelined - {}
2022-12-21 02:29:50.576+0000 INFO id:5662 - transaction id:5662 - 212 ms: (planning: 207, waiting: 0) - 512 B - 90 page hits, 0 page faults - bolt-session bolt Go Driver/5.0 client/172.18.0.5:53196 server/172.18.0.3:7687> neo4j - neo4j -
MATCH
(:NetworkGroup {id:$id})-[r:IN_GROUP]->(n:Network)
RETURN n
ORDER BY n.id
- {id: 'JiMaQUf1pFQonIiteIJC'} - runtime=pipelined - {}
2022-12-21 02:29:50.365+0000 INFO Query started: id:5663 - transaction id:5663 - 0 ms: (planning: 0, waiting: 0) - 0 B - 0 page hits, 0 page faults - bolt-session bolt Go Driver/5.0 client/172.18.0.5:53758 server/172.18.0.3:7687> neo4j - neo4j -
MATCH
(n:Subject )-[r:PROVIDES]->(:NetworkGroup{id:$id})
RETURN n
ORDER BY n.id
- {id: 'zGUGiMzubl9JX8qR3Ffb'} - runtime=null - {}
Debug log
2022-12-21 02:28:21.613+0000 INFO [o.n.b.BoltServer] Bolt server started
2022-12-21 02:28:21.615+0000 INFO [c.n.c.d.d.TopologyState] 'ServerId{2249baa2}' information change: 'ServerInfo[versionInfo=5.2.0, connectors={BOLT=localhost:7687, RAFT=8e32fc5fe5f1:7000, CLUSTER=8e32fc5fe5f1:6000}, serverConfig={initial.server.allowed_databases, a ',' separated set with elements of type 'a string'.=[], initial.server.mode_constraint, one of [PRIMARY, SECONDARY, NONE]=NONE, server.groups, a ',' separated list with elements of type 'a string identifying a Server Tag'.=[], server.cluster.initial_mode_constraint, a string=NONE, initial.server.denied_databases, a ',' separated set with elements of type 'a string'.=[]}]' -> 'ServerInfo[versionInfo=5.2.0, connectors={CLUSTER=8e32fc5fe5f1:6000, BOLT=localhost:7687, INTRA_BOLT=localhost:7688, RAFT=8e32fc5fe5f1:7000}, serverConfig={initial.server.allowed_databases, a ',' separated set with elements of type 'a string'.=[], initial.server.mode_constraint, one of [PRIMARY, SECONDARY, NONE]=NONE, server.groups, a ',' separated list with elements of type 'a string identifying a Server Tag'.=[], server.cluster.initial_mode_constraint, a string=NONE, initial.server.denied_databases, a ',' separated set with elements of type 'a string'.=[]}]'
2022-12-21 02:28:21.616+0000 INFO [o.n.s.A.ServerComponentsLifecycleAdapter] Starting web server
2022-12-21 02:28:22.118+0000 INFO [c.n.s.e.EnterpriseNeoWebServer] Remote interface available at http://localhost:7474/
2022-12-21 02:28:22.120+0000 INFO [o.n.s.A.ServerComponentsLifecycleAdapter] Web server started.
2022-12-21 02:28:22.126+0000 INFO [o.n.g.f.DatabaseManagementServiceFactory] id: 8A1242F186E28E0A1E9FD2DB9A895A0E829888307EB3B4CB9AFBFDF920315683
2022-12-21 02:28:22.129+0000 INFO [o.n.g.f.DatabaseManagementServiceFactory] name: system
2022-12-21 02:28:22.132+0000 INFO [c.n.c.d.d.TopologyState] 'ServerId{2249baa2}' information change: 'ServerInfo[versionInfo=5.2.0, connectors={CLUSTER=8e32fc5fe5f1:6000, BOLT=localhost:7687, INTRA_BOLT=localhost:7688, RAFT=8e32fc5fe5f1:7000}, serverConfig={initial.server.allowed_databases, a ',' separated set with elements of type 'a string'.=[], initial.server.mode_constraint, one of [PRIMARY, SECONDARY, NONE]=NONE, server.groups, a ',' separated list with elements of type 'a string identifying a Server Tag'.=[], server.cluster.initial_mode_constraint, a string=NONE, initial.server.denied_databases, a ',' separated set with elements of type 'a string'.=[]}]' -> 'ServerInfo[versionInfo=5.2.0, connectors={HTTP=localhost:7474, CLUSTER=8e32fc5fe5f1:6000, BOLT=localhost:7687, INTRA_BOLT=localhost:7688, RAFT=8e32fc5fe5f1:7000}, serverConfig={initial.server.allowed_databases, a ',' separated set with elements of type 'a string'.=[], initial.server.mode_constraint, one of [PRIMARY, SECONDARY, NONE]=NONE, server.groups, a ',' separated list with elements of type 'a string identifying a Server Tag'.=[], server.cluster.initial_mode_constraint, a string=NONE, initial.server.denied_databases, a ',' separated set with elements of type 'a string'.=[]}]'
2022-12-21 02:28:22.134+0000 INFO [o.n.g.f.DatabaseManagementServiceFactory] creationDate: 2022-12-09T10:26:36.774Z
2022-12-21 02:29:27.794+0000 ERROR [o.n.b.p.c.c.c.AtomicSchedulingConnection] [bolt-48] Unable to schedule for execution since there are no available threads to serve it at the moment. You can retry at a later time or consider increasing max thread pool size for bolt connector(s).
2022-12-21 02:29:29.878+0000 ERROR [o.n.b.p.c.c.c.AtomicSchedulingConnection] [bolt-69] Unable to schedule for execution since there are no available threads to serve it at the moment. You can retry at a later time or consider increasing max thread pool size for bolt connector(s).
2022-12-21 02:30:09.486+0000 WARN [o.n.k.i.a.t.m.TransactionMonitor] [neo4j/b2103733] Transaction KernelTransactionImplementationHandle{transactionSequenceNumber=5401, tx=KernelTransaction[lease:-1]} timeout.
2022-12-21 02:30:10.562+0000 WARN [o.n.k.i.a.t.m.TransactionMonitor] Transaction QueryRouterTransaction[id=5613,clientAddress=172.18.0.5:53422,username=neo4j] timeout.
Using the following versions of neo4j and driver
Neo4J : 5.2.0 enterprise
Go-driver. : 5.3.0