search

covidgraph / graph-processing_fragmentize_text

Create Fragment nodes from full text data (publications/patents)
1 stars 2 forks source link

Node Lock #4

Closed motey closed 4 years ago

motey commented 4 years ago 
Active database: graph.db
Directories in use:
  home:         /var/lib/neo4j
  config:       /var/lib/neo4j/conf
  logs:         /logs
  plugins:      /plugins
  import:       /import
  data:         /var/lib/neo4j/data
  certificates: /ssl
  run:          /var/lib/neo4j/run
Starting Neo4j.
2020-07-06 18:14:41.544+0000 WARN  Unknown config option: dbms.default_advertised_address
2020-07-06 18:14:41.552+0000 WARN  Unknown config option: dbms.default_listen_address
2020-07-06 18:14:41.597+0000 INFO  ======== Neo4j 3.5.17 ========
2020-07-06 18:14:41.617+0000 INFO  Starting...
2020-07-06 18:14:44.209+0000 INFO  Initiating metrics...
2020-07-06 18:15:13.750+0000 INFO  Sending metrics to CSV file at /var/lib/neo4j/metrics
2020-07-06 18:15:14.429+0000 INFO  Bolt enabled on 0.0.0.0:7687.
2020-07-06 18:15:16.795+0000 WARN  Server thread metrics not available (missing neo4j.server.threads.jetty.all)
2020-07-06 18:15:16.797+0000 WARN  Server thread metrics not available (missing neo4j.server.threads.jetty.idle)
2020-07-06 18:15:18.126+0000 INFO  Started.
2020-07-06 18:15:18.389+0000 INFO  Mounted REST API at: /db/manage
2020-07-06 18:15:18.423+0000 INFO  Mounted unmanaged extension [com.neo4j.bloom.server] at [/browser/bloom]
2020-07-06 18:15:18.554+0000 INFO  Server thread metrics have been registered successfully
2020-07-06 18:15:20.917+0000 WARN  The following warnings have been detected with resource and/or provider classes:
  WARNING: A sub-resource method, public javax.ws.rs.core.Response com.neo4j.bloom.server.BloomResource.file(), with URI template, "/", is treated as a resource method
2020-07-06 18:15:21.410+0000 INFO  Remote interface available at http://localhost:7474/
2020-07-06 19:41:40.731+0000 INFO  starting batching from `MATCH (text_node:BodyText) WHERE NOT text_node:CollectionHub AND NOT (text_node)-[:HAS_FRAGMENT]-() RETURN text_node` operation using iteration `WITH text_node,split(text_node.text, '. ') AS frags
WHERE size(frags) > 0
WITH text_node,frags,range(0,size(frags)-1) AS r
WITH text_node,frags,r
FOREACH ( entry in r | CREATE (f:Fragment:FromBodyText) 
                SET f.text = frags[entry], f.sequence = entry, f.kind = labels(text_node)[0]
                MERGE (text_node)-[:HAS_FRAGMENT]->(f) )` in separate thread
2020-07-06 19:41:41.367+0000 INFO  starting batching from `MATCH (f:Fragment:FromBodyText) WHERE f.sequence > 0 RETURN f` operation using iteration `MATCH (f)<--(n)-->(f2:Fragment:FromBodyText)
    WHERE f2.sequence = f.sequence - 1
    MERGE (f2)-[:NEXT]->(f)` in separate thread
2020-07-06 19:41:41.658+0000 INFO  starting batching from `MATCH (text_node:Abstract) WHERE NOT text_node:CollectionHub AND NOT (text_node)-[:HAS_FRAGMENT]-() RETURN text_node` operation using iteration `WITH text_node,split(text_node.text, '. ') AS frags
WHERE size(frags) > 0
WITH text_node,frags,range(0,size(frags)-1) AS r
WITH text_node,frags,r
FOREACH ( entry in r | CREATE (f:Fragment:FromAbstract) 
                SET f.text = frags[entry], f.sequence = entry, f.kind = labels(text_node)[0]
                MERGE (text_node)-[:HAS_FRAGMENT]->(f) )` in separate thread
