From 056837cc584416700813a03443aa2aab3f121579 Mon Sep 17 00:00:00 2001 From: tinwelint Date: Mon, 25 Jul 2016 15:23:25 +0200 Subject: [PATCH] Logs timestamp information when terminating unsafe tx logged at info since this is typically very rarely logged and makes sense to have enabled by default for visibility --- .../neo4j/kernel/api/KernelTransaction.java | 12 +++++++ .../api/KernelTransactionImplementation.java | 12 +++++++ .../ConstraintIndexCreatorTest.java | 12 +++++++ ...TransactionCommittingResponseUnpacker.java | 32 +++++++++++++++++-- 4 files changed, 66 insertions(+), 2 deletions(-) diff --git a/community/kernel/src/main/java/org/neo4j/kernel/api/KernelTransaction.java b/community/kernel/src/main/java/org/neo4j/kernel/api/KernelTransaction.java index 6da6cb400229a..4b21143b7be65 100644 --- a/community/kernel/src/main/java/org/neo4j/kernel/api/KernelTransaction.java +++ b/community/kernel/src/main/java/org/neo4j/kernel/api/KernelTransaction.java @@ -21,6 +21,7 @@ import org.neo4j.kernel.api.exceptions.Status; import org.neo4j.kernel.api.exceptions.TransactionFailureException; +import org.neo4j.kernel.impl.api.Kernel; /** * Represents a transaction of changes to the underlying graph. @@ -129,6 +130,17 @@ interface CloseListener */ long lastTransactionTimestampWhenStarted(); + /** + * @return The id of the last transaction that was committed to the store when this transaction started. + */ + long lastTransactionIdWhenStarted(); + + /** + * @return start time of this transaction, i.e. basically {@link System#currentTimeMillis()} when user called + * {@link Kernel#newTransaction()}. + */ + long localStartTime(); + /** * Register a {@link CloseListener} to be invoked after commit, but before transaction events "after" hooks * are invoked. diff --git a/community/kernel/src/main/java/org/neo4j/kernel/impl/api/KernelTransactionImplementation.java b/community/kernel/src/main/java/org/neo4j/kernel/impl/api/KernelTransactionImplementation.java index 58ae764e47866..009c9a9f2c5b5 100644 --- a/community/kernel/src/main/java/org/neo4j/kernel/impl/api/KernelTransactionImplementation.java +++ b/community/kernel/src/main/java/org/neo4j/kernel/impl/api/KernelTransactionImplementation.java @@ -273,6 +273,18 @@ int getReuseCount() return reuseCount; } + @Override + public long localStartTime() + { + return startTimeMillis; + } + + @Override + public long lastTransactionIdWhenStarted() + { + return lastTransactionIdWhenStarted; + } + @Override public void success() { diff --git a/community/kernel/src/test/java/org/neo4j/kernel/impl/api/constraints/ConstraintIndexCreatorTest.java b/community/kernel/src/test/java/org/neo4j/kernel/impl/api/constraints/ConstraintIndexCreatorTest.java index 788d1212b12c2..6e358fcb47569 100644 --- a/community/kernel/src/test/java/org/neo4j/kernel/impl/api/constraints/ConstraintIndexCreatorTest.java +++ b/community/kernel/src/test/java/org/neo4j/kernel/impl/api/constraints/ConstraintIndexCreatorTest.java @@ -218,6 +218,18 @@ public long lastTransactionTimestampWhenStarted() public void registerCloseListener( CloseListener listener ) { } + + @Override + public long lastTransactionIdWhenStarted() + { + return 0; + } + + @Override + public long localStartTime() + { + return 0; + } }; } diff --git a/enterprise/com/src/main/java/org/neo4j/com/storecopy/TransactionCommittingResponseUnpacker.java b/enterprise/com/src/main/java/org/neo4j/com/storecopy/TransactionCommittingResponseUnpacker.java index 9eca2a6573617..cd730fe553da5 100644 --- a/enterprise/com/src/main/java/org/neo4j/com/storecopy/TransactionCommittingResponseUnpacker.java +++ b/enterprise/com/src/main/java/org/neo4j/com/storecopy/TransactionCommittingResponseUnpacker.java @@ -51,6 +51,8 @@ import org.neo4j.kernel.lifecycle.Lifecycle; import org.neo4j.logging.Log; +import static org.neo4j.helpers.Format.duration; +import static org.neo4j.helpers.Format.time; import static org.neo4j.kernel.impl.api.TransactionApplicationMode.EXTERNAL; /** @@ -399,8 +401,9 @@ private boolean batchSizeExceedsSafeZone() private void markUnsafeTransactionsForTermination() { - long lastAppliedTimestamp = transactionQueue.last().getCommitEntry().getTimeWritten(); - long earliestSafeTimestamp = lastAppliedTimestamp - idReuseSafeZoneTime; + long firstCommittedTimestamp = transactionQueue.first().getCommitEntry().getTimeWritten(); + long lastCommittedTimestamp = transactionQueue.last().getCommitEntry().getTimeWritten(); + long earliestSafeTimestamp = lastCommittedTimestamp - idReuseSafeZoneTime; for ( KernelTransaction tx : kernelTransactions.activeTransactions() ) { @@ -409,11 +412,36 @@ private void markUnsafeTransactionsForTermination() if ( commitTimestamp != TransactionIdStore.BASE_TX_COMMIT_TIMESTAMP && commitTimestamp < earliestSafeTimestamp ) { + log.info( "Marking transaction for termination, " + + "invalidated due to an upcoming batch of changes being applied:" + + "\n" + + " Batch: firstCommittedTxId:" + transactionQueue.first().getCommitEntry().getTxId() + + ", firstCommittedTimestamp:" + informativeTimestamp( firstCommittedTimestamp ) + + ", lastCommittedTxId:" + transactionQueue.last().getCommitEntry().getTxId() + + ", lastCommittedTimestamp:" + informativeTimestamp( lastCommittedTimestamp ) + + ", batchTimeRange:" + informativeDuration( lastCommittedTimestamp - firstCommittedTimestamp ) + + ", earliestSafeTimstamp:" + informativeTimestamp( earliestSafeTimestamp ) + + ", safeZoneDuration:" + informativeDuration( idReuseSafeZoneTime ) + + "\n" + + " Transaction: lastCommittedTimestamp:" + + informativeTimestamp( tx.lastTransactionTimestampWhenStarted() ) + + ", lastCommittedTxId:" + tx.lastTransactionIdWhenStarted() + + ", localStartTimestamp:" + informativeTimestamp( tx.localStartTime() ) ); tx.markForTermination( Status.Transaction.Outdated ); } } } + private static String informativeDuration( long duration ) + { + return duration( duration ) + "/" + duration; + } + + private static String informativeTimestamp( long timestamp ) + { + return time( timestamp ) + "/" + timestamp; + } + private void applyQueuedTransactions() throws IOException { // Synchronize to guard for concurrent shutdown