Possible Bug: unique constraint violation while adding non unique vertex properties in threaded transaction concurrently #3470

mrckzgl · 2023-01-18T19:44:34Z

mrckzgl
Jan 18, 2023

Using Janusgraph 0.6.1 (org.janusgraph:janusgraph-berkeleyje:0.6.1) with JRuby and Lucene index (though I guess this is not a mixed index problem). This is the config we are using:

org.janusgraph.core.JanusGraphFactory.build
       .set("storage.backend","berkeleyje")
       .set("storage.directory", DB_FOLDER)
       .set("allow_upgrade",false)
       .set("lock_mode","READ_UNCOMMITED")
       .set("jvm_cache","50")
       .set("timestamp_provider","NANO")
       .set("index.search.backend","lucene")
       .set("index.search.directory","#{DB_FOLDER}/index")
       .set("query.batch-property-prefetch","true")
       .set("query.fast-property","true")
       .set("query.force-index","true")

We open a threaded transaction:

dbtx = DB.tx().createThreadedTx();

Then each thread drops some vertices and afterwards creates new vertices and adds properties to those vertices:

traverser = dbtx.traversal.add_v()
      .property('prop_name', 'prop_value') #  <- quite a lot of those kind of calls

traverser.iterate()

After all threads are done dbtx is committed. The .property gremlin calls (or the .iterate calls, sorry not sure atm) sometimes (not deterministically) fail with such stacktrace:

Java::OrgJanusgraphCore::SchemaViolationException - Adding this property for key [~T$SchemaName] and value [rtprop_incipit] violates a uniqueness constraint [SystemIndex#~T$SchemaName]:
	org.janusgraph.graphdb.transaction.StandardJanusGraphTx.addProperty(org/janusgraph/graphdb/transaction/StandardJanusGraphTx.java:916)
	org.janusgraph.graphdb.transaction.StandardJanusGraphTx.addProperty(org/janusgraph/graphdb/transaction/StandardJanusGraphTx.java:838)
	org.janusgraph.graphdb.transaction.StandardJanusGraphTx.addProperty(org/janusgraph/graphdb/transaction/StandardJanusGraphTx.java:834)
	org.janusgraph.graphdb.transaction.StandardJanusGraphTx.makeSchemaVertex(org/janusgraph/graphdb/transaction/StandardJanusGraphTx.java:970)
	org.janusgraph.graphdb.transaction.StandardJanusGraphTx.makePropertyKey(org/janusgraph/graphdb/transaction/StandardJanusGraphTx.java:989)
	org.janusgraph.graphdb.types.StandardPropertyKeyMaker.make(org/janusgraph/graphdb/types/StandardPropertyKeyMaker.java:114)
	org.janusgraph.core.schema.JanusGraphDefaultSchemaMaker.makePropertyKey(org/janusgraph/core/schema/JanusGraphDefaultSchemaMaker.java:75)
	org.janusgraph.graphdb.transaction.StandardJanusGraphTx.getOrCreatePropertyKey(org/janusgraph/graphdb/transaction/StandardJanusGraphTx.java:1100)
	org.janusgraph.graphdb.vertices.AbstractVertex.property(org/janusgraph/graphdb/vertices/AbstractVertex.java:165)
	org.janusgraph.graphdb.vertices.AbstractVertex.property(org/janusgraph/graphdb/vertices/AbstractVertex.java:160)
	org.janusgraph.core.JanusGraphVertex.property(org/janusgraph/core/JanusGraphVertex.java:72)
	org.janusgraph.graphdb.util.ElementHelper.attachProperties(org/janusgraph/graphdb/util/ElementHelper.java:87)
	org.janusgraph.graphdb.tinkerpop.JanusGraphBlueprintsTransaction.addVertex(org/janusgraph/graphdb/tinkerpop/JanusGraphBlueprintsTransaction.java:128)
	org.janusgraph.graphdb.tinkerpop.JanusGraphBlueprintsTransaction.addVertex(org/janusgraph/graphdb/tinkerpop/JanusGraphBlueprintsTransaction.java:49)
	org.apache.tinkerpop.gremlin.process.traversal.step.map.AddVertexStartStep.processNextStart(org/apache/tinkerpop/gremlin/process/traversal/step/map/AddVertexStartStep.java:102)
	org.apache.tinkerpop.gremlin.process.traversal.step.util.AbstractStep.hasNext(org/apache/tinkerpop/gremlin/process/traversal/step/util/AbstractStep.java:150)
	org.apache.tinkerpop.gremlin.process.traversal.step.util.ExpandableStepIterator.next(org/apache/tinkerpop/gremlin/process/traversal/step/util/ExpandableStepIterator.java:55)
	org.apache.tinkerpop.gremlin.process.traversal.step.filter.FilterStep.processNextStart(org/apache/tinkerpop/gremlin/process/traversal/step/filter/FilterStep.java:37)
	org.apache.tinkerpop.gremlin.process.traversal.step.util.AbstractStep.next(org/apache/tinkerpop/gremlin/process/traversal/step/util/AbstractStep.java:135)
	org.apache.tinkerpop.gremlin.process.traversal.step.util.AbstractStep.next(org/apache/tinkerpop/gremlin/process/traversal/step/util/AbstractStep.java:40)
	org.apache.tinkerpop.gremlin.process.traversal.Traversal.iterate(org/apache/tinkerpop/gremlin/process/traversal/Traversal.java:210)
	org.apache.tinkerpop.gremlin.process.traversal.dsl.graph.GraphTraversal.iterate(org/apache/tinkerpop/gremlin/process/traversal/dsl/graph/GraphTraversal.java:2994)
	org.apache.tinkerpop.gremlin.process.traversal.dsl.graph.GraphTraversal$Admin.iterate(org/apache/tinkerpop/gremlin/process/traversal/dsl/graph/GraphTraversal.java:192)
	org.apache.tinkerpop.gremlin.process.traversal.dsl.graph.DefaultGraphTraversal.iterate(org/apache/tinkerpop/gremlin/process/traversal/dsl/graph/DefaultGraphTraversal.java:48)
	jdk.internal.reflect.GeneratedMethodAccessor18.invoke(jdk/internal/reflect/GeneratedMethodAccessor18)
	jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(jdk/internal/reflect/DelegatingMethodAccessorImpl.java:43)
	java.lang.reflect.Method.invoke(java/lang/reflect/Method.java:564)
	org.jruby.javasupport.JavaMethod.invokeDirectWithExceptionHandling(org/jruby/javasupport/JavaMethod.java:442)
	org.jruby.javasupport.JavaMethod.invokeDirect(org/jruby/javasupport/JavaMethod.java:306)
	RUBY.reindex_nodes(./controllers/api_build_search_graph.rb:143)

The graph does have composite and mixed indices, but non of the composite indices are unique. When adding the properties and vertices sequentially and not hitting the transaction in parallel, we did not encounter this problem. Only when doing this in parallel. Also, the property key ~T$SchemaName seems to be something JanusGraph internal, so I suspect a bug here. Should I open a bug report? I probably won't be able to boil down the problem any further.

Also, might this be related to #3205 ?

best

mrckzgl · 2023-01-18T20:01:04Z

mrckzgl
Jan 18, 2023
Author

And there are even more problems. Running the exact same code (again in parallel) sometimes generates this:

java.lang.IllegalStateException: Vertex with id 442380312 was removed.
	at org.janusgraph.core.InvalidElementException.removedException(org/janusgraph/core/InvalidElementException.java:57)
	at org.janusgraph.graphdb.vertices.AbstractVertex.verifyAccess(org/janusgraph/graphdb/vertices/AbstractVertex.java:98)
	at org.janusgraph.graphdb.vertices.AbstractVertex.query(org/janusgraph/graphdb/vertices/AbstractVertex.java:145)
	at org.janusgraph.graphdb.vertices.AbstractVertex.query(org/janusgraph/graphdb/vertices/AbstractVertex.java:45)
	at org.janusgraph.graphdb.util.ElementHelper.getValues(org/janusgraph/graphdb/util/ElementHelper.java:48)
	at org.janusgraph.graphdb.query.condition.PredicateCondition.evaluate(org/janusgraph/graphdb/query/condition/PredicateCondition.java:66)
	at org.janusgraph.graphdb.query.condition.And.evaluate(org/janusgraph/graphdb/query/condition/And.java:55)
	at org.janusgraph.graphdb.query.graph.GraphCentricQuery.matches(org/janusgraph/graphdb/query/graph/GraphCentricQuery.java:157)
	at com.google.common.collect.Iterators$5.computeNext(com/google/common/collect/Iterators.java:637)
	at com.google.common.collect.AbstractIterator.tryToComputeNext(com/google/common/collect/AbstractIterator.java:141)
	at com.google.common.collect.AbstractIterator.hasNext(com/google/common/collect/AbstractIterator.java:136)
	at org.janusgraph.graphdb.query.QueryProcessor.getUnfoldedIterator(org/janusgraph/graphdb/query/QueryProcessor.java:100)
	at org.janusgraph.graphdb.query.QueryProcessor.iterator(org/janusgraph/graphdb/query/QueryProcessor.java:68)
	at org.janusgraph.graphdb.query.graph.GraphCentricQueryBuilder.lambda$iterables$1(org/janusgraph/graphdb/query/graph/GraphCentricQueryBuilder.java:239)
	at org.janusgraph.graphdb.tinkerpop.optimize.step.JanusGraphStep.lambda$executeGraphCentricQuery$2(org/janusgraph/graphdb/tinkerpop/optimize/step/JanusGraphStep.java:203)
	at org.janusgraph.graphdb.util.ProfiledIterator.<init>(org/janusgraph/graphdb/util/ProfiledIterator.java:36)
	at org.janusgraph.graphdb.tinkerpop.optimize.step.JanusGraphStep.executeGraphCentricQuery(org/janusgraph/graphdb/tinkerpop/optimize/step/JanusGraphStep.java:203)
	at org.janusgraph.graphdb.tinkerpop.optimize.step.JanusGraphStep.lambda$null$0(org/janusgraph/graphdb/tinkerpop/optimize/step/JanusGraphStep.java:106)
	at java.lang.Iterable.forEach(java/lang/Iterable.java:75)
	at org.janusgraph.graphdb.tinkerpop.optimize.step.JanusGraphStep.lambda$new$1(org/janusgraph/graphdb/tinkerpop/optimize/step/JanusGraphStep.java:106)
	at org.apache.tinkerpop.gremlin.process.traversal.step.map.GraphStep.processNextStart(org/apache/tinkerpop/gremlin/process/traversal/step/map/GraphStep.java:157)
	at org.apache.tinkerpop.gremlin.process.traversal.step.util.AbstractStep.hasNext(org/apache/tinkerpop/gremlin/process/traversal/step/util/AbstractStep.java:150)
	at org.apache.tinkerpop.gremlin.process.traversal.step.util.ExpandableStepIterator.next(org/apache/tinkerpop/gremlin/process/traversal/step/util/ExpandableStepIterator.java:55)
	at org.apache.tinkerpop.gremlin.process.traversal.step.filter.FilterStep.processNextStart(org/apache/tinkerpop/gremlin/process/traversal/step/filter/FilterStep.java:37)
	at org.apache.tinkerpop.gremlin.process.traversal.step.util.AbstractStep.hasNext(org/apache/tinkerpop/gremlin/process/traversal/step/util/AbstractStep.java:150)
	at org.apache.tinkerpop.gremlin.process.traversal.step.util.ExpandableStepIterator.next(org/apache/tinkerpop/gremlin/process/traversal/step/util/ExpandableStepIterator.java:55)
	at org.apache.tinkerpop.gremlin.process.traversal.step.filter.FilterStep.processNextStart(org/apache/tinkerpop/gremlin/process/traversal/step/filter/FilterStep.java:37)
	at org.apache.tinkerpop.gremlin.process.traversal.step.util.AbstractStep.next(org/apache/tinkerpop/gremlin/process/traversal/step/util/AbstractStep.java:135)
	at org.apache.tinkerpop.gremlin.process.traversal.step.util.AbstractStep.next(org/apache/tinkerpop/gremlin/process/traversal/step/util/AbstractStep.java:40)
	at org.apache.tinkerpop.gremlin.process.traversal.Traversal.iterate(org/apache/tinkerpop/gremlin/process/traversal/Traversal.java:210)
	at org.apache.tinkerpop.gremlin.process.traversal.dsl.graph.GraphTraversal.iterate(org/apache/tinkerpop/gremlin/process/traversal/dsl/graph/GraphTraversal.java:2994)
	at org.apache.tinkerpop.gremlin.process.traversal.dsl.graph.GraphTraversal$Admin.iterate(org/apache/tinkerpop/gremlin/process/traversal/dsl/graph/GraphTraversal.java:192)
	at org.apache.tinkerpop.gremlin.process.traversal.dsl.graph.DefaultGraphTraversal.iterate(org/apache/tinkerpop/gremlin/process/traversal/dsl/graph/DefaultGraphTraversal.java:48)
	at jdk.internal.reflect.GeneratedMethodAccessor18.invoke(jdk/internal/reflect/GeneratedMethodAccessor18)
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(jdk/internal/reflect/DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(java/lang/reflect/Method.java:564)
	at org.jruby.javasupport.JavaMethod.invokeDirectWithExceptionHandling(org/jruby/javasupport/JavaMethod.java:442)
	at org.jruby.javasupport.JavaMethod.invokeDirect(org/jruby/javasupport/JavaMethod.java:306)
	at RUBY.reindex_nodes(./controllers/api_build_search_graph.rb:102)

The exception is raised at dropping the vertices. The vertices to drop are selected using a mixed index:

dbtx.traversal.v.has("search_nodetype", JanusText.textContains(node_type)).drop.iterate

Where search_nodetype is one key of a mixed Lucene index.

However, the set of vertices each thread drops are / should be totally separate and not overlap.

0 replies

vtslab · 2023-01-19T12:25:02Z

vtslab
Jan 19, 2023

Thanks for reporting. Can you please add the following details:

Does the issue also occur without the config for lock-mode (using the default setting)?
Did you add the schema of the graph explicitly? Either way, can you add the output of mgmt.printSchema()

0 replies

derMart · 2023-01-19T14:05:25Z

derMart
Jan 19, 2023

Thanks alot for the answer.

Yes :-) it seems so far that both issues do not occur in the default lock-mode. Here comes some confusion (I did not personally wrote the configuration): We do specify lock-mode, but this configuration is not even present in the reference: https://docs.janusgraph.org/configs/configuration-reference There only storage.berkeleyje.lock-mode exists. What is going on here? What configuration value sets lock-mode or is this internally mapped to storage.berkeleyje.lock-mode? I suspect we would be ok with a different (=default) lock mode, but which is this? storage.berkeleyje.lock-modeonly mentions LockMode.DEFAULT ...
No, just default automatic schema creation. But really good that you mention this. I am beginning to understand how cardinality is implemented in JanusGraph and that vertex properties have a single cardinality by default, I need to change that for our case as we have multiple values for the same key. Moreover, I am confused as this single cardinality feature does interfere with the Gremlin reference: https://tinkerpop.apache.org/docs/current/reference/#vertex-properties Here it is explicitly stated that Moreover, while an Edge can only have one property of key "name" (for example), a Vertex can have multiple "name" properties. It is not mentioned that this needs to be enabled by configuration or in no way is non standard behavior. The example below in the reference also makes that clear:

gremlin> v = g.addV().property('name','marko').property('name','marko a. rodriguez').next()
==>v[0]
gremlin> g.V(v).properties('name').count() ////
2

EDIT: Output of printSchema would be very verbose, but it is quite simple: All vertex properties have cardinality SINGLE and all of them which the transaction touches are of data type class java.lang.String (only other datatype available is class java.lang.Boolean)

As for the problem here, the .property('prop_name', 'prop_value') steps above do infact add the same property key multiple times. However, if I understand cardinality single correctly this should overwrite a previous value. Also to mention is, that in our case the threads do only writes on distinct set of vertices. So all threads write into the same transaction but no time a write on the same vertex is done from multiple threads.

Another thing I encountered with READ_UNCOMMITED lock-mode but also in a single threaded scenario was that with a reasonable sized transaction (about 80000 vertex writes) the commit call fails with this error:

SEVERE: <DaemonThread name="Checkpointer"/> caught exception, com.sleepycat.je.EnvironmentFailureException: (JE 18.3.12) db Latch timeout.
BIN97725 currentThread: Thread[Checkpointer,5,main] currentTime: 1674083568449 exclusiveOwner: Thread[Ruby-0-Thread-519@puma srv tp 001: /home/martin/.rvm/gems/jruby-9.3.4.0/gems/puma-5.6.4-java/lib/puma/thread_pool.rb:104,5,main] UNEXPECTED_STATE_FATAL: Unexpected internal state, unable to continue. Environment is invalid and must be closed. Exiting
com.sleepycat.je.EnvironmentFailureException: (JE 18.3.12) db_princeton Latch timeout. BIN97725 currentThread: Thread[Checkpointer,5,main] currentTime: 1674083568449 exclusiveOwner: Thread[Ruby-0-Thread-519@puma srv tp 001: /home/martin/.rvm/gems/jruby-9.3.4.0/gems/puma-5.6.4-java/lib/puma/thread_pool.rb:104,5,main] UNEXPECTED_STATE_FATAL: Unexpected internal state, unable to continue. Environment is invalid and must be closed.
	at com.sleepycat.je.EnvironmentFailureException.unexpectedState(EnvironmentFailureException.java:459)
	at com.sleepycat.je.latch.LatchSupport.handleTimeout(LatchSupport.java:211)
	at com.sleepycat.je.latch.LatchImpl.acquireExclusive(LatchImpl.java:63)
	at com.sleepycat.je.latch.LatchImpl.acquireShared(LatchImpl.java:107)
	at com.sleepycat.je.tree.IN.latchShared(IN.java:563)
	at com.sleepycat.je.recovery.DirtyINMap.selectDirtyINsForCheckpoint(DirtyINMap.java:247)
	at com.sleepycat.je.recovery.Checkpointer.doCheckpoint(Checkpointer.java:826)
	at com.sleepycat.je.recovery.Checkpointer.onWakeup(Checkpointer.java:572)
	at com.sleepycat.je.utilint.DaemonThread.run(DaemonThread.java:154)
	at java.base/java.lang.Thread.run(Thread.java:832)

This also went away when switching to the default lock-mode.

To conclude, I suspect a thread safety issue for dropping vertices and adding properties in case of READ_UNCOMMITED lock-mode (which is funny as I would expect such lock-mode as being the least restrict to cause the least issues). I would also suspect a transaction commit issue with READ_UNCOMMITED independent of any user multithreading.

1 reply

derMart Jan 19, 2023

Heh and reading through it again I do see that we have a typo in the configuration *g READ_UNCOMMITED vs READ_UNCOMMITTED ? What does Janusgraph do in that case? Does it set some more strict lock-mode even? Is there some source code link where to see valid values for lock-mode (whatever configuration option that sets)?

vtslab · 2023-01-20T07:14:42Z

vtslab
Jan 20, 2023

Berkeleyje lockmodes are documented here.
Glad to hear that you have a working config now. I appreciate your drive to get to the bottom of this, but unless you are willing to provide a PR yourself it is unlikely that JanusGraph committers can find time to address issues on Berkeleyje as it is merely a demo mode of JanusGraph.
As you describe there are two possible issues involved:

the Berkeleyje storage backend allows for lock-mode values that are not compatible with JanusGraph ThreadedTransactions
undefined configuration key and values can pass the parsing and create havoc later on. If documented properly with a reproducible example this would be valuable as an issue in the issues section.

0 replies

mrckzgl · 2023-01-20T13:42:31Z

mrckzgl
Jan 20, 2023
Author

I am afraid, we now also encountered the Adding this property for key [~T$SchemaName] and value [rtprop_incipit] violates a uniqueness constraint kind of exceptions when using default (=from us not specified) lock-mode in a concurrent setting as described above.

1 reply

mrckzgl Jan 20, 2023
Author

Things changed a bit though in our graph schema. We not also use LIST and SET cardinality for the vertex properties which are written by the transaction.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Possible Bug: unique constraint violation while adding non unique vertex properties in threaded transaction concurrently #3470

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 5 comments 2 replies

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

Select a reply

Possible Bug: unique constraint violation while adding non unique vertex properties in threaded transaction concurrently #3470

mrckzgl Jan 18, 2023

Replies: 5 comments · 2 replies

mrckzgl Jan 18, 2023 Author

vtslab Jan 19, 2023

derMart Jan 19, 2023

derMart Jan 19, 2023

vtslab Jan 20, 2023

mrckzgl Jan 20, 2023 Author

mrckzgl Jan 20, 2023 Author

mrckzgl
Jan 18, 2023

Replies: 5 comments 2 replies

mrckzgl
Jan 18, 2023
Author

vtslab
Jan 19, 2023

derMart
Jan 19, 2023

vtslab
Jan 20, 2023

mrckzgl
Jan 20, 2023
Author

mrckzgl Jan 20, 2023
Author