2020-07-06 19:43:17.639+0000 INFO  starting batching from `MATCH (f:Fragment:FromAbstract) WHERE f.sequence > 0 RETURN f` operation using iteration `MATCH (f)<--(n)-->(f2:Fragment:FromAbstract)
    WHERE f2.sequence = f.sequence - 1
    MERGE (f2)-[:NEXT]->(f)` in separate thread
2020-07-06 19:43:52.025+0000 ERROR Error while executing background job because of the following exception (the task will be killed): ForsetiClient[8] can't acquire ExclusiveLock{owner=ForsetiClient[7]} on RELATIONSHIP(4148500), because holders of that lock are waiting for ForsetiClient[8].
 Wait list:ExclusiveLock[
Client[7] waits for [8]]
org.neo4j.kernel.DeadlockDetectedException: ForsetiClient[8] can't acquire ExclusiveLock{owner=ForsetiClient[7]} on RELATIONSHIP(4148500), because holders of that lock are waiting for ForsetiClient[8].
 Wait list:ExclusiveLock[
Client[7] waits for [8]]
    at org.neo4j.kernel.impl.enterprise.lock.forseti.ForsetiClient.waitFor(ForsetiClient.java:981)
    at org.neo4j.kernel.impl.enterprise.lock.forseti.ForsetiClient.acquireExclusive(ForsetiClient.java:326)
    at org.neo4j.kernel.impl.storageengine.impl.recordstorage.RelationshipCreator.connect(RelationshipCreator.java:206)
    at org.neo4j.kernel.impl.storageengine.impl.recordstorage.RelationshipCreator.connect(RelationshipCreator.java:176)
    at org.neo4j.kernel.impl.storageengine.impl.recordstorage.RelationshipCreator.connectRelationship(RelationshipCreator.java:137)
    at org.neo4j.kernel.impl.storageengine.impl.recordstorage.RelationshipCreator.relationshipCreate(RelationshipCreator.java:71)
    at org.neo4j.kernel.impl.storageengine.impl.recordstorage.TransactionRecordState.relCreate(TransactionRecordState.java:291)
    at org.neo4j.kernel.impl.storageengine.impl.recordstorage.TransactionToRecordStateVisitor.visitCreatedRelationship(TransactionToRecordStateVisitor.java:92)
    at org.neo4j.storageengine.api.txstate.TxStateVisitor$Delegator.visitCreatedRelationship(TxStateVisitor.java:190)
    at org.neo4j.kernel.api.txstate.TransactionCountingStateVisitor.visitCreatedRelationship(TransactionCountingStateVisitor.java:108)
    at org.neo4j.kernel.impl.api.state.RelationshipStateImpl.accept(RelationshipStateImpl.java:115)
    at org.neo4j.kernel.impl.api.state.TxState.relationshipVisit(TxState.java:832)
    at org.neo4j.kernel.impl.api.state.TxState.accept(TxState.java:131)
    at org.neo4j.kernel.impl.storageengine.impl.recordstorage.RecordStorageEngine.createCommands(RecordStorageEngine.java:272)
    at org.neo4j.kernel.impl.api.KernelTransactionImplementation.commit(KernelTransactionImplementation.java:687)
    at org.neo4j.kernel.impl.api.KernelTransactionImplementation.closeTransaction(KernelTransactionImplementation.java:594)
    at org.neo4j.internal.kernel.api.Transaction.close(Transaction.java:178)
    at org.neo4j.kernel.impl.coreapi.TopLevelTransaction.close(TopLevelTransaction.java:77)
    at apoc.util.Util.lambda$inTxFuture$4(Util.java:240)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
