Reindexing index in empty DB sometimes is too slow

[Alexandr Porunov]

Hello,

I am creating indexes in an empty database. 

The flow looks like this:

graph.tx().rollback();

mgmt = graph.openManagement();

Index index = mgmt.buildIndex("my_index", Vertex.class)

                .addKey(myPropertyKey)

                .addKey(myPropertyKey1)

                .addKey(myPropertyKey2)

                .indexOnly(myVertexLabel)

                .buildMixedIndex("search");

mgmt.commit();

ManagementSystem.awaitGraphIndexStatus(graph, "my_index").call();

mgmt = graph.openManagement();

mgmt.updateIndex(mgmt.getGraphIndex("my_index"), SchemaAction.REINDEX).get(); // Sometimes reindexing of empty DB takes 3 minutes

mgmt.commit();

Also, when the reindexing is running I am shown with some logger errors, but after 3 minutes reindexing is successfully finished:

""2018-06-10 09:03:19 [Thread-11] ERROR o.j.g.d.management.ManagementLogger - Evicted [2@6d56b8c524955-pc-jblur-com3] from cache but waiting too long for transactions to close. Stale transaction alert on: [standardjanusgraphtx[0x67a3ba21], standardjanusgraphtx[0x6cf78315], standardjanusgraphtx[0x48ce7bcd], standardjanusgraphtx[0x1862c45e], standardjanusgraphtx[0x04c1309d], standardjanusgraphtx[0x13bda0b2], standardjanusgraphtx[0x1187c9e8]]

""2018-06-10 09:03:19 [Thread-15] ERROR o.j.g.d.management.ManagementLogger - Evicted [6@6d56b8c524955-pc-jblur-com3] from cache but waiting too long for transactions to close. Stale transaction alert on: [standardjanusgraphtx[0x67a3ba21], standardjanusgraphtx[0x6cf78315], standardjanusgraphtx[0x48ce7bcd], standardjanusgraphtx[0x1862c45e], standardjanusgraphtx[0x04c1309d], standardjanusgraphtx[0x13bda0b2], standardjanusgraphtx[0x1187c9e8]]

""2018-06-10 09:03:19 [Thread-16] ERROR o.j.g.d.management.ManagementLogger - Evicted [7@6d56b8c524955-pc-jblur-com3] from cache but waiting too long for transactions to close. Stale transaction alert on: [standardjanusgraphtx[0x67a3ba21], standardjanusgraphtx[0x6cf78315], standardjanusgraphtx[0x48ce7bcd], standardjanusgraphtx[0x1862c45e], standardjanusgraphtx[0x04c1309d], standardjanusgraphtx[0x13bda0b2], standardjanusgraphtx[0x1187c9e8]]

""2018-06-10 09:03:19 [Thread-14] ERROR o.j.g.d.management.ManagementLogger - Evicted [5@6d56b8c524955-pc-jblur-com3] from cache but waiting too long for transactions to close. Stale transaction alert on: [standardjanusgraphtx[0x67a3ba21], standardjanusgraphtx[0x6cf78315], standardjanusgraphtx[0x48ce7bcd], standardjanusgraphtx[0x1862c45e], standardjanusgraphtx[0x04c1309d], standardjanusgraphtx[0x13bda0b2], standardjanusgraphtx[0x1187c9e8]]

Also, what I've noticed. It doesn't matter what is the type of the index (i.e. Mixed or Composite) and it doesn't matter how much PropertyKeys it has. Every time I create indexes the first index to be reindexed is stuck for 3 minutes with logger errors (which are seen above). And sometimes my 5th (last) index is also stuck for 3 minutes with the same errors. Again, I tried different combination of indexes. Indexes which are reindexed after the first index are fast. It takes less than a second to reindex 3-4 indexes after the first one. Also, I've noticed that logger errors are shown exactly after 1 minute and the index is successfully reindexes exactly after 3 minutes (doesn't matter what keys I am using, how many keys are there and what is the type of the index).

Also, I am reindexing all indexes in single JanusGraph Management transaction.

Does anyone know why is it happening?

Best regards,

Alexandr

[chris....@gmail.com]

You might want to check that there aren't any other open mgmt transactions. Sometimes if JanusGraph doesn't shut down properly you'll get extra open instances. Instructions on how to find and identify and close these instances can be found in the failure recovery doc. 

gremlin> mgmt.getOpenInstances()

==>0934f2eb69223-Chriss-MacBook-Pro-2-local2(current)

If you don't have multiple open mgmt instances check transactions. I've also had issues with reindexing when I have multiple open transactions so I've been checking to see if I have multiple transactions and rolling them back to make sure I only have 1 open before I do any indexing operations. 

gremlin> graph.getOpenTransactions()

==>standardjanusgraphtx[0x14ba9376]

==>standardjanusgraphtx[0x477aaf55]

To rollback a transaction you can run the command below.

graph.getOpenTransactions().getAt(0).rollback()

You'll want to set mgmt = graph.openManagement(); after you rollback all the OpenTransactions since it'll be unbound. I found a thread with different indexing issues caused by open transactions https://groups.google.com/forum/#!msg/janusgraph-users/ha2HaWkdGMY/nJsL6-7eBAAJ

[Alexandr Porunov]

Hello Chris,

Thank you very much for your response! 

I tried this method but I always have only 1 opened instance (current). I still didn't figure out why is it happens.

Best regards,

Alexandr

[dengzim...@gmail.com]

this is because reindex process contains multi-thread , the thread to get data from Empty DB can't fetch any data, so it will try for 3 min, i will fix this bug in the future.

i think you can create property and index in one transaction without reindex process according to the janusgraph docs to avoid this problem if the DB is empty.

[Alexandr Porunov]

Thank you very much for the help!

Could you please open an issue for it so it could be tracked?

Best regards,

Alexandr

[Alexandr Porunov]

I have created an issue to tack this bug: https://github.com/JanusGraph/janusgraph/issues/1157

[dengzim...@gmail.com]

ok, i have created a merge request to fix this problem: https://github.com/JanusGraph/janusgraph/pull/1162

this will be fixed in the future.