Titan/DynamoDb не освобождает все полученные блокировки при фиксации (через гремлин)

Хорошо, я понимаю, что это звучит маловероятно, и я готов разочароваться в этом, но вот...

У меня есть сервер Gremlin, работающий против titanDB и DynamoDB (локальный). Я запускаю некоторые модульные тесты, которые продолжают терпеть неудачу из-за

tx 0x705eafda280e already locked key-column (  8-  0-  0-  0-  0-  0-  0-128, 80-160) when tx 0x70629e1d56bf tried to lock

Я запускаю следующие команды в клиентской консоли Gremlin для чистой, совершенно пустой БД (воссозданной между тестовыми прогонами с использованием образов докеров). Целью этой работы является поддержка сценариев обновления базы данных. Первоначальные фактические шаги были более полными, чем приведенные ниже, но это минимум для воспроизведения проблемы.

(Connect to local 'remote')
:remote connect tinkerpop.server conf/remote.yaml

(Add a unique constraint on a 'databaseMetadata' label which has a single 'version' property)
:> mgmt = graph.openManagement();if (!mgmt.getGraphIndex("bydatabaseMetadataversion")) {graph.tx().rollback();int size = graph.getOpenTransactions().size();for (i = 0; i < size; i++) { try { graph.getOpenTransactions().getAt(0).rollback();} catch(Throwable ex) { }; }; mgmt = graph.openManagement();propertyKey = (!mgmt.containsPropertyKey("version")) ? mgmt.makePropertyKey("version").dataType(String.class).cardinality(Cardinality.SINGLE).make():mgmt.getPropertyKey("version");labelObj = (!mgmt.containsVertexLabel("databaseMetadata")) ? mgmt.makeVertexLabel("databaseMetadata").make():mgmt.getVertexLabel("databaseMetadata");index = mgmt.buildIndex("bydatabaseMetadataversion", Vertex.class).addKey(propertyKey).unique().indexOnly(labelObj).buildCompositeIndex();mgmt.setConsistency(propertyKey, ConsistencyModifier.LOCK);mgmt.setConsistency(index, ConsistencyModifier.LOCK);mgmt.commit();mgmt = graph.openManagement();index = mgmt.getGraphIndex("bydatabaseMetadataversion");propertyKey = mgmt.getPropertyKey("version");if (index.getIndexStatus(propertyKey) == SchemaStatus.INSTALLED) {mgmt.awaitGraphIndexStatus(graph, "bydatabaseMetadataversion").status(SchemaStatus.REGISTERED).timeout(10, java.time.temporal.ChronoUnit.MINUTES).call();}; mgmt.commit();mgmt = graph.openManagement();index = mgmt.getGraphIndex("bydatabaseMetadataversion");propertyKey = mgmt.getPropertyKey("version");if (index.getIndexStatus(propertyKey) != SchemaStatus.ENABLED) {mgmt.commit();mgmt = graph.openManagement();mgmt.updateIndex(mgmt.getGraphIndex("bydatabaseMetadataversion"), SchemaAction.ENABLE_INDEX).get();mgmt.commit();mgmt = graph.openManagement();mgmt.awaitGraphIndexStatus(graph, "bydatabaseMetadataversion").status(SchemaStatus.ENABLED).timeout(10, java.time.temporal.ChronoUnit.MINUTES).call();}; mgmt.commit();} else {index = mgmt.getGraphIndex("bydatabaseMetadataversion");propertyKey = mgmt.getPropertyKey("version");if (index.getIndexStatus(propertyKey) != SchemaStatus.ENABLED) {mgmt.awaitGraphIndexStatus(graph, "bydatabaseMetadataversion").status(SchemaStatus.ENABLED).timeout(10, java.time.temporal.ChronoUnit.MINUTES).call();}; mgmt.commit();};

(Add the metadata vertex with initial version '0.0.1')
:> graph.addVertex(label, "databaseMetadata").property("version", "0.0.1");graph.tx().commit();

(Update the metadata vertex with the next version - 0.0.2)
:> g.V().hasLabel("databaseMetadata").has("version", "0.0.1").property("version", "0.0.2").next();g.tx().commit();

(THIS FAILS - Update the metadata vertex with the next version - 0.0.3)
:> g.V().hasLabel("databaseMetadata").has("version", "0.0.2").property("version", "0.0.3").next();g.tx().commit();
tx 0x705eafda280e already locked key-column (  8-  0-  0-  0-  0-  0-  0-128, 80-160) when tx 0x70629e1d56bf tried to lock