2020-07-06 19:43:52.039+0000 ERROR Error while executing background job because of the following exception (the task will be killed): ForsetiClient[3] can't acquire ExclusiveLock{owner=ForsetiClient[7]} on RELATIONSHIP(4148582), because holders of that lock are waiting for ForsetiClient[3].
 Wait list:ExclusiveLock[
Client[7] waits for [3,8]]
org.neo4j.kernel.DeadlockDetectedException: ForsetiClient[3] can't acquire ExclusiveLock{owner=ForsetiClient[7]} on RELATIONSHIP(4148582), because holders of that lock are waiting for ForsetiClient[3].
 Wait list:ExclusiveLock[
Client[7] waits for [3,8]]
    at org.neo4j.kernel.impl.enterprise.lock.forseti.ForsetiClient.waitFor(ForsetiClient.java:981)
    at org.neo4j.kernel.impl.enterprise.lock.forseti.ForsetiClient.acquireExclusive(ForsetiClient.java:326)
    at org.neo4j.kernel.impl.storageengine.impl.recordstorage.RelationshipCreator.connect(RelationshipCreator.java:206)
    at org.neo4j.kernel.impl.storageengine.impl.recordstorage.RelationshipCreator.connect(RelationshipCreator.java:176)
    at org.neo4j.kernel.impl.storageengine.impl.recordstorage.RelationshipCreator.connectRelationship(RelationshipCreator.java:126)
    at org.neo4j.kernel.impl.storageengine.impl.recordstorage.RelationshipCreator.relationshipCreate(RelationshipCreator.java:71)
    at org.neo4j.kernel.impl.storageengine.impl.recordstorage.TransactionRecordState.relCreate(TransactionRecordState.java:291)
    at org.neo4j.kernel.impl.storageengine.impl.recordstorage.TransactionToRecordStateVisitor.visitCreatedRelationship(TransactionToRecordStateVisitor.java:92)
    at org.neo4j.storageengine.api.txstate.TxStateVisitor$Delegator.visitCreatedRelationship(TxStateVisitor.java:190)
    at org.neo4j.kernel.api.txstate.TransactionCountingStateVisitor.visitCreatedRelationship(TransactionCountingStateVisitor.java:108)
    at org.neo4j.kernel.impl.api.state.RelationshipStateImpl.accept(RelationshipStateImpl.java:115)
    at org.neo4j.kernel.impl.api.state.TxState.relationshipVisit(TxState.java:832)
    at org.neo4j.kernel.impl.api.state.TxState.accept(TxState.java:131)
    at org.neo4j.kernel.impl.storageengine.impl.recordstorage.RecordStorageEngine.createCommands(RecordStorageEngine.java:272)
    at org.neo4j.kernel.impl.api.KernelTransactionImplementation.commit(KernelTransactionImplementation.java:687)
    at org.neo4j.kernel.impl.api.KernelTransactionImplementation.closeTransaction(KernelTransactionImplementation.java:594)
    at org.neo4j.internal.kernel.api.Transaction.close(Transaction.java:178)
    at org.neo4j.kernel.impl.coreapi.TopLevelTransaction.close(TopLevelTransaction.java:77)
    at apoc.util.Util.lambda$inTxFuture$4(Util.java:240)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
2020-07-06 19:43:57.295+0000 WARN  Error during iterate.commit:
2020-07-06 19:43:57.296+0000 WARN  1 times: org.neo4j.kernel.DeadlockDetectedException: ForsetiClient[3] can't acquire ExclusiveLock{owner=ForsetiClient[7]} on RELATIONSHIP(4148582), because holders of that lock are waiting for ForsetiClient[3].
 Wait list:ExclusiveLock[
Client[7] waits for [3,8]]
2020-07-06 19:43:57.296+0000 WARN  1 times: org.neo4j.kernel.DeadlockDetectedException: ForsetiClient[8] can't acquire ExclusiveLock{owner=ForsetiClient[7]} on RELATIONSHIP(4148500), because holders of that lock are waiting for ForsetiClient[8].
 Wait list:ExclusiveLock[
Client[7] waits for [8]]
2020-07-06 19:43:57.383+0000 INFO  starting batching from `MATCH (text_node:PatentDescription) WHERE NOT text_node:CollectionHub AND NOT (text_node)-[:HAS_FRAGMENT]-() RETURN text_node` operation using iteration `WITH text_node,split(text_node.text, '. ') AS frags
WHERE size(frags) > 0
WITH text_node,frags,range(0,size(frags)-1) AS r
WITH text_node,frags,r
FOREACH ( entry in r | CREATE (f:Fragment:FromPatentDescription) 
                SET f.text = frags[entry], f.sequence = entry, f.kind = labels(text_node)[0]
                MERGE (text_node)-[:HAS_FRAGMENT]->(f) )` in separate thread
