Neo4j

callumholmes97 · ‎09-17-2020

Hi,

I'm trying to populate a database with randomly generated users along with the company they work at, this is aiming to test a larger application. Then if all goes well I intend to have Neo4j Enterprise as the primary database.

I've started off small with approximately 36 random companies that the 100 users could be a part of. However, I intend to generate a few hundred thousand users in the end.

I'm working in python using the py2neo package. Looking at the timings I have found that it takes an average for 2 seconds to generate and insert each user. Because of this, I decided to set up a Kubernetes cluster (2 raspberry pis and 2 old laptops) so I can have multiple instances running and hopefully speed up the process.

To run my program on Kubernetes I split it into two services:

Usernumber - Passes out the number of a user for the other service to create. This manages how many users I want to create and ensures no two users have the same user number.
Usergenerator - Retrieves the user number from Usernumber, creates the user and inserts it into the dataabse.

My hope was to be able to run 1 Usernumber services and multiple Usergenerator services. Unfortunately, I have found that every now and they some users aren't being added to the database. Upon inspection of the logs I found it was because of a RW Lock (I assume the lock is on the company node and that two users are trying to be linked to that company).

At first I looked at changing:
dbms.transaction.timeout
dbms.lock.acquisition.timeout

which had no effect, so I included retries in my code along with checks that the user had been added to the database.
The code I used for inserting a user into the database is as follows:

    def user(cls, user_object):
        push_attempts = 1
        while push_attempts <= cls.max_retries:
            try:
                logger.debug(f'Attempting to insert user number {user_object.UserNumber}')
                with neo4j.GraphTransaction(graph=NeoGraph.graph, timeout=cls.timeout) as tx:
                    tx.merge(user_object)
                assert NeoGraph.graph.exists(user_object), Exception(f"Claims user {user_object.UserNumber} has been added but has not")
                logger.info(f'Successfully inserted user number {user_object.UserNumber}')
                break
            except Exception as e:
                logger.warning(
                    f'Failed to insert user number {user_object.UserNumber} on attempt {push_attempts} - {e}',
                    exc_info=True)
                push_attempts += 1
                logger.debug('Sleeping for 1 second and retrying')
                time.sleep(1)
        else:
            logger.critical(f'Failed to insert user number {user_object.UserNumber}')
            sys.exit()

I included the sys.exit() so I could stop the program when 1 user fails so don't have to search through hundreds of logs.

This still didn't work so I looked closely at my logs and the database logs (database logging set to debug).

My logs are:

{"asctime": "2020-07-29 08:57:22,368", "name": "Database.DbHandler", "levelname": "WARNING", "filename": "DbHandler.py", "funcName": "user", "message": "Failed to insert user number 10 on attempt 1 - <py2neo.database.GraphTransaction object at 0xffff820c74c0>", "exc_info": "Traceback (most recent call last):\n  File \"/app/Database/DbHandler.py\", line 244, in user\n    tx.merge(user_object)\n  File \"/usr/local/lib/python3.8/site-packages/py2neo/database.py\", line 1060, in merge\n    merge(self, primary_label, primary_key)\n  File \"/usr/local/lib/python3.8/site-packages/py2neo/ogm/__init__.py\", line 462, in __db_merge__\n    related_objects.__db_push__(tx)\n  File \"/usr/local/lib/python3.8/site-packages/py2neo/ogm/__init__.py\", line 293, in __db_push__\n    tx.merge(related_object)\n  File \"/usr/local/lib/python3.8/site-packages/py2neo/database.py\", line 1060, in merge\n    merge(self, primary_label, primary_key)\n  File \"/usr/local/lib/python3.8/site-packages/py2neo/ogm/__init__.py\", line 462, in __db_merge__\n    related_objects.__db_push__(tx)\n  File \"/usr/local/lib/python3.8/site-packages/py2neo/ogm/__init__.py\", line 300, in __db_push__\n    tx.run(\"MATCH (a) WHERE id(a) = $x MATCH (b) WHERE id(b) = $y \"\n  File \"/usr/local/lib/python3.8/site-packages/py2neo/database.py\", line 916, in run\n    result = self._connector.run_in_tx(self._transaction, cypher, parameters, hydrant)\n  File \"/usr/local/lib/python3.8/site-packages/py2neo/client/__init__.py\", line 1007, in run_in_tx\n    cx.sync(result)  # TODO: avoid sync on every tx.run\n  File \"/usr/local/lib/python3.8/site-packages/py2neo/client/bolt.py\", line 320, in sync\n    self._audit(result)\n  File \"/usr/local/lib/python3.8/site-packages/py2neo/client/bolt.py\", line 418, in _audit\n    task.audit()\n  File \"/usr/local/lib/python3.8/site-packages/py2neo/client/bolt.py\", line 613, in audit\n    item.audit()\n  File \"/usr/local/lib/python3.8/site-packages/py2neo/client/bolt.py\", line 783, in audit\n    raise self._failure\npy2neo.database.TransientError: LockClient[1077] can't wait on resource RWLock[NODE(647), hash=316713160] since => LockClient[1077] <-[:HELD_BY]- RWLock[NODE(666), hash=1732213899] <-[:WAITING_FOR]- LockClient[1144] <-[:HELD_BY]- RWLock[NODE(647), hash=316713160]\n\nDuring handling of the above exception, another exception occurred:\n\nTraceback (most recent call last):\n  File \"/app/Database/DbHandler.py\", line 244, in user\n    tx.merge(user_object)\n  File \"/usr/local/lib/python3.8/site-packages/py2neo/database.py\", line 878, in __exit__\n    self.rollback()\n  File \"/usr/local/lib/python3.8/site-packages/py2neo/database.py\", line 943, in rollback\n    self._assert_unfinished()\n  File \"/usr/local/lib/python3.8/site-packages/py2neo/database.py\", line 882, in _assert_unfinished\n    raise GraphTransactionError(self)\npy2neo.database.GraphTransactionError: <py2neo.database.GraphTransaction object at 0xffff820c74c0>"}
{"asctime": "2020-07-29 08:57:22,787", "name": "Database.DbHandler", "levelname": "CRITICAL", "filename": "DbHandler.py", "funcName": "user", "message": "Failed to insert user number 7"}
{"asctime": "2020-07-29 08:57:23,390", "name": "Database.DbHandler", "levelname": "WARNING", "filename": "DbHandler.py", "funcName": "user", "message": "Failed to insert user number 10 on attempt 2 - Claims user 10 has been added but has not", "exc_info": "Traceback (most recent call last):\n  File \"/app/Database/DbHandler.py\", line 245, in user\n    assert NeoGraph.graph.exists(user_object), Exception(f\"Claims user {user_object.UserNumber} \"\nAssertionError: Claims user 10 has been added but has not"}
{"asctime": "2020-07-29 08:57:24,405", "name": "Database.DbHandler", "levelname": "WARNING", "filename": "DbHandler.py", "funcName": "user", "message": "Failed to insert user number 10 on attempt 3 - Claims user 10 has been added but has not", "exc_info": "Traceback (most recent call last):\n  File \"/app/Database/DbHandler.py\", line 245, in user\n    assert NeoGraph.graph.exists(user_object), Exception(f\"Claims user {user_object.UserNumber} \"\nAssertionError: Claims user 10 has been added but has not"}
{"asctime": "2020-07-29 08:57:25,419", "name": "Database.DbHandler", "levelname": "WARNING", "filename": "DbHandler.py", "funcName": "user", "message": "Failed to insert user number 10 on attempt 4 - Claims user 10 has been added but has not", "exc_info": "Traceback (most recent call last):\n  File \"/app/Database/DbHandler.py\", line 245, in user\n    assert NeoGraph.graph.exists(user_object), Exception(f\"Claims user {user_object.UserNumber} \"\nAssertionError: Claims user 10 has been added but has not"}
{"asctime": "2020-07-29 08:57:26,503", "name": "Database.DbHandler", "levelname": "WARNING", "filename": "DbHandler.py", "funcName": "user", "message": "Failed to insert user number 10 on attempt 5 - Claims user 10 has been added but has not", "exc_info": "Traceback (most recent call last):\n  File \"/app/Database/DbHandler.py\", line 245, in user\n    assert NeoGraph.graph.exists(user_object), Exception(f\"Claims user {user_object.UserNumber} \"\nAssertionError: Claims user 10 has been added but has not"}
{"asctime": "2020-07-29 08:57:27,713", "name": "Database.DbHandler", "levelname": "CRITICAL", "filename": "DbHandler.py", "funcName": "user", "message": "Failed to insert user number 10"}

and the database logs for the same time are:

2020-07-29 08:57:19.351+0000 INFO [o.n.c.i.ExecutionEngine] [neo4j] Discarded stale query from the query cache after 10 seconds: MATCH (a) WHERE id(a) = $x MATCH (b) WHERE id(b) = $y MERGE (a)-[_:DEFINED_BY]->(b) SET _ = $z
2020-07-29 08:57:19.353+0000 DEBUG [o.n.c.i.CommunityCompilerFactory] [neo4j] Discarded stale plan from the plan cache after 10 seconds: MATCH (a) WHERE id(a) = $x MATCH (b) WHERE id(b) = $y MERGE (a)-[_:DEFINED_BY]->(b) SET _ = $z
2020-07-29 08:57:21.427+0000 INFO [o.n.c.i.ExecutionEngine] [neo4j] Discarded stale query from the query cache after 10 seconds: MATCH (a)-[_:HAS]->(b) WHERE id(a) = $x AND NOT id(b) IN $y DELETE _
2020-07-29 08:57:21.428+0000 DEBUG [o.n.c.i.CommunityCompilerFactory] [neo4j] Discarded stale plan from the plan cache after 10 seconds: MATCH (a)-[_:HAS]->(b) WHERE id(a) = $x AND NOT id(b) IN $y DELETE _
2020-07-29 08:57:21.469+0000 INFO [o.n.c.i.ExecutionEngine] [neo4j] Discarded stale query from the query cache after 10 seconds: MATCH (a) WHERE id(a) = $x MATCH (b) WHERE id(b) = $y MERGE (a)-[_:HAS]->(b) SET _ = $z
2020-07-29 08:57:21.470+0000 DEBUG [o.n.c.i.CommunityCompilerFactory] [neo4j] Discarded stale plan from the plan cache after 10 seconds: MATCH (a) WHERE id(a) = $x MATCH (b) WHERE id(b) = $y MERGE (a)-[_:HAS]->(b) SET _ = $z
2020-07-29 08:57:21.546+0000 INFO [o.n.c.i.ExecutionEngine] [neo4j] Discarded stale query from the query cache after 10 seconds: MATCH (a)-[_:WORKS_AT]->(b) WHERE id(a) = $x AND NOT id(b) IN $y DELETE _
2020-07-29 08:57:21.547+0000 DEBUG [o.n.c.i.CommunityCompilerFactory] [neo4j] Discarded stale plan from the plan cache after 10 seconds: MATCH (a)-[_:WORKS_AT]->(b) WHERE id(a) = $x AND NOT id(b) IN $y DELETE _
2020-07-29 08:57:21.593+0000 INFO [o.n.c.i.ExecutionEngine] [neo4j] Discarded stale query from the query cache after 10 seconds: MATCH (a) WHERE id(a) = $x MATCH (b) WHERE id(b) = $y MERGE (a)-[_:WORKS_AT]->(b) SET _ = $z
2020-07-29 08:57:21.594+0000 DEBUG [o.n.c.i.CommunityCompilerFactory] [neo4j] Discarded stale plan from the plan cache after 10 seconds: MATCH (a) WHERE id(a) = $x MATCH (b) WHERE id(b) = $y MERGE (a)-[_:WORKS_AT]->(b) SET _ = $z
2020-07-29 08:57:21.659+0000 INFO [o.n.c.i.ExecutionEngine] [neo4j] Discarded stale query from the query cache after 10 seconds: OPTIONAL MATCH (a) WHERE id(a) IN $x OPTIONAL MATCH ()-[r]->() WHERE id(r) IN $y RETURN count(DISTINCT a) + count(DISTINCT r)
2020-07-29 08:57:21.661+0000 DEBUG [o.n.c.i.CommunityCompilerFactory] [neo4j] Discarded stale plan from the plan cache after 10 seconds: OPTIONAL MATCH (a) WHERE id(a) IN $x OPTIONAL MATCH ()-[r]->() WHERE id(r) IN $y RETURN count(DISTINCT a) + count(DISTINCT r)
2020-07-29 08:57:28.305+0000 INFO [o.n.c.i.ExecutionEngine] [neo4j] Discarded stale query from the query cache after 20 seconds: UNWIND $x AS data MERGE (_:Position {Id:data[0]}) SET _:Position SET _ = data[1] RETURN id(_)
2020-07-29 08:57:28.306+0000 DEBUG [o.n.c.i.CommunityCompilerFactory] [neo4j] Discarded stale plan from the plan cache after 20 seconds: UNWIND $x AS data MERGE (_:Position {Id:data[0]}) SET _:Position SET _ = data[1] RETURN id(_)

Hi,

I'm trying to populate a database with randomly generated users along with the company they work at ,as part of testing a larger application. I've started off small with approximately 36 random companies that the 100 users could be a part of. However, I intend to generate a few hundred thousand users in the end.