Ранее я просмотрел исходный код titan-dynamodb и увидел, что фиксации/откаты и т. д. транзакций регистрируются, поэтому я изменил уровень журнала, чтобы получить дополнительную информацию (доступен полный файл журнала).

При выполнении обновления 0.0.1 -> 0.0.2 были получены следующие блокировки:

[33mtitan_server_1  |[0m 120479 [gremlin-server-exec-3] TRACE com.amazon.titan.diskstorage.dynamodb.AbstractDynamoDBStore  - acquiring lock on (  8-  0-  0-  0-  0-  0-  0-128, 80-160) at 123552624951495
[33mtitan_server_1  |[0m 120489 [gremlin-server-exec-3] TRACE com.amazon.titan.diskstorage.dynamodb.AbstractDynamoDBStore  - acquiring lock on (  6-137-160- 48- 46- 48- 46-177,  0) at 123552635424334
[33mtitan_server_1  |[0m 120489 [gremlin-server-exec-3] TRACE com.amazon.titan.diskstorage.dynamodb.AbstractDynamoDBStore  - acquiring lock on (  6-137-160- 48- 46- 48- 46-178,  0) at 123552635704705

Когда эта транзакция была зафиксирована, были освобождены только ДВЕ блокировки.

[33mtitan_server_1  |[0m 120722 [gremlin-server-exec-3] DEBUG com.amazon.titan.diskstorage.dynamodb.DynamoDBStoreTransaction  - commit id:0x705eafda280e
[33mtitan_server_1  |[0m 120722 [gremlin-server-exec-3] TRACE com.amazon.titan.diskstorage.dynamodb.AbstractDynamoDBStore  - Expiring (  6-137-160- 48- 46- 48- 46-177,  0) in tx 0x705eafda280e because of EXPLICIT
[33mtitan_server_1  |[0m 120722 [gremlin-server-exec-3] TRACE com.amazon.titan.diskstorage.dynamodb.AbstractDynamoDBStore  - Expiring (  6-137-160- 48- 46- 48- 46-178,  0) in tx 0x705eafda280e because of EXPLICIT
[33mtitan_server_1  |[0m 120722 [gremlin-server-exec-3] DEBUG org.apache.tinkerpop.gremlin.server.op.AbstractEvalOpProcessor  - Preparing to iterate results from - RequestMessage{, requestId=09f27811-dcc3-4e53-a749-22828d34997f, op='eval', processor='', args={gremlin=g.V().hasLabel("databaseMetadata").has("version", "0.0.1").property("version", "0.0.2").next();g.tx().commit();, batchSize=64}} - in thread [gremlin-server-exec-3]

Срок действия оставшейся блокировки истекает через несколько минут, но в то же время каждое второе обновление завершается сбоем, как сообщается.

Итак, почему этот замок не снимается? Я подозреваю, что это связано с созданным уникальным индексом, поэтому я либо неправильно настроил индекс (хорошая возможность), либо это ошибка.

Для простоты использования (слегка укороченная) установка индекса приведена ниже:

mgmt = graph.openManagement()
propertyKey = (!mgmt.containsPropertyKey("version")) ? mgmt.makePropertyKey("version").dataType(String.class).cardinality(Cardinality.SINGLE).make():mgmt.getPropertyKey("version")
labelObj = (!mgmt.containsVertexLabel("databaseMetadata")) ? mgmt.makeVertexLabel("databaseMetadata").make():mgmt.getVertexLabel("databaseMetadata")
index = mgmt.buildIndex("bydatabaseMetadataversion", Vertex.class).addKey(propertyKey).unique().indexOnly(labelObj).buildCompositeIndex()
mgmt.setConsistency(propertyKey, ConsistencyModifier.LOCK)
mgmt.setConsistency(index, ConsistencyModifier.LOCK)
mgmt.commit()
mgmt = graph.openManagement()
index = mgmt.getGraphIndex("bydatabaseMetadataversion")
propertyKey = mgmt.getPropertyKey("version")
if (index.getIndexStatus(propertyKey) == SchemaStatus.INSTALLED) {
  mgmt.awaitGraphIndexStatus(graph, "bydatabaseMetadataversion").status(SchemaStatus.REGISTERED).timeout(10, java.time.temporal.ChronoUnit.MINUTES).call()
}
mgmt.commit()
mgmt = graph.openManagement()
index = mgmt.getGraphIndex("bydatabaseMetadataversion")
propertyKey = mgmt.getPropertyKey("version")
if (index.getIndexStatus(propertyKey) != SchemaStatus.ENABLED) {
  mgmt.commit()
  mgmt = graph.openManagement()
  mgmt.updateIndex(mgmt.getGraphIndex("bydatabaseMetadataversion"), SchemaAction.ENABLE_INDEX).get()
  mgmt.commit()
  mgmt = graph.openManagement()
  mgmt.awaitGraphIndexStatus(graph, "bydatabaseMetadataversion").status(SchemaStatus.ENABLED).timeout(10, java.time.temporal.ChronoUnit.MINUTES).call()
}
mgmt.commit()

Я знаю, что это ДЛИННОЕ описание проблемы, но любая помощь будет принята с благодарностью!

(Я также должен сказать, что я пробовал это против локальных и облачных экземпляров DynamoDb и имел ту же проблему на обоих, поэтому вернулся к локальному и включил ведение журнала.)

Я использую титан 1.0.0 и tinkerpop 3, как указано в dynamo-titan на github< /а>.


person John Stephenson    schedule 07.02.2017    source источник
comment
Вы можете дополнительно регистрировать «номер шага» после каждого оператора вашего кода настройки индекса, чтобы увидеть, какой оператор получает и какой оператор освобождает какую блокировку. Это может привести вас к одному оператору блокировки, у которого нет соответствующего оператора освобождения. Тогда опубликуйте это здесь.   -  person Double M    schedule 10.02.2017
comment
Спасибо за ответ, но я не уверен, что понимаю вас. Индексы создаются... затем проходит время... только при запуске обновления "0.0.1 -> 0.0.2" проблемная блокировка приобретается. Можете ли вы привести пример регистрации «номера шага» в контексте вышеизложенного? Я бы понял, что эта проблема возникает, если бы у меня не было нужного количества коммитов/откатов, но AFAICT я их покрыл.   -  person John Stephenson    schedule 10.02.2017
comment
Кто-нибудь может подтвердить правильность шагов по созданию индекса?   -  person John Stephenson    schedule 10.02.2017
comment
Я понимаю. Вы уверены, что эти записи журнала определенно созданы двумя последними операторами вашего кода? Это все однопоточно? Кстати, вы также можете хранить метаданные непосредственно на графике, но я не не знаю, будет ли это поддерживать индексацию. Номер шага примера: statement1; log.info(i++); statement2; log.info(i++)... просто чтобы узнать, когда происходит блокировка/разблокировка   -  person Double M    schedule 10.02.2017
comment
Ваша индексация выглядит очень хорошо. Не могли бы вы попробовать это? g.V().hasLabel("databaseMetadata").has("version", "0.0.2").property("version", "0.0.3").iterate(); для версий от 0.0.1 до 0.0.2 и от 0.0.2 до 0.0.3, с commit() после каждого.   -  person Double M    schedule 10.02.2017
comment
Я довольно уверен относительно утверждений. Определенно однопоточный, когда я перезапустился, очистил БД (содержащую докер) и выполнил команды вручную в консоли гремлина. Ничто другое не работало против (локальной) БД в то время... ....попробую ваше предложение....   -  person John Stephenson    schedule 10.02.2017
comment
Давайте продолжим обсуждение в чате.   -  person John Stephenson    schedule 10.02.2017


Ответы (2)


Я получил репродукцию и нашел вашу проблему. По сути, кеш LRU получает время истечения срока действия из конфигурации storage.lock.expiry-time. По умолчанию это 5 минут, поэтому, если вы попытаетесь внести изменения до истечения 5 минут, кэш LRU AbstractDynamoDBStore.keyColumnLocalLocks не позволит вам внести второе изменение. Сокращая время истечения срока действия и Thread.sleep() перед внесением второго изменения, вы позволяете второму изменению снова потребовать блокировку и добиться успеха.

//default lock expiry time is 300*1000 ms = 5 minutes. Set to 100ms.
config.setProperty("storage.lock.expiry-time", 100);
person Alexander Patrikalakis    schedule 02.05.2017
comment
Если вы согласны с моим повторить здесь, пожалуйста, примите и этот ответ :) - person Alexander Patrikalakis; 03.05.2017
comment
github.com/awslabs/dynamodb-titan-storage-backend/blob/master/ - person Alexander Patrikalakis; 04.05.2017
comment
Я принял это, как после установки его в моем файле свойств (в отличие от кода) с помощью: storage.lock.expiry-time=100. Хотя у меня есть вопрос о том, почему тайм-аут исправляет это, поскольку я ожидаю, что блокировки столбцов будут сняты с фиксацией/откатом, иначе кажется вероятным, что это, вероятно, может происходить снова с перерывами. - person John Stephenson; 02.06.2017
comment
Я создал задачу в проекте, чтобы отслеживать вопрос об снятии блокировок при фиксации. ()/откат() - person Alexander Patrikalakis; 06.07.2017
comment
Я считаю, что решил проблему с блокировками, которые не освобождаются в той же JVM в мое недавнее исправление. - person Alexander Patrikalakis; 30.07.2017

F.y.i. Я запустил весь приведенный выше код на Java, используя серверную часть хранилища Berkeley.

TitanGraph graph = ...;
TitanManagement mgmt = graph.openManagement();
PropertyKey propertyKey = (!mgmt.containsPropertyKey("version"))
        ? mgmt.makePropertyKey("version").dataType(String.class).cardinality(Cardinality.SINGLE).make()
        : mgmt.getPropertyKey("version");
VertexLabel labelObj = (!mgmt.containsVertexLabel("databaseMetadata"))
        ? mgmt.makeVertexLabel("databaseMetadata").make() 
        : mgmt.getVertexLabel("databaseMetadata");
TitanGraphIndex index = mgmt.buildIndex("bydatabaseMetadataversion", Vertex.class).addKey(propertyKey).unique()
        .indexOnly(labelObj).buildCompositeIndex();
mgmt.setConsistency(propertyKey, ConsistencyModifier.LOCK);
mgmt.setConsistency(index, ConsistencyModifier.LOCK);
mgmt.commit();
mgmt = graph.openManagement();
index = mgmt.getGraphIndex("bydatabaseMetadataversion");
propertyKey = mgmt.getPropertyKey("version");
if (index.getIndexStatus(propertyKey) == SchemaStatus.INSTALLED) {
    try {
        ManagementSystem.awaitGraphIndexStatus(graph,"bydatabaseMetadataversion").status(SchemaStatus.REGISTERED).timeout(10, java.time.temporal.ChronoUnit.MINUTES).call();
    } catch (InterruptedException e) {
        e.printStackTrace();
    }
}
mgmt.commit();
mgmt = graph.openManagement();
index = mgmt.getGraphIndex("bydatabaseMetadataversion");
propertyKey = mgmt.getPropertyKey("version");
if (index.getIndexStatus(propertyKey) != SchemaStatus.ENABLED) {
    mgmt.commit();
    mgmt = graph.openManagement();
    try {
        mgmt.updateIndex(mgmt.getGraphIndex("bydatabaseMetadataversion"), SchemaAction.ENABLE_INDEX).get();
    } catch (InterruptedException | ExecutionException e) {
        e.printStackTrace();
    }
    mgmt.commit();
    mgmt = graph.openManagement();
    try {
        ManagementSystem.awaitGraphIndexStatus(graph, "bydatabaseMetadataversion").status(SchemaStatus.ENABLED)
                        .timeout(10, java.time.temporal.ChronoUnit.MINUTES).call();
    } catch (InterruptedException e) {
        e.printStackTrace();
    }
}
mgmt.commit();

Затем операции над графом;

GraphTraversalSource g = graph.traversal();

graph.addVertex("databaseMetadata").property("version", "0.0.1");
graph.tx().commit();

g.V().hasLabel("databaseMetadata").has("version", "0.0.1").property("version", "0.0.2").iterate();
g.tx().commit();

g.V().hasLabel("databaseMetadata").has("version", "0.0.1").property("version", "0.0.2").iterate();
g.tx().commit();

g.V().hasLabel("databaseMetadata").has("version", "0.0.2").property("version", "0.0.3").iterate();
g.tx().commit();

g.V().hasLabel("databaseMetadata").has("version").properties("version").forEachRemaining(prop -> {
    System.out.println("Version: " + prop.value());
});

В результате:

Version: 0.0.3

К сожалению, iterate() изменение вашего запроса применимо только к Java. Ваши скрипты должны работать так, как они есть. Из-за результатов моего эксперимента я сильно подозреваю, что проблемы вызывает серверная часть DynamoDB.

person Double M    schedule 10.02.2017
comment
Спасибо за ваши усилия - я пропингую ребят из DynamoDB и отчитаюсь... - person John Stephenson; 10.02.2017
comment
К сведению: это проблема на github - person John Stephenson; 13.02.2017
comment
Спасибо, выглядит хорошо. Я буду следить за этим. Было бы неплохо, если бы вы также опубликовали результат здесь, как только он, надеюсь, будет решен. - person Double M; 13.02.2017
comment
обязательно сделаю :-) - person John Stephenson; 13.02.2017
comment
К вашему сведению, отсюда звучит так, что Титан отправится в Janus Graph (ветвь). Я не уверен, что это значит для чего-либо, но было бы хорошо, если бы Amazon сообщил людям, читающим их блестящие страницы titan/dynamoDb!?! - person John Stephenson; 15.02.2017