use of com.thinkaurelius.titan.core.log.ChangeState in project titan by thinkaurelius.
the class TitanGraphTest method simpleLogTest.
public void simpleLogTest(final boolean withLogFailure) throws InterruptedException {
final String userlogName = "test";
final Serializer serializer = graph.getDataSerializer();
final EdgeSerializer edgeSerializer = graph.getEdgeSerializer();
final TimestampProvider times = graph.getConfiguration().getTimestampProvider();
final Instant startTime = times.getTime();
clopen(option(SYSTEM_LOG_TRANSACTIONS), true, option(LOG_BACKEND, USER_LOG), (withLogFailure ? TestMockLog.class.getName() : LOG_BACKEND.getDefaultValue()), option(TestMockLog.LOG_MOCK_FAILADD, USER_LOG), withLogFailure, option(KCVSLog.LOG_READ_LAG_TIME, USER_LOG), Duration.ofMillis(50), option(LOG_READ_INTERVAL, USER_LOG), Duration.ofMillis(250), option(LOG_SEND_DELAY, USER_LOG), Duration.ofMillis(100), option(KCVSLog.LOG_READ_LAG_TIME, TRANSACTION_LOG), Duration.ofMillis(50), option(LOG_READ_INTERVAL, TRANSACTION_LOG), Duration.ofMillis(250), option(MAX_COMMIT_TIME), Duration.ofSeconds(1));
final String instanceid = graph.getConfiguration().getUniqueGraphId();
PropertyKey weight = tx.makePropertyKey("weight").dataType(Float.class).cardinality(Cardinality.SINGLE).make();
EdgeLabel knows = tx.makeEdgeLabel("knows").make();
TitanVertex n1 = tx.addVertex("weight", 10.5);
newTx();
final Instant[] txTimes = new Instant[4];
//Transaction with custom userlog name
txTimes[0] = times.getTime();
TitanTransaction tx2 = graph.buildTransaction().logIdentifier(userlogName).start();
TitanVertex v1 = tx2.addVertex("weight", 111.1);
v1.addEdge("knows", v1);
tx2.commit();
final long v1id = getId(v1);
txTimes[1] = times.getTime();
tx2 = graph.buildTransaction().logIdentifier(userlogName).start();
TitanVertex v2 = tx2.addVertex("weight", 222.2);
v2.addEdge("knows", getV(tx2, v1id));
tx2.commit();
final long v2id = getId(v2);
//Only read tx
tx2 = graph.buildTransaction().logIdentifier(userlogName).start();
v1 = getV(tx2, v1id);
assertEquals(111.1, v1.<Float>value("weight").doubleValue(), 0.01);
assertEquals(222.2, getV(tx2, v2).<Float>value("weight").doubleValue(), 0.01);
tx2.commit();
//Deleting transaction
txTimes[2] = times.getTime();
tx2 = graph.buildTransaction().logIdentifier(userlogName).start();
v2 = getV(tx2, v2id);
assertEquals(222.2, v2.<Float>value("weight").doubleValue(), 0.01);
v2.remove();
tx2.commit();
//Edge modifying transaction
txTimes[3] = times.getTime();
tx2 = graph.buildTransaction().logIdentifier(userlogName).start();
v1 = getV(tx2, v1id);
assertEquals(111.1, v1.<Float>value("weight").doubleValue(), 0.01);
Edge e = getOnlyElement(v1.query().direction(Direction.OUT).labels("knows").edges());
assertFalse(e.property("weight").isPresent());
e.property("weight", 44.4);
tx2.commit();
close();
final Instant endTime = times.getTime();
final ReadMarker startMarker = ReadMarker.fromTime(startTime);
Log txlog = openTxLog();
Log userLog = openUserLog(userlogName);
final EnumMap<LogTxStatus, AtomicInteger> txMsgCounter = new EnumMap<LogTxStatus, AtomicInteger>(LogTxStatus.class);
for (LogTxStatus status : LogTxStatus.values()) txMsgCounter.put(status, new AtomicInteger(0));
final AtomicInteger userlogMeta = new AtomicInteger(0);
txlog.registerReader(startMarker, new MessageReader() {
@Override
public void read(Message message) {
Instant msgTime = message.getTimestamp();
assertTrue(msgTime.isAfter(startTime) || msgTime.equals(startTime));
assertNotNull(message.getSenderId());
TransactionLogHeader.Entry txEntry = TransactionLogHeader.parse(message.getContent(), serializer, times);
TransactionLogHeader header = txEntry.getHeader();
// System.out.println(header.getTimestamp(TimeUnit.MILLISECONDS));
assertTrue(header.getTimestamp().isAfter(startTime) || header.getTimestamp().equals(startTime));
assertTrue(header.getTimestamp().isBefore(msgTime) || header.getTimestamp().equals(msgTime));
assertNotNull(txEntry.getMetadata());
assertNull(txEntry.getMetadata().get(LogTxMeta.GROUPNAME));
LogTxStatus status = txEntry.getStatus();
if (status == LogTxStatus.PRECOMMIT) {
assertTrue(txEntry.hasContent());
Object logid = txEntry.getMetadata().get(LogTxMeta.LOG_ID);
if (logid != null) {
assertTrue(logid instanceof String);
assertEquals(userlogName, logid);
userlogMeta.incrementAndGet();
}
} else if (withLogFailure) {
assertTrue(status.isPrimarySuccess() || status == LogTxStatus.SECONDARY_FAILURE);
if (status == LogTxStatus.SECONDARY_FAILURE) {
TransactionLogHeader.SecondaryFailures secFail = txEntry.getContentAsSecondaryFailures(serializer);
assertTrue(secFail.failedIndexes.isEmpty());
assertTrue(secFail.userLogFailure);
}
} else {
assertFalse(txEntry.hasContent());
assertTrue(status.isSuccess());
}
txMsgCounter.get(txEntry.getStatus()).incrementAndGet();
}
});
final EnumMap<Change, AtomicInteger> userChangeCounter = new EnumMap<Change, AtomicInteger>(Change.class);
for (Change change : Change.values()) userChangeCounter.put(change, new AtomicInteger(0));
final AtomicInteger userLogMsgCounter = new AtomicInteger(0);
userLog.registerReader(startMarker, new MessageReader() {
@Override
public void read(Message message) {
Instant msgTime = message.getTimestamp();
assertTrue(msgTime.isAfter(startTime) || msgTime.equals(startTime));
assertNotNull(message.getSenderId());
StaticBuffer content = message.getContent();
assertTrue(content != null && content.length() > 0);
TransactionLogHeader.Entry txentry = TransactionLogHeader.parse(content, serializer, times);
Instant txTime = txentry.getHeader().getTimestamp();
assertTrue(txTime.isBefore(msgTime) || txTime.equals(msgTime));
assertTrue(txTime.isAfter(startTime) || txTime.equals(msgTime));
long txid = txentry.getHeader().getId();
assertTrue(txid > 0);
for (TransactionLogHeader.Modification modification : txentry.getContentAsModifications(serializer)) {
assertTrue(modification.state == Change.ADDED || modification.state == Change.REMOVED);
userChangeCounter.get(modification.state).incrementAndGet();
}
userLogMsgCounter.incrementAndGet();
}
});
Thread.sleep(4000);
assertEquals(5, txMsgCounter.get(LogTxStatus.PRECOMMIT).get());
assertEquals(4, txMsgCounter.get(LogTxStatus.PRIMARY_SUCCESS).get());
assertEquals(1, txMsgCounter.get(LogTxStatus.COMPLETE_SUCCESS).get());
assertEquals(4, userlogMeta.get());
if (withLogFailure)
assertEquals(4, txMsgCounter.get(LogTxStatus.SECONDARY_FAILURE).get());
else
assertEquals(4, txMsgCounter.get(LogTxStatus.SECONDARY_SUCCESS).get());
//User-Log
if (withLogFailure) {
assertEquals(0, userLogMsgCounter.get());
} else {
assertEquals(4, userLogMsgCounter.get());
assertEquals(7, userChangeCounter.get(Change.ADDED).get());
assertEquals(4, userChangeCounter.get(Change.REMOVED).get());
}
clopen(option(VERBOSE_TX_RECOVERY), true);
/*
Transaction Recovery
*/
TransactionRecovery recovery = TitanFactory.startTransactionRecovery(graph, startTime);
/*
Use user log processing framework
*/
final AtomicInteger userLogCount = new AtomicInteger(0);
LogProcessorFramework userlogs = TitanFactory.openTransactionLog(graph);
userlogs.addLogProcessor(userlogName).setStartTime(startTime).setRetryAttempts(1).addProcessor(new ChangeProcessor() {
@Override
public void process(TitanTransaction tx, TransactionId txId, ChangeState changes) {
assertEquals(instanceid, txId.getInstanceId());
//Just some reasonable upper bound
assertTrue(txId.getTransactionId() > 0 && txId.getTransactionId() < 100);
final Instant txTime = txId.getTransactionTime();
assertTrue(String.format("tx timestamp %s not between start %s and end time %s", txTime, startTime, endTime), //Times should be within a second
(txTime.isAfter(startTime) || txTime.equals(startTime)) && (txTime.isBefore(endTime) || txTime.equals(endTime)));
assertTrue(tx.containsRelationType("knows"));
assertTrue(tx.containsRelationType("weight"));
EdgeLabel knows = tx.getEdgeLabel("knows");
PropertyKey weight = tx.getPropertyKey("weight");
Instant txTimeMicro = txId.getTransactionTime();
int txNo;
if (txTimeMicro.isBefore(txTimes[1])) {
txNo = 1;
//v1 addition transaction
assertEquals(1, Iterables.size(changes.getVertices(Change.ADDED)));
assertEquals(0, Iterables.size(changes.getVertices(Change.REMOVED)));
assertEquals(1, Iterables.size(changes.getVertices(Change.ANY)));
assertEquals(2, Iterables.size(changes.getRelations(Change.ADDED)));
assertEquals(1, Iterables.size(changes.getRelations(Change.ADDED, knows)));
assertEquals(1, Iterables.size(changes.getRelations(Change.ADDED, weight)));
assertEquals(2, Iterables.size(changes.getRelations(Change.ANY)));
assertEquals(0, Iterables.size(changes.getRelations(Change.REMOVED)));
TitanVertex v = Iterables.getOnlyElement(changes.getVertices(Change.ADDED));
assertEquals(v1id, getId(v));
VertexProperty<Float> p = Iterables.getOnlyElement(changes.getProperties(v, Change.ADDED, "weight"));
assertEquals(111.1, p.value().doubleValue(), 0.01);
assertEquals(1, Iterables.size(changes.getEdges(v, Change.ADDED, OUT)));
assertEquals(1, Iterables.size(changes.getEdges(v, Change.ADDED, BOTH)));
} else if (txTimeMicro.isBefore(txTimes[2])) {
txNo = 2;
//v2 addition transaction
assertEquals(1, Iterables.size(changes.getVertices(Change.ADDED)));
assertEquals(0, Iterables.size(changes.getVertices(Change.REMOVED)));
assertEquals(2, Iterables.size(changes.getVertices(Change.ANY)));
assertEquals(2, Iterables.size(changes.getRelations(Change.ADDED)));
assertEquals(1, Iterables.size(changes.getRelations(Change.ADDED, knows)));
assertEquals(1, Iterables.size(changes.getRelations(Change.ADDED, weight)));
assertEquals(2, Iterables.size(changes.getRelations(Change.ANY)));
assertEquals(0, Iterables.size(changes.getRelations(Change.REMOVED)));
TitanVertex v = Iterables.getOnlyElement(changes.getVertices(Change.ADDED));
assertEquals(v2id, getId(v));
VertexProperty<Float> p = Iterables.getOnlyElement(changes.getProperties(v, Change.ADDED, "weight"));
assertEquals(222.2, p.value().doubleValue(), 0.01);
assertEquals(1, Iterables.size(changes.getEdges(v, Change.ADDED, OUT)));
assertEquals(1, Iterables.size(changes.getEdges(v, Change.ADDED, BOTH)));
} else if (txTimeMicro.isBefore(txTimes[3])) {
txNo = 3;
//v2 deletion transaction
assertEquals(0, Iterables.size(changes.getVertices(Change.ADDED)));
assertEquals(1, Iterables.size(changes.getVertices(Change.REMOVED)));
assertEquals(2, Iterables.size(changes.getVertices(Change.ANY)));
assertEquals(0, Iterables.size(changes.getRelations(Change.ADDED)));
assertEquals(2, Iterables.size(changes.getRelations(Change.REMOVED)));
assertEquals(1, Iterables.size(changes.getRelations(Change.REMOVED, knows)));
assertEquals(1, Iterables.size(changes.getRelations(Change.REMOVED, weight)));
assertEquals(2, Iterables.size(changes.getRelations(Change.ANY)));
TitanVertex v = Iterables.getOnlyElement(changes.getVertices(Change.REMOVED));
assertEquals(v2id, getId(v));
VertexProperty<Float> p = Iterables.getOnlyElement(changes.getProperties(v, Change.REMOVED, "weight"));
assertEquals(222.2, p.value().doubleValue(), 0.01);
assertEquals(1, Iterables.size(changes.getEdges(v, Change.REMOVED, OUT)));
assertEquals(0, Iterables.size(changes.getEdges(v, Change.ADDED, BOTH)));
} else {
txNo = 4;
//v1 edge modification
assertEquals(0, Iterables.size(changes.getVertices(Change.ADDED)));
assertEquals(0, Iterables.size(changes.getVertices(Change.REMOVED)));
assertEquals(1, Iterables.size(changes.getVertices(Change.ANY)));
assertEquals(1, Iterables.size(changes.getRelations(Change.ADDED)));
assertEquals(1, Iterables.size(changes.getRelations(Change.REMOVED)));
assertEquals(1, Iterables.size(changes.getRelations(Change.REMOVED, knows)));
assertEquals(2, Iterables.size(changes.getRelations(Change.ANY)));
TitanVertex v = Iterables.getOnlyElement(changes.getVertices(Change.ANY));
assertEquals(v1id, getId(v));
TitanEdge e = Iterables.getOnlyElement(changes.getEdges(v, Change.REMOVED, Direction.OUT, "knows"));
assertFalse(e.property("weight").isPresent());
assertEquals(v, e.vertex(Direction.IN));
e = Iterables.getOnlyElement(changes.getEdges(v, Change.ADDED, Direction.OUT, "knows"));
assertEquals(44.4, e.<Float>value("weight").doubleValue(), 0.01);
assertEquals(v, e.vertex(Direction.IN));
}
//See only current state of graph in transaction
TitanVertex v1 = getV(tx, v1id);
assertNotNull(v1);
assertTrue(v1.isLoaded());
if (txNo != 2) {
//In the transaction that adds v2, v2 will be considered "loaded"
assertMissing(tx, v2id);
// assertTrue(txNo + " - " + v2, v2 == null || v2.isRemoved());
}
assertEquals(111.1, v1.<Float>value("weight").doubleValue(), 0.01);
assertCount(1, v1.query().direction(Direction.OUT).edges());
userLogCount.incrementAndGet();
}
}).build();
//wait
Thread.sleep(22000L);
recovery.shutdown();
long[] recoveryStats = ((StandardTransactionLogProcessor) recovery).getStatistics();
if (withLogFailure) {
assertEquals(1, recoveryStats[0]);
assertEquals(4, recoveryStats[1]);
} else {
assertEquals(5, recoveryStats[0]);
assertEquals(0, recoveryStats[1]);
}
userlogs.removeLogProcessor(userlogName);
userlogs.shutdown();
assertEquals(4, userLogCount.get());
}
Aggregations