2020-07-06 20:12:40.350+0000 INFO  starting batching from `MATCH (f:Fragment:FromPatentDescription) WHERE f.sequence > 0 RETURN f` operation using iteration `MATCH (f)<--(n)-->(f2:Fragment:FromPatentDescription)
    WHERE f2.sequence = f.sequence - 1
    MERGE (f2)-[:NEXT]->(f)` in separate thread
2020-07-06 21:58:35.537+0000 INFO  starting batching from `MATCH (text_node:PatentTitle) WHERE NOT text_node:CollectionHub AND NOT (text_node)-[:HAS_FRAGMENT]-() RETURN text_node` operation using iteration `WITH text_node,split(text_node.text, '. ') AS frags
WHERE size(frags) > 0
WITH text_node,frags,range(0,size(frags)-1) AS r
WITH text_node,frags,r
FOREACH ( entry in r | CREATE (f:Fragment:FromPatentTitle) 
                SET f.text = frags[entry], f.sequence = entry, f.kind = labels(text_node)[0]
                MERGE (text_node)-[:HAS_FRAGMENT]->(f) )` in separate thread
2020-07-06 21:58:42.974+0000 INFO  starting batching from `MATCH (f:Fragment:FromPatentTitle) WHERE f.sequence > 0 RETURN f` operation using iteration `MATCH (f)<--(n)-->(f2:Fragment:FromPatentTitle)
    WHERE f2.sequence = f.sequence - 1
    MERGE (f2)-[:NEXT]->(f)` in separate thread
2020-07-06 21:58:43.267+0000 INFO  starting batching from `MATCH (text_node:PatentAbstract) WHERE NOT text_node:CollectionHub AND NOT (text_node)-[:HAS_FRAGMENT]-() RETURN text_node` operation using iteration `WITH text_node,split(text_node.text, '. ') AS frags
WHERE size(frags) > 0
WITH text_node,frags,range(0,size(frags)-1) AS r
WITH text_node,frags,r
FOREACH ( entry in r | CREATE (f:Fragment:FromPatentAbstract) 
                SET f.text = frags[entry], f.sequence = entry, f.kind = labels(text_node)[0]
                MERGE (text_node)-[:HAS_FRAGMENT]->(f) )` in separate thread
2020-07-06 21:58:57.660+0000 INFO  starting batching from `MATCH (f:Fragment:FromPatentAbstract) WHERE f.sequence > 0 RETURN f` operation using iteration `MATCH (f)<--(n)-->(f2:Fragment:FromPatentAbstract)
    WHERE f2.sequence = f.sequence - 1
    MERGE (f2)-[:NEXT]->(f)` in separate thread
2020-07-06 21:59:01.265+0000 INFO  starting batching from `MATCH (text_node:PatentClaim) WHERE NOT text_node:CollectionHub AND NOT (text_node)-[:HAS_FRAGMENT]-() RETURN text_node` operation using iteration `WITH text_node,split(text_node.text, '. ') AS frags
WHERE size(frags) > 0
WITH text_node,frags,range(0,size(frags)-1) AS r
WITH text_node,frags,r
FOREACH ( entry in r | CREATE (f:Fragment:FromPatentClaim) 
                SET f.text = frags[entry], f.sequence = entry, f.kind = labels(text_node)[0]
                MERGE (text_node)-[:HAS_FRAGMENT]->(f) )` in separate thread
2020-07-06 22:01:07.333+0000 INFO  starting batching from `MATCH (f:Fragment:FromPatentClaim) WHERE f.sequence > 0 RETURN f` operation using iteration `MATCH (f)<--(n)-->(f2:Fragment:FromPatentClaim)
    WHERE f2.sequence = f.sequence - 1
    MERGE (f2)-[:NEXT]->(f)` in separate thread
