private async Task FlushTask(object initiatingTcs)
{
var flushingTasks = new List <TaskCompletionSource <object> >();
flushingTasks.Add((TaskCompletionSource <object>)initiatingTcs);
var isFlushTask = true;
var flushWatch = Stopwatch.StartNew();
var serializationWatch = Stopwatch.StartNew();
do
{
TaskCompletionSource <object> notificationTcs;
try
{
Utility.Assert(this.loggingException == null, "this.loggingException == null");
var numberOfLatencySensitiveRecords = 0;
ulong numberOfBytes = 0;
var startingPsn = this.flushingRecords[0].Psn;
FabricEvents.Events.PhysicalLogWriterFlushStart(
this.tracer.Type,
this.flushingRecords.Count,
startingPsn.PSN);
// Enable group commit as we are about to issue IO
// Operations above this line must not throw.
notificationTcs = Interlocked.Exchange <TaskCompletionSource <object> >(
ref this.flushNotificationTcs,
FlushPendingTcs);
flushWatch.Reset();
serializationWatch.Reset();
foreach (var record in this.flushingRecords)
{
serializationWatch.Start();
var operationData = this.WriteRecord(record, numberOfBytes);
#if DEBUG
ReplicatedLogManager.ValidateOperationData(operationData, "Log Write for " + record.RecordType);
#endif
var logicalRecord = record as LogicalLogRecord;
if (logicalRecord != null && logicalRecord.IsLatencySensitiveRecord == true)
{
++numberOfLatencySensitiveRecords;
}
serializationWatch.Stop();
this.avgSerializationLatencyCounterWriter.IncrementBy(serializationWatch);
flushWatch.Start();
foreach (var arraySegment in operationData)
{
numberOfBytes += (ulong)arraySegment.Count;
await
this.logicalLogStream.AppendAsync(
arraySegment.Array,
arraySegment.Offset,
arraySegment.Count,
CancellationToken.None).ConfigureAwait(false);
}
flushWatch.Stop();
}
Utility.Assert(notificationTcs == FlushPermittedTcs, "NotificationTcs == FlushPermittedTcs");
flushWatch.Start();
await this.logicalLogStream.FlushWithMarkerAsync(CancellationToken.None).ConfigureAwait(false);
flushWatch.Stop();
this.UpdateWriteStats(flushWatch, numberOfBytes);
var lastWrittenTailRecord = this.flushingRecords[this.flushingRecords.Count - 1];
// Save the new log tail position and no need to interlock as single
// instruction 64-bit writes are atomic on 64-bit machines and there
// can only be one thread here
this.currentLogTailPosition += numberOfBytes;
this.currentLogTailRecord = lastWrittenTailRecord;
this.bytesPerFlushCounterWriter.IncrementBy((long)numberOfBytes);
if (flushWatch.ElapsedMilliseconds > 3000)
{
FabricEvents.Events.PhysicalLogWriterFlushEndWarning(
this.tracer.Type,
numberOfBytes,
this.flushingRecords.Count,
numberOfLatencySensitiveRecords,
flushWatch.ElapsedMilliseconds,
serializationWatch.ElapsedMilliseconds,
(double)this.writeSpeedBytesPerSecondSum / MovingAverageHistory,
(double)this.runningLatencySumMs / MovingAverageHistory,
this.logicalLogStream.WritePosition - (long)numberOfBytes);
}
else
{
FabricEvents.Events.PhysicalLogWriterFlushEnd(
this.tracer.Type,
numberOfBytes,
this.flushingRecords.Count,
numberOfLatencySensitiveRecords,
flushWatch.ElapsedMilliseconds,
serializationWatch.ElapsedMilliseconds,
(double)this.writeSpeedBytesPerSecondSum / MovingAverageHistory,
(double)this.runningLatencySumMs / MovingAverageHistory,
this.logicalLogStream.WritePosition - (long)numberOfBytes);
}
}
catch (Exception e)
{
this.loggingException = e;
}
finally
{
try
{
// Disable group commit as there is no pending IO
notificationTcs = this.FlushCompleted();
// GopalK: The order of the following instructions is very important.
// It is important to process flushed records first before
// waking up flush waiters
var flushedTasks = flushingTasks;
var flushedRecords = new LoggedRecords(this.flushingRecords, this.loggingException);
this.ProcessFlushedRecords(flushedRecords);
isFlushTask = this.ProcessFlushCompletion(flushedRecords, ref flushedTasks, out flushingTasks);
this.WakeupFlushWaiters(flushedTasks);
if ((isFlushTask == true) && (this.loggingException != null))
{
this.FailedFlushTask(flushingTasks);
isFlushTask = false;
}
}
catch (Exception e)
{
int innerHResult = 0;
var exception = Utility.FlattenException(e, out innerHResult);
var exceptionMessage =
string.Format(
CultureInfo.InvariantCulture,
"PhysicalLogWriter::FlushTask() - Hit an exception, Type: {0}, Message: {1}, HResult: 0x{2:X8}, Stack Trace: {3}",
exception.GetType().ToString(),
exception.Message,
exception.HResult != 0 ? exception.HResult : innerHResult,
exception.StackTrace);
FabricEvents.Events.Warning(this.tracer.Type, exceptionMessage);
Utility.Assert(false, exceptionMessage);
throw;
}
}
} while (isFlushTask == true);
return;
}
internal static void Assert(bool condition, string format, TruncateHeadLogRecord param1, LogRecord param2)
{
if (condition == false)
{
var failFastMessage = string.Format(System.Globalization.CultureInfo.InvariantCulture, format, param1, param2);
FailFast(failFastMessage);
// AMW - Force break into debugger for ease of debugging
Debugger.Break();
}
}
public async Task <LogRecord> TruncateTailAsync()
{
Utility.Assert(
tailLsn < this.replicatedLogManager.CurrentLogTailLsn,
"tailLsn < this.currentLogTailLsn. Current log tail lsn: {0}",
this.replicatedLogManager.CurrentLogTailLsn.LSN);
Utility.Assert(
tailLsn >= this.replicatedLogManager.LastCompletedBeginCheckpointRecord.Lsn,
"tailLsn >= this.LastCompletedBeginCheckpointRecord.LastLogicalSequenceNumber. LastCompletedBeginCheckpointLogRecord: {0}",
this.replicatedLogManager.LastCompletedBeginCheckpointRecord.Lsn);
Utility.Assert(
this.replicatedLogManager.LastInProgressTruncateHeadRecord == null,
"this.lastInProgressTruncateHeadRecord == null");
var currentRecord = this.replicatedLogManager.LogManager.CurrentLogTailRecord;
var currentLsn = currentRecord.Lsn;
var isUpdateRecordAtTail = true;
var recoveredLsn = currentLsn;
EndCheckpointLogRecord endCheckpointLogRecord = null;
CompleteCheckpointLogRecord completeCheckpointLogRecord = null;
var lastPhysicalRecord = this.replicatedLogManager.LogManager.CurrentLastPhysicalRecord;
do
{
Utility.Assert(
LogRecord.IsInvalidRecord(currentRecord) == false,
"LogRecord.IsInvalidRecord(currentRecord ({0})) == false",
currentRecord);
if (isUpdateRecordAtTail == true)
{
isUpdateRecordAtTail = currentRecord.Lsn == recoveredLsn;
}
OperationData metaData = null;
switch (currentRecord.RecordType)
{
case LogRecordType.BeginTransaction:
var beginTransactionRecord = (BeginTransactionOperationLogRecord)currentRecord;
// Cache the latest metadata just read from disk
metaData = beginTransactionRecord.MetaData;
beginTransactionRecord = this.transactionsMap.DeleteTransaction(beginTransactionRecord);
// Reset the metadata of the transaction as it may have been modified during redo pass
beginTransactionRecord.MetaData = metaData;
if (beginTransactionRecord.IsSingleOperationTransaction)
{
Utility.Assert(
beginTransactionRecord.Lsn != LogicalSequenceNumber.InvalidLsn,
"begin transaction record lsn must not be invalid.");
beginTransactionRecord.Transaction.CommitSequenceNumber = beginTransactionRecord.Lsn.LSN;
var operationContext =
await
this.stateManager.OnApplyAsync(
beginTransactionRecord.Lsn.LSN,
beginTransactionRecord.Transaction,
beginTransactionRecord.MetaData,
beginTransactionRecord.Undo,
falseProgressApplyContext).ConfigureAwait(false);
if (operationContext != null)
{
this.stateManager.Unlock(operationContext);
}
FabricEvents.Events.TruncateTailSingleOperationTransactionRecord(
this.tracer.Type,
"Deleted",
beginTransactionRecord.Lsn.LSN,
beginTransactionRecord.Psn.PSN,
beginTransactionRecord.RecordPosition,
beginTransactionRecord.Transaction.Id);
}
else
{
FabricEvents.Events.TruncateTailTransactionRecord(
this.tracer.Type,
"Deleted",
beginTransactionRecord.Lsn.LSN,
beginTransactionRecord.Psn.PSN,
beginTransactionRecord.RecordPosition,
beginTransactionRecord.Transaction.Id);
}
break;
case LogRecordType.Operation:
var operationRecord = (OperationLogRecord)currentRecord;
// Cache the latest metadata just read from disk
metaData = operationRecord.MetaData;
operationRecord = this.transactionsMap.RedactOperation(operationRecord);
// Reset the metadata of the operation as it may have been modified during redo pass
operationRecord.MetaData = metaData;
if (operationRecord.Transaction.IsAtomicOperation == true)
{
Utility.Assert(
operationRecord.IsRedoOnly == false,
"TruncateTail- RedoOnly operation cannot be undone");
Utility.Assert(
operationRecord.Lsn != LogicalSequenceNumber.InvalidLsn,
"Operation's lsn must not be invalid.");
operationRecord.Transaction.CommitSequenceNumber = operationRecord.Lsn.LSN;
var operationContext =
await
this.stateManager.OnApplyAsync(
operationRecord.Lsn.LSN,
operationRecord.Transaction,
operationRecord.MetaData,
operationRecord.Undo,
falseProgressApplyContext).ConfigureAwait(false);
if (operationContext != null)
{
this.stateManager.Unlock(operationContext);
}
FabricEvents.Events.TruncateTailAtomicOperation(
this.tracer.Type,
operationRecord.Lsn.LSN,
operationRecord.Psn.PSN,
operationRecord.RecordPosition,
operationRecord.Transaction.Id);
}
else
{
FabricEvents.Events.TruncateTailOperationRecord(
this.tracer.Type,
"Deleted",
operationRecord.Lsn.LSN,
operationRecord.Psn.PSN,
operationRecord.RecordPosition,
operationRecord.Transaction.Id);
}
break;
case LogRecordType.EndTransaction:
var endTransactionRecord = (EndTransactionLogRecord)currentRecord;
endTransactionRecord = this.transactionsMap.ReifyTransaction(endTransactionRecord);
Utility.Assert(
endTransactionRecord.Lsn != LogicalSequenceNumber.InvalidLsn,
"end transaction record cannot have an invalid lsn.");
// Undo all operations (Call apply with undo).
if (endTransactionRecord.IsCommitted == true)
{
TransactionLogRecord transactionRecord = endTransactionRecord;
do
{
// During recovery operations that may be undo are kept in memory.
// Since Truncate tail uses the in-memory links, Transaction have already been created and their commit sequence numbers
// have been set during recovery redo.
Utility.Assert(
transactionRecord.RecordType == LogRecordType.EndTransaction ||
transactionRecord.Transaction.CommitSequenceNumber
!= LogicalSequenceNumber.InvalidLsn.LSN,
"For an operation to be undone, it must already have been done.");
object operationContext = null;
transactionRecord = transactionRecord.ParentTransactionRecord;
Utility.Assert(transactionRecord != null, "transactionRecord != null");
if (transactionRecord is BeginTransactionOperationLogRecord)
{
// Cache the metadata read from disk
var justReadTransactionRecord =
await this.recoveryLogsReader.GetNextLogRecord(transactionRecord.RecordPosition).ConfigureAwait(false);
Utility.Assert(
justReadTransactionRecord.RecordType == LogRecordType.BeginTransaction,
"Just read transaction during false progress is not begintransaction. It is {0}",
justReadTransactionRecord.RecordType);
var justReadBeginTransactionRecord =
(BeginTransactionOperationLogRecord)justReadTransactionRecord;
var beginTx = (BeginTransactionOperationLogRecord)transactionRecord;
beginTx.MetaData = justReadBeginTransactionRecord.MetaData;
Utility.Assert(
beginTx.IsSingleOperationTransaction == false,
"beginTx.IsSingleOperationTransaction must be false when endTxRecord is being processed");
operationContext =
await
this.stateManager.OnApplyAsync(
beginTx.Lsn.LSN,
beginTx.Transaction,
beginTx.MetaData,
beginTx.Undo,
falseProgressApplyContext).ConfigureAwait(false);
if (operationContext != null)
{
beginTx.OperationContext = operationContext;
}
break;
}
// Cache the metadata read from disk
var justReadOperationLogRecord =
await this.recoveryLogsReader.GetNextLogRecord(transactionRecord.RecordPosition).ConfigureAwait(false);
Utility.Assert(
justReadOperationLogRecord.RecordType == LogRecordType.Operation,
"Just read operation during false progress is not of the right type. It is {0}",
justReadOperationLogRecord.RecordType);
var justReadOperationRecord = (OperationLogRecord)justReadOperationLogRecord;
operationRecord = (OperationLogRecord)transactionRecord;
operationRecord.MetaData = justReadOperationRecord.MetaData;
operationContext =
await
this.stateManager.OnApplyAsync(
operationRecord.Lsn.LSN,
operationRecord.Transaction,
operationRecord.MetaData,
operationRecord.Undo,
falseProgressApplyContext).ConfigureAwait(false);
if (operationContext != null)
{
operationRecord.OperationContext = operationContext;
}
} while (true);
// call unlock
transactionRecord = endTransactionRecord;
do
{
object operationContext = null;
transactionRecord = transactionRecord.ParentTransactionRecord;
Utility.Assert(transactionRecord != null, "transactionRecord != null");
if (transactionRecord is BeginTransactionOperationLogRecord)
{
var beginTx = (BeginTransactionOperationLogRecord)transactionRecord;
operationContext = beginTx.ResetOperationContext();
if (operationContext != null)
{
this.stateManager.Unlock(operationContext);
}
FabricEvents.Events.TruncateTailOperationRecord(
this.tracer.Type,
"Undone",
beginTx.Lsn.LSN,
beginTx.Psn.PSN,
beginTx.RecordPosition,
beginTx.Transaction.Id);
break;
}
operationRecord = (OperationLogRecord)transactionRecord;
operationContext = operationRecord.ResetOperationContext();
if (operationContext != null)
{
this.stateManager.Unlock(operationContext);
}
FabricEvents.Events.TruncateTailOperationRecord(
this.tracer.Type,
"Undone",
operationRecord.Lsn.LSN,
operationRecord.Psn.PSN,
operationRecord.RecordPosition,
operationRecord.Transaction.Id);
} while (true);
}
FabricEvents.Events.TruncateTailTransactionRecord(
this.tracer.Type,
"Reified",
endTransactionRecord.Lsn.LSN,
endTransactionRecord.Psn.PSN,
endTransactionRecord.RecordPosition,
endTransactionRecord.Transaction.Id);
break;
case LogRecordType.Barrier:
var barrierRecord = (BarrierLogRecord)currentRecord;
FabricEvents.Events.TruncateTailBarrier(
this.tracer.Type,
barrierRecord.Lsn.LSN,
barrierRecord.Psn.PSN,
barrierRecord.RecordPosition);
break;
case LogRecordType.Backup:
// Inform the backup manager that the last backup log record has been undone.
this.backupManager.UndoLastCompletedBackupLogRecord();
// Trace that the backup log record has been false progressed.
var backupRecord = (BackupLogRecord)currentRecord;
#if !DotNetCoreClr
// These are new events defined in System.Fabric, existing CoreCLR apps would break
// if these events are refernced as it wont be found. As CoreCLR apps carry System.Fabric
// along with application
// This is just a mitigation for now. Actual fix being tracked via bug# 11614507
FabricEvents.Events.TruncateTailBackup(
this.tracer.Type,
backupRecord.Lsn.LSN,
backupRecord.Psn.PSN,
backupRecord.RecordPosition);
#endif
break;
case LogRecordType.UpdateEpoch:
// These records can only occur at the tail
Utility.Assert(isUpdateRecordAtTail == true, "isUpdateRecordAtTail == true");
var updateEpochRecord = (UpdateEpochLogRecord)currentRecord;
var lastVector = new ProgressVectorEntry(updateEpochRecord);
this.replicatedLogManager.ProgressVector.TruncateTail(lastVector);
FabricEvents.Events.TruncateTailUpdateEpoch(
this.tracer.Type,
lastVector.Epoch.DataLossNumber,
lastVector.Epoch.ConfigurationNumber,
updateEpochRecord.Lsn.LSN,
updateEpochRecord.Psn.PSN,
updateEpochRecord.RecordPosition);
break;
case LogRecordType.EndCheckpoint:
Utility.Assert(
currentRecord.Psn == this.replicatedLogManager.LastCompletedEndCheckpointRecord.Psn,
"currentRecord.Psn == this.lastCompletedEndCheckpointRecord.Psn");
Utility.Assert(
currentRecord.Psn == this.replicatedLogManager.LastLinkedPhysicalRecord.Psn,
"currentRecord.Psn == this.lastLinkedPhysicalRecord.Psn");
endCheckpointLogRecord = this.replicatedLogManager.LastCompletedEndCheckpointRecord;
this.replicatedLogManager.OnTruncateTailOfLastLinkedPhysicalRecord();
goto case LogRecordType.Indexing;
case LogRecordType.TruncateHead:
Utility.Assert(
currentRecord.Psn == this.replicatedLogManager.LastLinkedPhysicalRecord.Psn,
"currentRecord.Psn == this.lastLinkedPhysicalRecord.Psn");
var truncateHeadRecord = (TruncateHeadLogRecord)currentRecord;
Utility.Assert(
truncateHeadRecord.IsStable == false,
"Stable truncateHeadRecord cannot be undone due to false progress");
this.replicatedLogManager.OnTruncateTailOfLastLinkedPhysicalRecord();
goto case LogRecordType.Indexing;
case LogRecordType.CompleteCheckpoint:
completeCheckpointLogRecord = currentRecord as CompleteCheckpointLogRecord;
this.replicatedLogManager.OnTruncateTailOfLastLinkedPhysicalRecord();
goto case LogRecordType.Indexing;
case LogRecordType.Indexing:
case LogRecordType.TruncateTail:
case LogRecordType.BeginCheckpoint:
case LogRecordType.Information:
Utility.Assert(
currentRecord.Psn == lastPhysicalRecord.Psn,
"currentRecord.Psn == lastPhysicalRecord.Psn");
lastPhysicalRecord = lastPhysicalRecord.PreviousPhysicalRecord;
break;
default:
Utility.CodingError("Unexpected record type {0}", currentRecord.RecordType);
break;
}
currentRecord = await this.recoveryLogsReader.GetPreviousLogRecord(currentRecord.RecordPosition).ConfigureAwait(false);
currentLsn = currentRecord.Lsn;
} while (currentLsn > tailLsn);
Utility.Assert(currentLsn == tailLsn, "V1 replicator ensures that lsns are continuous. currentLsn {0} == tailLsn {1}", currentLsn, tailLsn);
if (currentRecord is LogicalLogRecord)
{
switch (currentRecord.RecordType)
{
case LogRecordType.BeginTransaction:
var beginTransactionRecord =
(BeginTransactionOperationLogRecord)currentRecord;
currentRecord = this.transactionsMap.FindTransaction(beginTransactionRecord);
// Single operation transactions are not stored in the tx map and hence are not returned above. As a result, they dont have a valid indexing of the previous physical record
if (beginTransactionRecord.IsSingleOperationTransaction)
{
currentRecord.PreviousPhysicalRecord = lastPhysicalRecord;
}
break;
case LogRecordType.Operation:
var operationRecord = (OperationLogRecord)currentRecord;
currentRecord = this.transactionsMap.FindOperation(operationRecord);
// Atomic operations are not stored in the tx map and hence are not returned above. As a result, they dont have a valid indexing of the previous physical record
if (operationRecord.Transaction.IsAtomicOperation)
{
currentRecord.PreviousPhysicalRecord = lastPhysicalRecord;
}
break;
case LogRecordType.EndTransaction:
var endTransactionRecord = (EndTransactionLogRecord)currentRecord;
currentRecord = this.transactionsMap.FindUnstableTransaction(endTransactionRecord);
break;
case LogRecordType.Backup:
case LogRecordType.Barrier:
currentRecord.PreviousPhysicalRecord = lastPhysicalRecord;
break;
case LogRecordType.UpdateEpoch:
currentRecord.PreviousPhysicalRecord = lastPhysicalRecord;
break;
default:
Utility.CodingError("Unexpected record type {0}", currentRecord.RecordType);
break;
}
Utility.Assert(
currentRecord.PreviousPhysicalRecord == lastPhysicalRecord,
"currentRecord.PreviousPhysicalRecord == lastPhysicalRecord");
}
else
{
Utility.Assert(
lastPhysicalRecord.Psn == currentRecord.Psn,
"lastPhysicalRecord.Psn == currentRecord.Psn");
currentRecord = lastPhysicalRecord;
}
Utility.Assert(
(this.replicatedLogManager.LastLinkedPhysicalRecord == lastPhysicalRecord) ||
(this.replicatedLogManager.LastLinkedPhysicalRecord == lastPhysicalRecord.LinkedPhysicalRecord),
"(this.lastLinkedPhysicalRecord == lastPhysicalRecord) || (this.lastLinkedPhysicalRecord == lastPhysicalRecord.LinkedPhysicalRecord)");
await this.replicatedLogManager.LogManager.PerformLogTailTruncationAsync(currentRecord).ConfigureAwait(false);
this.replicatedLogManager.SetTailLsn(tailLsn);
// If endchkpoint was truncated, even complete checkpoint must be truncated
if (endCheckpointLogRecord != null)
{
Utility.Assert(
completeCheckpointLogRecord != null,
"TruncateTailAsync: EndCheckpoint was truncated but CompleteCheckpoint was not");
this.replicatedLogManager.EndCheckpoint(endCheckpointLogRecord.LastCompletedBeginCheckpointRecord);
}
if (completeCheckpointLogRecord != null)
{
this.replicatedLogManager.CompleteCheckpoint();
}
this.replicatedLogManager.TruncateTail(tailLsn);
await this.replicatedLogManager.LogManager.FlushAsync("TruncateTailAsync").ConfigureAwait(false);
FabricEvents.Events.TruncateTailDone(
this.tracer.Type,
currentRecord.RecordType.ToString(),
currentRecord.Lsn.LSN,
currentRecord.Psn.PSN,
currentRecord.RecordPosition);
return(currentRecord);
}
private async Task ApplyCallback(LogRecord record)
{
Utility.Assert(
this.roleContextDrainState.DrainingStream != DrainingStream.Invalid && this.roleContextDrainState.DrainingStream != DrainingStream.StateStream,
"ApplyCallback: this.roleContextDrainState.DrainingStream != DrainingStream.Invalid && this.roleContextDrainState.DrainingStream != DrainingStream.StateStream. It is {0} for log record lsn: {1} and psn: {2}",
this.roleContextDrainState.DrainingStream, record.Lsn, record.Psn);
var serviceException = this.serviceException;
if (serviceException != null)
{
record.CompletedApply(serviceException);
return;
}
try
{
OperationLogRecord operationRecord;
var callbackRedoContext = this.roleContextDrainState.ApplyRedoContext;
switch (record.RecordType)
{
case LogRecordType.BeginTransaction:
var beginTransactionRecordExtra =
(BeginTransactionOperationLogRecord)record;
FabricEvents.Events.ApplyCallbackTransactionRecordNoise(
this.tracer.Type,
(int)this.roleContextDrainState.DrainingStream,
(uint)beginTransactionRecordExtra.RecordType,
beginTransactionRecordExtra.Lsn.LSN,
beginTransactionRecordExtra.Psn.PSN,
beginTransactionRecordExtra.RecordPosition,
beginTransactionRecordExtra.Transaction.Id);
if (beginTransactionRecordExtra.IsSingleOperationTransaction)
{
if (beginTransactionRecordExtra.Lsn > this.recoveredOrCopiedCheckpointLsn.Value)
{
beginTransactionRecordExtra.Transaction.CommitSequenceNumber =
beginTransactionRecordExtra.Lsn.LSN;
var operationContext =
await
this.stateManager.OnApplyAsync(
beginTransactionRecordExtra.Lsn.LSN,
beginTransactionRecordExtra.Transaction,
beginTransactionRecordExtra.MetaData,
beginTransactionRecordExtra.Redo,
callbackRedoContext).ConfigureAwait(false);
if (operationContext != null)
{
beginTransactionRecordExtra.OperationContext = operationContext;
}
FabricEvents.Events.ApplyCallbackSingleOperationTransaction(
this.tracer.Type,
(int)this.roleContextDrainState.DrainingStream,
beginTransactionRecordExtra.Lsn.LSN,
beginTransactionRecordExtra.Psn.PSN,
beginTransactionRecordExtra.RecordPosition,
beginTransactionRecordExtra.Transaction.Id);
}
}
break;
case LogRecordType.Operation:
operationRecord = (OperationLogRecord)record;
if (operationRecord.Transaction.IsAtomicOperation == true)
{
if (operationRecord.Lsn > this.recoveredOrCopiedCheckpointLsn.Value)
{
// For atomic operations create lsn equals commit lsn.
operationRecord.Transaction.CommitSequenceNumber = operationRecord.Lsn.LSN;
var operationContext =
await
this.stateManager.OnApplyAsync(
operationRecord.Lsn.LSN,
operationRecord.Transaction,
operationRecord.MetaData,
operationRecord.Redo,
callbackRedoContext).ConfigureAwait(false);
if (operationContext != null)
{
operationRecord.OperationContext = operationContext;
}
FabricEvents.Events.ApplyCallbackAtomicOperationRecord(
this.tracer.Type,
(int)this.roleContextDrainState.DrainingStream,
operationRecord.Lsn.LSN,
operationRecord.Psn.PSN,
operationRecord.RecordPosition,
operationRecord.Transaction.Id,
operationRecord.IsRedoOnly);
}
}
else
{
FabricEvents.Events.ApplyCallbackTransactionRecordNoise(
this.tracer.Type,
(int)this.roleContextDrainState.DrainingStream,
(uint)operationRecord.RecordType,
operationRecord.Lsn.LSN,
operationRecord.Psn.PSN,
operationRecord.RecordPosition,
operationRecord.Transaction.Id);
}
break;
case LogRecordType.EndTransaction:
var endTransactionRecord = (EndTransactionLogRecord)record;
if ((endTransactionRecord.IsCommitted == true) &&
(endTransactionRecord.Lsn > this.recoveredOrCopiedCheckpointLsn.Value))
{
// GopalK: I am currently adopting the approach of only applying updates that do not
// belong to any transaction in the update switch above and
// applying the updates that belong to a transaction only when if it commits.
// The other approach is to immediately apply updates of all
// transactions in the update switch case above and then undoing updates of
// aborted transactions here.
// Both approaches have their pros and cons and we may want to look into
// making this a replicator option that the service developer can choose.
// If on Primary, Transaction object is shared.
endTransactionRecord.Transaction.CommitSequenceNumber = endTransactionRecord.Lsn.LSN;
BeginTransactionOperationLogRecord beginTransactionRecord = null;
TransactionLogRecord transactionRecord = endTransactionRecord;
do
{
transactionRecord = transactionRecord.ParentTransactionRecord;
beginTransactionRecord = transactionRecord as BeginTransactionOperationLogRecord;
} while (beginTransactionRecord == null);
{
Utility.Assert(
LogRecord.IsInvalidRecord(beginTransactionRecord) == false,
"TransactionLogRecord.IsInvalidRecord(beginTransactionRecord) == false");
Utility.Assert(
beginTransactionRecord.IsSingleOperationTransaction == false,
"beginTransactionRecord.IsSingleOperationTransaction must be false when endTxRecord is being processed");
// If on not Primary, Transaction object is shared.
if (callbackRedoContext.HasFlag(ApplyContext.PRIMARY) == false)
{
beginTransactionRecord.Transaction.CommitSequenceNumber =
endTransactionRecord.Lsn.LSN;
}
else
{
// TODO: Temporary assert. Should be removed later.
Utility.Assert(
beginTransactionRecord.Transaction.CommitSequenceNumber
== endTransactionRecord.Lsn.LSN,
"Transaction's commit sequence number must have already been set. Expected: {0} Actual: {1}",
transactionRecord.Transaction.CommitSequenceNumber,
endTransactionRecord.Lsn.LSN);
}
var operationContext =
await
this.stateManager.OnApplyAsync(
beginTransactionRecord.Lsn.LSN,
beginTransactionRecord.Transaction,
beginTransactionRecord.MetaData,
beginTransactionRecord.Redo,
callbackRedoContext).ConfigureAwait(false);
if (operationContext != null)
{
beginTransactionRecord.OperationContext = operationContext;
}
FabricEvents.Events.ApplyCallbackTransactionRecordNoise(
this.tracer.Type,
(int)this.roleContextDrainState.DrainingStream,
(uint)beginTransactionRecord.RecordType,
beginTransactionRecord.Lsn.LSN,
beginTransactionRecord.Psn.PSN,
beginTransactionRecord.RecordPosition,
beginTransactionRecord.Transaction.Id);
}
do
{
transactionRecord = transactionRecord.ChildTransactionRecord;
Utility.Assert(
(transactionRecord != null) &&
(LogRecord.IsInvalidRecord(transactionRecord) == false),
"(transactionRecord != null) && (TransactionLogRecord.IsInvalidRecord(transactionRecord) == false");
if (transactionRecord == endTransactionRecord)
{
break;
}
operationRecord = (OperationLogRecord)transactionRecord;
// If on Primary, Transaction object is shared.
if (callbackRedoContext.HasFlag(ApplyContext.PRIMARY) == false)
{
operationRecord.Transaction.CommitSequenceNumber = endTransactionRecord.Lsn.LSN;
}
else
{
// TODO: Temporary assert. Should be removed later.
Utility.Assert(
operationRecord.Transaction.CommitSequenceNumber == endTransactionRecord.Lsn.LSN,
"Transaction's commit sequence number must have already been set. Expected: {0} Actual: {1}",
transactionRecord.Transaction.CommitSequenceNumber,
endTransactionRecord.Lsn.LSN);
}
var operationContext =
await
this.stateManager.OnApplyAsync(
operationRecord.Lsn.LSN,
operationRecord.Transaction,
operationRecord.MetaData,
operationRecord.Redo,
callbackRedoContext).ConfigureAwait(false);
if (operationContext != null)
{
operationRecord.OperationContext = operationContext;
}
FabricEvents.Events.ApplyCallbackTransactionRecordNoise(
this.tracer.Type,
(int)this.roleContextDrainState.DrainingStream,
(uint)operationRecord.RecordType,
operationRecord.Lsn.LSN,
operationRecord.Psn.PSN,
operationRecord.RecordPosition,
operationRecord.Transaction.Id);
} while (true);
FabricEvents.Events.ApplyCallbackTransactionRecord(
this.tracer.Type,
(int)this.roleContextDrainState.DrainingStream,
endTransactionRecord.Psn.PSN,
endTransactionRecord.Transaction.Id);
}
break;
case LogRecordType.Barrier:
this.LastAppliedBarrierRecord = (BarrierLogRecord)record;
FabricEvents.Events.ApplyCallbackBarrierRecord(
this.tracer.Type,
(int)this.roleContextDrainState.DrainingStream,
record.Lsn.LSN,
record.Psn.PSN,
record.RecordPosition);
break;
case LogRecordType.Backup:
// TODO: Trace.
break;
default:
Utility.CodingError("Unexpected record type {0}", record.RecordType);
break;
}
}
catch (Exception e)
{
this.ProcessServiceException("OnApply", record, e);
serviceException = e;
}
record.CompletedApply(serviceException);
return;
}
public void TruncateTail(LogRecord currentRecord)
{
this.LastAppliedBarrierRecord = currentRecord;
}
public async Task <long> CommitTransactionAsync(Transaction transaction)
{
LogRecord endTransactionRecord = await this.EndTransactionAsync(transaction, true, true).ConfigureAwait(false);
return(endTransactionRecord.Lsn.LSN);
}
public void Unlock(LogicalLogRecord record)
{
Utility.Assert(record.IsApplied == true, "record.IsApplied == true");
Utility.Assert(this.recoveredOrCopiedCheckpointLsn.Value != LogicalSequenceNumber.InvalidLsn, "recoveredOrCopiedCheckpointLsn must not be -1");
// If flush fails, the records are processed immediately, after which the processing can complete (before waiting for unlocks)
if (record.FlushException == null)
{
Utility.Assert(
roleContextDrainState.DrainingStream != DrainingStream.Invalid,
"this.DrainingStream != DrainingStream.Invalid during unlock for record lsn:{0} psn:{1}",
record.Lsn, record.Psn);
}
BeginTransactionOperationLogRecord beginTransactionRecord;
try
{
OperationLogRecord operationRecord;
switch (record.RecordType)
{
case LogRecordType.BeginTransaction:
beginTransactionRecord = (BeginTransactionOperationLogRecord)record;
if (beginTransactionRecord.IsSingleOperationTransaction)
{
if (beginTransactionRecord.Lsn > this.recoveredOrCopiedCheckpointLsn.Value)
{
var operationContext = beginTransactionRecord.ResetOperationContext();
if (operationContext != null)
{
this.stateManager.Unlock(operationContext);
}
}
this.FireCommitNotification((ITransaction)beginTransactionRecord.Transaction);
}
break;
case LogRecordType.Operation:
operationRecord = (OperationLogRecord)record;
if (operationRecord.Transaction.IsAtomicOperation == true)
{
if (operationRecord.Lsn > this.recoveredOrCopiedCheckpointLsn.Value)
{
var operationContext = operationRecord.ResetOperationContext();
if (operationContext != null)
{
this.stateManager.Unlock(operationContext);
}
}
}
break;
case LogRecordType.EndTransaction:
var endTransactionRecord = (EndTransactionLogRecord)record;
if (endTransactionRecord.Lsn > this.recoveredOrCopiedCheckpointLsn.Value)
{
TransactionLogRecord transactionRecord = endTransactionRecord;
do
{
transactionRecord = transactionRecord.ParentTransactionRecord;
beginTransactionRecord = transactionRecord as BeginTransactionOperationLogRecord;
} while (beginTransactionRecord == null);
Utility.Assert(
(beginTransactionRecord != null) &&
(LogRecord.IsInvalidRecord(beginTransactionRecord) == false),
"(beginTransactionRecord != null) && (TransactionLogRecord.IsInvalidRecord(beginTransactionRecord) == false)");
var operationContext = beginTransactionRecord.ResetOperationContext();
if (operationContext != null)
{
this.stateManager.Unlock(operationContext);
}
transactionRecord = beginTransactionRecord;
do
{
transactionRecord = transactionRecord.ChildTransactionRecord;
Utility.Assert(
(transactionRecord != null) &&
(LogRecord.IsInvalidRecord(transactionRecord) == false),
"(transactionRecord != null) && (TransactionLogRecord.IsInvalidRecord(transactionRecord) == false)");
if (transactionRecord == endTransactionRecord)
{
break;
}
operationRecord = (OperationLogRecord)transactionRecord;
operationContext = operationRecord.ResetOperationContext();
if (operationContext != null)
{
this.stateManager.Unlock(operationContext);
}
} while (true);
}
else
{
TransactionLogRecord transactionRecord = endTransactionRecord;
do
{
var parentRecord = transactionRecord.ParentTransactionRecord;
if (parentRecord == null)
{
break;
}
transactionRecord = parentRecord;
} while (true);
Utility.Assert(
(endTransactionRecord.IsEnlistedTransaction == false) ||
(transactionRecord is BeginTransactionOperationLogRecord),
"(endTransactionRecord.IsEnlistedTransaction {0} == false) || "
+ "(transactionRecord is BeginTransactionLogRecord {1})",
endTransactionRecord.IsEnlistedTransaction, transactionRecord.RecordType);
if (transactionRecord != endTransactionRecord)
{
do
{
transactionRecord = transactionRecord.ChildTransactionRecord;
Utility.Assert(
(transactionRecord != null) &&
(LogRecord.IsInvalidRecord(transactionRecord) == false),
"(transactionRecord != null) && (TransactionLogRecord.IsInvalidRecord(transactionRecord) == false)");
if (transactionRecord == endTransactionRecord)
{
break;
}
} while (true);
}
}
if (endTransactionRecord.IsCommitted == true)
{
this.FireCommitNotification((ITransaction)endTransactionRecord.Transaction);
}
break;
case LogRecordType.Backup:
var backupLogRecord = (BackupLogRecord)record;
Utility.Assert(backupManager != null, "Backupmanager must not be null in UnlockCallbackManager");
backupManager.LastCompletedBackupLogRecord = backupLogRecord;
break;
default:
Utility.CodingError("Unexpected record type {0}", record.RecordType);
break;
}
}
catch (Exception e)
{
this.ProcessServiceException("Unlockcallback", record, e);
}
this.ProcessedLogicalRecord(record);
return;
}
internal LoggedRecords(LogRecord record, Exception exception)
{
this.records = new List <LogRecord>();
this.records.Add(record);
this.exception = exception;
}
public RecordProcessingMode IdentifyProcessingModeForRecord(LogRecord record)
{
var stream = this.roleContextDrainState.DrainingStream;
Utility.Assert(
stream != DrainingStream.Invalid || record is UpdateEpochLogRecord || record is PhysicalLogRecord,
@"Draining stream should not be invalid or record should be of type epoch or physical log record.
DrainingStream: {0} RecordType: {1}",
stream, record.RecordType);
if (LoggingReplicator.IsBarrierRecord(record))
{
this.LastAppliedBarrierRecord = record;
}
RecordProcessingMode processingMode;
switch (record.RecordType)
{
case LogRecordType.EndCheckpoint:
case LogRecordType.TruncateTail:
case LogRecordType.Indexing:
case LogRecordType.UpdateEpoch:
case LogRecordType.Information:
case LogRecordType.CompleteCheckpoint:
processingMode = RecordProcessingMode.ProcessImmediately;
break;
case LogRecordType.Barrier:
processingMode = (this.roleContextDrainState.ReplicaRole == ReplicaRole.Unknown)
? RecordProcessingMode.ProcessImmediately
: RecordProcessingMode.ApplyImmediately;
break;
case LogRecordType.TruncateHead:
processingMode = RecordProcessingMode.ApplyImmediately;
break;
case LogRecordType.BeginCheckpoint:
Utility.Assert(
(record.Lsn >= this.recoveredOrCopiedCheckpointLsn.Value) ||
(this.roleContextDrainState.ReplicaRole == ReplicaRole.Unknown),
"record.LastLogicalSequenceNumber >= this.recoveredOrCopiedCheckpointLsn || "
+ "(this.replicaRole == ReplicaRole.Unknown)");
processingMode = (this.roleContextDrainState.ReplicaRole == ReplicaRole.Unknown)
? RecordProcessingMode.ProcessImmediately
: RecordProcessingMode.ApplyImmediately;
break;
case LogRecordType.BeginTransaction:
case LogRecordType.Operation:
case LogRecordType.EndTransaction:
case LogRecordType.Backup:
processingMode = RecordProcessingMode.Normal;
break;
default:
Utility.CodingError("Unexpected record type {0}", record.RecordType);
processingMode = RecordProcessingMode.Normal;
break;
}
return(processingMode);
}
private async Task DrainCopyStreamAsync(
IOperationStream copyStream,
IOperation operation,
BeginCheckpointLogRecord copiedCheckpointRecord,
bool renamedCopyLogSuccessfully)
{
FabricEvents.Events.DrainStart(this.tracer.Type, "Copy stream: RenamedCopyLogSuccessfully: " + renamedCopyLogSuccessfully);
var lastCopiedRecord = LogicalLogRecord.InvalidLogicalLogRecord;
long copiedRecordNumber = 0, acksOutstanding = 1;
TaskCompletionSource <object> allOperationsAckedTcs = new TaskCompletionSource <object>();
try
{
if (operation != null)
{
this.roleContextDrainState.OnDrainCopy();
do
{
var data = operation.Data;
#if DEBUG
ReplicatedLogManager.ValidateOperationData(data, "DrainCopyStreamAsync LSN: " + operation.SequenceNumber);
#endif
lastCopiedRecord = (LogicalLogRecord)LogRecord.FromOperationData(data);
await this.LogLogicalRecordOnSecondaryAsync(lastCopiedRecord).ConfigureAwait(false);
// After successfully appending the record into the buffer, increment the outstanding ack count
var acksRemaining = Interlocked.Increment(ref acksOutstanding);
FabricEvents.Events.DrainCopyReceive(
this.tracer.Type,
copiedRecordNumber,
lastCopiedRecord.RecordType.ToString(),
lastCopiedRecord.Lsn.LSN,
acksRemaining);
++copiedRecordNumber;
if (this.replicatorSettings.PublicSettings.MaxCopyQueueSize / 2 <= acksRemaining)
{
FabricEvents.Events.DrainCopyFlush(
this.tracer.Type,
copiedRecordNumber,
lastCopiedRecord.Lsn.LSN,
acksRemaining);
this.replicatedLogManager.LogManager.FlushAsync("DrainCopyStream.IsFull").IgnoreExceptionVoid();
}
var capturedOperation = operation;
var capturedRecord = lastCopiedRecord;
if (copiedCheckpointRecord == null)
{
copiedCheckpointRecord = this.replicatedLogManager.LastInProgressCheckpointRecord;
if (copiedCheckpointRecord != null)
{
Utility.Assert(
copiedCheckpointRecord.Lsn == this.recoveredOrCopiedCheckpointLsn.Value,
"copiedCheckpointRecordLsn {0} == recoveredOrCopiedCheckpointLsn {1}",
copiedCheckpointRecord.Lsn,
this.recoveredOrCopiedCheckpointLsn.Value);
}
}
// If pumped the last operation in the copy stream (indicated by copiedUptoLsn), rename the copy log if this was a full copy
// as we are guranteed that the replica has all the data needed to be promoted to an active secondary and we could not have lost any state
if (copiedCheckpointRecord != null &&
copiedCheckpointRecord != BeginCheckpointLogRecord.InvalidBeginCheckpointLogRecord &&
lastCopiedRecord.Lsn == this.copiedUptoLsn &&
renamedCopyLogSuccessfully == false) // Copied UE record could have same LSN, so this condition is needed
{
await this.checkpointManager.CompleteFirstCheckpointOnIdleAndRenameLog(copiedCheckpointRecord, this.copiedUptoLsn.LSN).ConfigureAwait(false);
renamedCopyLogSuccessfully = true;
}
lastCopiedRecord.AwaitFlush().ContinueWith(
async task =>
{
var acksPending = Interlocked.Decrement(ref acksOutstanding);
if (task.Exception != null)
{
// Signal the drain completion task if needed
if (acksPending == 0)
{
allOperationsAckedTcs.TrySetResult(null);
}
return;
}
capturedOperation.Acknowledge();
Utility.Assert(acksPending >= 0, "acksPending {0} >= 0", acksPending);
if (acksPending == 0)
{
allOperationsAckedTcs.TrySetResult(null);
}
FabricEvents.Events.DrainCopyNoise(
this.tracer.Type,
capturedRecord.Lsn.LSN,
acksPending);
await capturedRecord.AwaitApply().ConfigureAwait(false);
}).IgnoreExceptionVoid();
var drainTask = copyStream.GetOperationAsync(CancellationToken.None);
if (drainTask.IsCompleted == false)
{
// GopalK: Currently, we cannot wait for copy to finish because copy might get
// abandoned if the primary fails and the product waits for pending
// copy operations to get acknowledged before electing a new primary
this.replicatedLogManager.LogManager.FlushAsync("DrainCopyStream.IsEmpty").IgnoreExceptionVoid();
await drainTask.ConfigureAwait(false);
}
operation = drainTask.GetAwaiter().GetResult();
} while (operation != null);
}
}
// This finally block ensures that before we continue, we cancel the first full copy checkpoint during full build
// Without having this, it is possible that the above code throws out of this method and any lifecycle API like close might get stuck because
// there is a pending checkpoint that is not yet fully processed
finally
{
// If the pump prematurely finishes for any reason, it means the copy log cannot be renamed
if (copiedCheckpointRecord != null &&
copiedCheckpointRecord != BeginCheckpointLogRecord.InvalidBeginCheckpointLogRecord &&
renamedCopyLogSuccessfully == false)
{
await this.checkpointManager.CancelFirstCheckpointOnIdleDueToIncompleteCopy(copiedCheckpointRecord, this.copiedUptoLsn.LSN);
}
}
await this.replicatedLogManager.FlushInformationRecordAsync(
InformationEvent.CopyFinished,
closeLog : false,
flushInitiator : "DrainCopyStream.IsFinished").ConfigureAwait(false);
// Awaiting processing of this record,
// ensures that all operations in the copystream must have been applied Before we complete the drainComplationTcs.
await this.replicatedLogManager.LastInformationRecord.AwaitProcessing().ConfigureAwait(false);
await this.recordsProcessor.WaitForLogicalRecordsProcessingAsync().ConfigureAwait(false);
var acksOpen = Interlocked.Decrement(ref acksOutstanding);
Utility.Assert(acksOpen >= 0, "acksOpen {0} >= 0", acksOpen);
if (acksOpen != 0)
{
// wait for all the callbacks above to finish running and acknowleding
await allOperationsAckedTcs.Task.ConfigureAwait(false);
}
Utility.Assert(acksOutstanding == 0, "acksOutstanding == 0");
#if !DotNetCoreClr
// These are new events defined in System.Fabric, existing CoreCLR apps would break
// if these events are refernced as it wont be found. As CoreCLR apps carry System.Fabric
// along with application
// This is just a mitigation for now. Actual fix being tracked via bug# 11614507
FabricEvents.Events.DrainCompleted(
this.tracer.Type,
"Copy",
"Completed",
copiedRecordNumber,
(uint)lastCopiedRecord.RecordType,
lastCopiedRecord.Lsn.LSN,
lastCopiedRecord.Psn.PSN,
lastCopiedRecord.RecordPosition);
#endif
}
private async Task DrainReplicationStreamAsync(IOperationStream replicationStream)
{
FabricEvents.Events.DrainStart(this.tracer.Type, "Replication stream");
TaskCompletionSource <object> allOperationsAckedTcs = new TaskCompletionSource <object>();
var lastReplicatedRecord = LogicalLogRecord.InvalidLogicalLogRecord;
long replicatedRecordNumber = 0, acksOutstanding = 1, bytesOutstanding = 0;
this.roleContextDrainState.OnDrainReplication();
do
{
var drainTask = replicationStream.GetOperationAsync(CancellationToken.None);
if (drainTask.IsCompleted == false)
{
this.replicatedLogManager.LogManager.FlushAsync("DrainReplicationStream.IsEmpty").IgnoreExceptionVoid();
await drainTask.ConfigureAwait(false);
}
var operation = drainTask.GetAwaiter().GetResult();
if (operation != null)
{
var data = operation.Data;
#if DEBUG
ReplicatedLogManager.ValidateOperationData(data, "DrainReplicationStream LSN: " + operation.SequenceNumber);
#endif
lastReplicatedRecord = (LogicalLogRecord)LogRecord.FromOperationData(data);
lastReplicatedRecord.Lsn = new LogicalSequenceNumber(operation.SequenceNumber);
await this.LogLogicalRecordOnSecondaryAsync(lastReplicatedRecord).ConfigureAwait(false);
var acksRemaining = Interlocked.Increment(ref acksOutstanding);
FabricEvents.Events.DrainReplicationReceive(
this.tracer.Type,
replicatedRecordNumber,
(uint)lastReplicatedRecord.RecordType,
lastReplicatedRecord.Lsn.LSN,
acksRemaining);
++replicatedRecordNumber;
long operationSize = Utility.GetOperationSize(data);
var bytesRemaining = Interlocked.Add(ref bytesOutstanding, operationSize);
if (((this.replicatorSettings.PublicSettings.MaxSecondaryReplicationQueueSize / 2 <= acksRemaining) ||
((this.replicatorSettings.PublicSettings.MaxSecondaryReplicationQueueMemorySize > 0) &&
(this.replicatorSettings.PublicSettings.MaxSecondaryReplicationQueueMemorySize / 2 <= bytesRemaining))) ||
((this.replicatorSettings.PublicSettings.MaxPrimaryReplicationQueueSize / 2 <= acksRemaining) ||
((this.replicatorSettings.PublicSettings.MaxPrimaryReplicationQueueMemorySize > 0) &&
(this.replicatorSettings.PublicSettings.MaxPrimaryReplicationQueueMemorySize / 2 <= bytesRemaining))))
{
FabricEvents.Events.DrainReplicationFlush(
this.tracer.Type,
replicatedRecordNumber,
lastReplicatedRecord.Lsn.LSN,
acksRemaining,
bytesRemaining);
this.replicatedLogManager.LogManager.FlushAsync("DrainReplicationStream.IsFull").IgnoreExceptionVoid();
}
var capturedOperation = operation;
var capturedRecord = lastReplicatedRecord;
lastReplicatedRecord.AwaitFlush().IgnoreException().ContinueWith(
async task =>
{
var acksPending = Interlocked.Decrement(ref acksOutstanding);
if (task.Exception != null)
{
// Signal the drain completion task if needed
if (acksPending == 0)
{
allOperationsAckedTcs.TrySetResult(null);
}
return;
}
var bytesPending = Interlocked.Add(ref bytesOutstanding, -operationSize);
Utility.Assert(
(acksPending >= 0) && (bytesPending >= 0),
"(acksPending >= 0) && (bytesPending >= 0)");
if (acksPending == 0)
{
allOperationsAckedTcs.TrySetResult(null);
}
capturedOperation.Acknowledge();
FabricEvents.Events.DrainReplicationNoise(
this.tracer.Type,
capturedRecord.Lsn.LSN,
acksPending,
bytesPending);
await capturedRecord.AwaitApply().ConfigureAwait(false);
}).IgnoreExceptionVoid();
}
else
{
await this.replicatedLogManager.FlushInformationRecordAsync(
InformationEvent.ReplicationFinished,
closeLog : false,
flushInitiator : "DrainReplicationstream.IsFinished").ConfigureAwait(false);
await this.replicatedLogManager.LastInformationRecord.AwaitProcessing().ConfigureAwait(false);
await this.recordsProcessor.WaitForLogicalRecordsProcessingAsync().ConfigureAwait(false);
var acksPending = Interlocked.Decrement(ref acksOutstanding);
Utility.Assert(acksPending >= 0, "acksPending >= 0");
if (acksPending != 0)
{
await allOperationsAckedTcs.Task.ConfigureAwait(false);
}
Utility.Assert(acksOutstanding == 0, "acksOutstanding == 0");
break;
}
} while (true);
#if !DotNetCoreClr
// These are new events defined in System.Fabric, existing CoreCLR apps would break
// if these events are refernced as it wont be found. As CoreCLR apps carry System.Fabric
// along with application
// This is just a mitigation for now. Actual fix being tracked via bug# 11614507
FabricEvents.Events.DrainCompleted(
this.tracer.Type,
"Replication",
"Completed",
replicatedRecordNumber,
(uint)lastReplicatedRecord.RecordType,
lastReplicatedRecord.Lsn.LSN,
lastReplicatedRecord.Psn.PSN,
lastReplicatedRecord.RecordPosition);
#endif
}
/// <summary>
/// Processes the log record.
/// </summary>
/// <param name="logRecord">The log record to be processed.</param>
/// <param name="isRecoverableRecord">Is this a recoverable record.</param>
public void ProcessLogRecord(LogRecord logRecord, out bool isRecoverableRecord)
{
isRecoverableRecord = true;
var physicalLogRecord = logRecord as PhysicalLogRecord;
if (physicalLogRecord != null)
{
this.ProcessLogRecord(physicalLogRecord);
}
switch (logRecord.RecordType)
{
// Transaction related log records
case LogRecordType.BeginTransaction:
var beginTransactionRecord =
(BeginTransactionOperationLogRecord)logRecord;
this.ProcessLogRecord(beginTransactionRecord, out isRecoverableRecord);
break;
case LogRecordType.Operation:
var operationLogRecord = (OperationLogRecord)logRecord;
this.ProcessLogRecord(operationLogRecord, out isRecoverableRecord);
break;
case LogRecordType.EndTransaction:
var endTransactionRecord = (EndTransactionLogRecord)logRecord;
this.ProcessLogRecord(endTransactionRecord, out isRecoverableRecord);
break;
case LogRecordType.Barrier:
var barrierRecord = (BarrierLogRecord)logRecord;
this.ProcessLogRecord(barrierRecord, out isRecoverableRecord);
break;
// Replicated logical record.
case LogRecordType.Backup:
var backupLogRecord = (BackupLogRecord)logRecord;
this.ProcessLogRecord(backupLogRecord, out isRecoverableRecord);
break;
// Not replicated logical log record.
case LogRecordType.UpdateEpoch:
var updateEpochLogRecord = (UpdateEpochLogRecord)logRecord;
this.ProcessLogRecord(updateEpochLogRecord, out isRecoverableRecord);
break;
// Checkpoint cases
case LogRecordType.BeginCheckpoint:
var beginCheckpointRecord = (BeginCheckpointLogRecord)logRecord;
this.ProcessLogRecord(beginCheckpointRecord, out isRecoverableRecord);
break;
case LogRecordType.EndCheckpoint:
var endCheckpointLogRecord = (EndCheckpointLogRecord)logRecord;
this.ProcessLogRecord(endCheckpointLogRecord, out isRecoverableRecord);
break;
case LogRecordType.CompleteCheckpoint:
var completeCheckpointLogRecord = (CompleteCheckpointLogRecord)logRecord;
this.ProcessLogRecord(completeCheckpointLogRecord, out isRecoverableRecord);
break;
case LogRecordType.TruncateHead:
var truncateHeadLogRecord = (TruncateHeadLogRecord)logRecord;
this.ProcessLogRecord(truncateHeadLogRecord, out isRecoverableRecord);
break;
case LogRecordType.Indexing:
var indexingLogRecord = (IndexingLogRecord)logRecord;
this.ProcessLogRecord(indexingLogRecord, out isRecoverableRecord);
break;
case LogRecordType.Information:
var informationRecord = (InformationLogRecord)logRecord;
this.ProcessLogRecord(informationRecord, out isRecoverableRecord);
break;
case LogRecordType.TruncateTail:
var truncateTailLogRecord = (TruncateTailLogRecord)logRecord;
this.ProcessLogRecord(truncateTailLogRecord, out isRecoverableRecord);
break;
default:
Utility.CodingError("Unexpected record type {0}", logRecord.RecordType);
break;
}
}
/// <summary>
/// Processes the log record.
/// </summary>
/// <param name="logRecord">The log record to be processed.</param>
public void ProcessLogRecord(LogRecord logRecord)
{
var isRecoverableRecord = true;
this.ProcessLogRecord(logRecord, out isRecoverableRecord);
}
internal async Task <LogRecord> GetPreviousLogRecord(ulong recordPosition)
{
this.readStream.Position = (long)recordPosition;
return(await LogRecord.ReadPreviousRecordAsync(this.readStream).ConfigureAwait(false));
}
internal EndTransactionLogRecord ReifyTransaction(EndTransactionLogRecord record)
{
Utility.Assert(
record.Transaction.IsAtomicOperation == false,
"record.Transaction.IsAtomicOperation == false");
Utility.Assert(
LogRecord.IsInvalidRecord(record.ParentTransactionRecord) == true,
"LogRecord.IsInvalidRecord(record.ParentTransactionRecord) == true");
BeginTransactionOperationLogRecord reifiedBeginTransactionRecord = null;
EndTransactionLogRecord reifiedEndTransactionRecord = null;
int i;
lock (this.txmapLock)
{
for (i = this.completedTransactions.Count - 1; i >= 0; i--)
{
if (this.completedTransactions[i].Transaction == record.Transaction)
{
reifiedBeginTransactionRecord = this.completedTransactions[i];
Utility.Assert(
reifiedBeginTransactionRecord.IsSingleOperationTransaction == false,
"reifiedBeginTransactionRecord.IsSingleOperationTransaction == false");
this.completedTransactions.RemoveAt(i);
break;
}
}
Utility.Assert(i > -1, "Begin transaction record is not present in completed transactions");
for (i = this.unstableTransactions.Count - 1; i >= 0; i--)
{
if (this.unstableTransactions[i].Transaction == record.Transaction)
{
reifiedEndTransactionRecord = this.unstableTransactions[i];
this.unstableTransactions.RemoveAt(i);
break;
}
}
Utility.Assert(i > -1, "End transaction record is not present in unstable transactions");
this.latestRecords[record.Transaction.Id] = reifiedEndTransactionRecord.ParentTransactionRecord;
reifiedEndTransactionRecord.ParentTransactionRecord.ChildTransactionRecord =
TransactionLogRecord.InvalidTransactionLogRecord;
TransactionLogRecord parentRecord = reifiedEndTransactionRecord;
BeginTransactionOperationLogRecord chainedBeginTransactionRecord;
do
{
parentRecord = parentRecord.ParentTransactionRecord;
chainedBeginTransactionRecord = parentRecord as BeginTransactionOperationLogRecord;
} while (chainedBeginTransactionRecord == null);
Utility.Assert(
reifiedBeginTransactionRecord == chainedBeginTransactionRecord,
"reifiedBeginTransactionRecord == chainedBeginTransactionRecord");
Utility.Assert(
reifiedBeginTransactionRecord.IsEnlistedTransaction,
"reifiedBeginTransactionRecord.IsEnlistedTransaction == true");
this.transactionIdPendingTransactionsPair[reifiedBeginTransactionRecord.Transaction.Id] =
reifiedBeginTransactionRecord;
this.lsnPendingTransactionsPair[reifiedBeginTransactionRecord.Lsn.LSN] = reifiedBeginTransactionRecord;
}
return(reifiedEndTransactionRecord);
}
public async Task ImmediatelyProcessRecord(
LogRecord record,
Exception flushException,
RecordProcessingMode processingMode)
{
Utility.Assert(
processingMode > RecordProcessingMode.Normal,
"processingMode ({0}) > RecordProcessingMode.Normal",
processingMode);
// TODO: Temporary double check.
Utility.Assert(record.RecordType != LogRecordType.Backup, "record.RecordType != LogRecordType.Backup");
Exception exception = null;
if (flushException != null)
{
Utility.Assert(
this.logException != null,
"FlushException is {0} and this.logException is null",
flushException);
exception = flushException;
}
// In case there was an apply failure, we should fault any further applies of any records.
// Without this, we could end up assuming that all applies have succeeded and as a result, issue a checkpoint call
if (exception == null)
{
exception = this.serviceException;
}
FabricEvents.Events.RecordProcessedImmediatelyNoise(
this.tracer.Type,
(int)this.roleContextDrainState.DrainingStream,
record.Psn.PSN);
var information = string.Empty;
switch (record.RecordType)
{
case LogRecordType.TruncateHead:
this.checkpointManager.ApplyLogHeadTruncationIfPermitted(exception, record);
break;
case LogRecordType.BeginCheckpoint:
if (processingMode == RecordProcessingMode.ProcessImmediately)
{
goto default;
}
await this.checkpointManager.ApplyCheckpointIfPermitted(exception, record).ConfigureAwait(false);
break;
case LogRecordType.Information:
information = '-' + ((InformationLogRecord)record).InformationEvent.ToString();
goto case LogRecordType.EndCheckpoint;
case LogRecordType.EndCheckpoint:
case LogRecordType.TruncateTail:
case LogRecordType.Indexing:
case LogRecordType.UpdateEpoch:
goto default;
default:
record.CompletedApply(exception);
break;
}
if (processingMode == RecordProcessingMode.ProcessImmediately)
{
FabricEvents.Events.RecordProcessedImmediately(
this.tracer.Type,
(int)this.roleContextDrainState.DrainingStream,
information,
record.Psn.PSN);
record.CompletedProcessing(null);
}
return;
}
/// <summary>
/// Write the backup log file.
/// </summary>
/// <param name="stream">Backup log stream.</param>
/// <param name="logRecords">The log records.</param>
/// <param name="cancellationToken">Token used to signal cancellation.</param>
/// <returns>Task that represents the asynchronous operation.</returns>
private async Task WriteLogRecordsAsync(
Stream stream,
IAsyncEnumerator <LogRecord> logRecords,
CancellationToken cancellationToken)
{
var firstIndexingRecordProcessed = false;
using (var memoryStream = new MemoryStream(InitialSizeOfMemoryStream))
using (var binaryWriter = new BinaryWriter(memoryStream))
using (var recordWriter = new BinaryWriter(new MemoryStream()))
{
// Reserve an 'int' at the start to store the size of the block
memoryStream.Position += sizeof(int);
while (true == await logRecords.MoveNextAsync(cancellationToken).ConfigureAwait(false))
{
var record = logRecords.Current;
var indexingLogRecord = record as IndexingLogRecord;
if (indexingLogRecord != null)
{
if (false == firstIndexingRecordProcessed)
{
this.IndexingRecordEpoch = indexingLogRecord.CurrentEpoch;
this.IndexingRecordLsn = indexingLogRecord.Lsn;
firstIndexingRecordProcessed = true;
}
this.LastBackedUpEpoch = indexingLogRecord.CurrentEpoch;
}
var updateEpochLogRecord = record as UpdateEpochLogRecord;
if (updateEpochLogRecord != null)
{
this.LastBackedUpEpoch = updateEpochLogRecord.Epoch;
}
this.LastBackedUpLsn = record.Lsn;
var operationData = LogRecord.WriteRecord(record, recordWriter, isPhysicalWrite: false, setRecordLength: false);
// TODO: Fix this by using operationdata in this class
foreach (var buffer in operationData)
{
binaryWriter.Write(buffer.Array, buffer.Offset, buffer.Count);
}
this.Count++;
// Flush the block after it's large enough.
if (memoryStream.Position >= MinimumIntermediateFlushSize)
{
await this.WriteLogRecordBlockAsync(stream, memoryStream, binaryWriter, cancellationToken).ConfigureAwait(false);
}
// Check for cancellation.
cancellationToken.ThrowIfCancellationRequested();
}
// Flush the block, if there's any remaining data (ignoring the block size 'int' at the start).
if (memoryStream.Position > sizeof(int))
{
await this.WriteLogRecordBlockAsync(stream, memoryStream, binaryWriter, cancellationToken).ConfigureAwait(false);
}
await stream.FlushAsync(cancellationToken).ConfigureAwait(false);
}
// If no logical record is being backed up, lastBackedupLsn can be Invalid.
if (this.LastBackedUpLsn == LogicalSequenceNumber.InvalidLsn)
{
this.LastBackedUpLsn = this.IndexingRecordLsn;
}
Utility.Assert(true == firstIndexingRecordProcessed, "Indexing log record must have been processed.");
Utility.Assert(
this.IndexingRecordEpoch.CompareTo(LoggingReplicator.InvalidEpoch) > 0,
"Indexing record epoch has not been set.");
Utility.Assert(
this.LastBackedUpEpoch.CompareTo(LoggingReplicator.InvalidEpoch) > 0,
"Ending epoch has not been set.");
Utility.Assert(
this.IndexingRecordLsn != LogicalSequenceNumber.InvalidLsn,
"Indexing record lsn has not been set.");
Utility.Assert(this.LastBackedUpLsn != LogicalSequenceNumber.InvalidLsn, "Ending lsn has not been set.");
}
internal async Task <PhysicalLogReader> OpenWithRestoreFileAsync(
ReplicaOpenMode openMode,
FabricPerformanceCounterSetInstance perfCounterInstance,
IList <string> backupLogFilePathList,
int flushEveryNKB)
{
this.LogicalLog = await this.CreateLogFileAsync(openMode == ReplicaOpenMode.New, CancellationToken.None).ConfigureAwait(false);
// No usable content in the log
if (this.LogicalLog.WritePosition > 0)
{
await this.LogicalLog.TruncateTail(0, CancellationToken.None).ConfigureAwait(false);
// Remove all contents and reset write cursor back to 0
Utility.Assert(
this.LogicalLog.Length == 0 && this.LogicalLog.WritePosition == 0,
"{0}: this.logicalLog.Length: {1} this.logicalLog.WritePosition: {2}",
this.tracer.Type,
this.LogicalLog.Length,
this.LogicalLog.WritePosition);
}
using (PhysicalLogWriter logWriter = new PhysicalLogWriter(
this.LogicalLog,
this.emptyCallbackManager,
this.Tracer,
this.MaxWriteCacheSizeInMB,
this.IncomingBytesRateCounterWriter,
this.LogFlushBytesRateCounterWriter,
this.BytesPerFlushCounterWriter,
this.AvgFlushLatencyCounterWriter,
this.AvgSerializationLatencyCounterWriter,
true))
{
LogRecord record = null;
LogRecordsMap logRecordsMap = null;
long bufferedRecordsSizeBytes = -1;
long backupRecordIndex = 0;
foreach (string backupLogFilePath in backupLogFilePathList)
{
BackupLogFile backupLogFile = await BackupLogFile.OpenAsync(
backupLogFilePath,
CancellationToken.None).ConfigureAwait(false);
using (var backupLogEnumerator = backupLogFile.GetAsyncEnumerator())
{
if (logRecordsMap == null)
{
bool hasFirstRecord = await backupLogEnumerator.MoveNextAsync(CancellationToken.None).ConfigureAwait(false);
Utility.Assert(hasFirstRecord, "{0}: Backup must include at least six records.", this.tracer.Type);
// If the log is being restored.
// First record must be a indexing log record. Flush it.
LogRecord firstRecordFromBackupLog = backupLogEnumerator.Current;
Utility.Assert(
null != firstRecordFromBackupLog,
"{0}: BackupLogEnumerator will never return null",
this.tracer.Type);
Utility.Assert(
false == LogRecord.IsInvalidRecord(firstRecordFromBackupLog),
"{0}: First record read from the backup log cannot be invalid",
this.tracer.Type);
IndexingLogRecord logHead = firstRecordFromBackupLog as IndexingLogRecord;
Utility.Assert(
null != logHead,
"{0}: First record read from the backup log must be indexing log record: Type: {1} LSN: {2} PSN: {3} Position: {4}",
this.tracer.Type,
firstRecordFromBackupLog.RecordType,
firstRecordFromBackupLog.Lsn.LSN,
firstRecordFromBackupLog.Psn.PSN,
firstRecordFromBackupLog.RecordPosition);
logRecordsMap = new LogRecordsMap(logHead, this.Tracer);
logRecordsMap.ProcessLogRecord(logHead);
bufferedRecordsSizeBytes = logWriter.InsertBufferedRecord(logHead);
// Note that logHead.PreviousPhysicalRecord is an InvalidLogRecord.
backupRecordIndex++;
FabricEvents.Events.RestoreOperationAsync(
this.Tracer.Type,
logHead.RecordType.ToString(),
backupRecordIndex,
logHead.Lsn.LSN,
logHead.Psn.PSN,
long.MaxValue);
}
while (await backupLogEnumerator.MoveNextAsync(CancellationToken.None).ConfigureAwait(false))
{
record = backupLogEnumerator.Current;
logRecordsMap.ProcessLogRecord(record);
// Note: Function inserts a record to the buffer where it waits to be flushed and return
// the new size of the whole buffer.
bufferedRecordsSizeBytes = logWriter.InsertBufferedRecord(record);
backupRecordIndex++;
FabricEvents.Events.RestoreOperationAsync(
this.Tracer.Type,
record.RecordType.ToString(),
backupRecordIndex,
record.Lsn.LSN,
record.Psn.PSN,
record.PreviousPhysicalRecord.Psn.PSN);
// TODO: Use a backup config for this flush size determination
if (bufferedRecordsSizeBytes > flushEveryNKB * 1024)
{
string intermediateFlushMessage = string.Format(
CultureInfo.InvariantCulture,
"LogManager: OpenWithRestoreFile (Restore) Intermediate Flush Size: {0} bytes, Index: {1}",
bufferedRecordsSizeBytes,
backupRecordIndex);
await logWriter.FlushAsync(intermediateFlushMessage).ConfigureAwait(false);
// This additional await is required to ensure the log record was indeed flushed.
// Without this, the flushasync could succeed, but the log record flush could have failed due to a write error
await record.AwaitFlush().ConfigureAwait(false);
bufferedRecordsSizeBytes = 0;
}
}
}
}
// Note: Move the last flush for remaining items out of the loop to avoid unnecessary flush in the
// case of each iteration has a small number of un-flushed log records.
if (bufferedRecordsSizeBytes > 0)
{
string flushMessage = string.Format(
CultureInfo.InvariantCulture,
"LogManager: OpenWithRestoreFile (Restore)");
await logWriter.FlushAsync(flushMessage).ConfigureAwait(false);
// This additional await is required to ensure the log record was indeed flushed.
// Without this, the flushasync could succeed, but the log record flush could have failed due to a write error
await record.AwaitFlush().ConfigureAwait(false);
}
}
return(new PhysicalLogReader(this));
}