2020-07-06 22:02:34.039+0000 ERROR Error while executing background job because of the following exception (the task will be killed): ForsetiClient[7] can't acquire ExclusiveLock{owner=ForsetiClient[0]} on RELATIONSHIP(18826856), because holders of that lock are waiting for ForsetiClient[7].
 Wait list:ExclusiveLock[
Client[0] waits for [7]]
org.neo4j.kernel.DeadlockDetectedException: ForsetiClient[7] can't acquire ExclusiveLock{owner=ForsetiClient[0]} on RELATIONSHIP(18826856), because holders of that lock are waiting for ForsetiClient[7].
 Wait list:ExclusiveLock[
Client[0] waits for [7]]
    at org.neo4j.kernel.impl.enterprise.lock.forseti.ForsetiClient.waitFor(ForsetiClient.java:981)
    at org.neo4j.kernel.impl.enterprise.lock.forseti.ForsetiClient.acquireExclusive(ForsetiClient.java:326)
    at org.neo4j.kernel.impl.storageengine.impl.recordstorage.RelationshipCreator.connect(RelationshipCreator.java:206)
    at org.neo4j.kernel.impl.storageengine.impl.recordstorage.RelationshipCreator.connect(RelationshipCreator.java:176)
    at org.neo4j.kernel.impl.storageengine.impl.recordstorage.RelationshipCreator.connectRelationship(RelationshipCreator.java:126)
    at org.neo4j.kernel.impl.storageengine.impl.recordstorage.RelationshipCreator.relationshipCreate(RelationshipCreator.java:71)
    at org.neo4j.kernel.impl.storageengine.impl.recordstorage.TransactionRecordState.relCreate(TransactionRecordState.java:291)
    at org.neo4j.kernel.impl.storageengine.impl.recordstorage.TransactionToRecordStateVisitor.visitCreatedRelationship(TransactionToRecordStateVisitor.java:92)
    at org.neo4j.storageengine.api.txstate.TxStateVisitor$Delegator.visitCreatedRelationship(TxStateVisitor.java:190)
    at org.neo4j.kernel.api.txstate.TransactionCountingStateVisitor.visitCreatedRelationship(TransactionCountingStateVisitor.java:108)
    at org.neo4j.kernel.impl.api.state.RelationshipStateImpl.accept(RelationshipStateImpl.java:115)
    at org.neo4j.kernel.impl.api.state.TxState.relationshipVisit(TxState.java:832)
    at org.neo4j.kernel.impl.api.state.TxState.accept(TxState.java:131)
    at org.neo4j.kernel.impl.storageengine.impl.recordstorage.RecordStorageEngine.createCommands(RecordStorageEngine.java:272)
    at org.neo4j.kernel.impl.api.KernelTransactionImplementation.commit(KernelTransactionImplementation.java:687)
    at org.neo4j.kernel.impl.api.KernelTransactionImplementation.closeTransaction(KernelTransactionImplementation.java:594)
    at org.neo4j.internal.kernel.api.Transaction.close(Transaction.java:178)
    at org.neo4j.kernel.impl.coreapi.TopLevelTransaction.close(TopLevelTransaction.java:77)
    at apoc.util.Util.lambda$inTxFuture$4(Util.java:240)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
2020-07-06 22:02:55.589+0000 WARN  Error during iterate.commit:
2020-07-06 22:02:55.589+0000 WARN  1 times: org.neo4j.kernel.DeadlockDetectedException: ForsetiClient[7] can't acquire ExclusiveLock{owner=ForsetiClient[0]} on RELATIONSHIP(18826856), because holders of that lock are waiting for ForsetiClient[7].
 Wait list:ExclusiveLock[
Client[0] waits for [7]]

When running against DEV text fragger gets a node lock Martin suspects that happens when the amount of sentences in a text node exceed the batch size

mpreusse commented 4 years ago

Node lock occurs in the second step where we chain the :Fragment nodes with NEXT relationships. This can be parallelized. I suspect the root cause of the error was that the query killed the machine (see other issue).

mpreusse commented 4 years ago

For now we don't create the NEXT relationships. If we need the previous/next fragments in an application we can get them with a Cypher query dynamically.