public async Task PerformRecoveryAsync(
RecoveredOrCopiedCheckpointLsn recoveredOrCopiedCheckpointLsn,
OperationProcessor recordsProcessor,
CheckpointManager checkpointManager,
TransactionManager transactionManager,
LogRecordsDispatcher logRecordsDispatcher,
ReplicatedLogManager replicatedLogManager)
{
var lastPhysicalRecord = PhysicalLogRecord.InvalidPhysicalLogRecord;
LogicalSequenceNumber lsn;
var recoveredRecords = new List <LogRecord>();
var recoveredLastCompletedBeginCheckpointRecord = await this.RecoveryLogsReader.GetLastCompletedBeginCheckpointRecord(this.RecoveredLastEndCheckpointRecord).ConfigureAwait(false);
var recoveredLastCompletedBeginCheckpointRecordPosition = recoveredLastCompletedBeginCheckpointRecord.RecordPosition;
var recoveryStartingPosition = recoveredLastCompletedBeginCheckpointRecordPosition - recoveredLastCompletedBeginCheckpointRecord.EarliestPendingTransactionOffset;
// Set the recovered lsn before performing recovery as it impacts unlock callback logic during recovery
recoveredOrCopiedCheckpointLsn.Update(recoveredLastCompletedBeginCheckpointRecord.Lsn);
var trace =
string.Format(
CultureInfo.InvariantCulture,
"PerformRecoveryAsync: " + Environment.NewLine
+ " Recovered last completed begin checkpoint record." + Environment.NewLine
+ " Type: {0} LSN: {1} PSN:{2} Position: {3}" + Environment.NewLine
+ " Recovery Starting Position: {4} Recovery Starting Epoch: {5},{6}" + Environment.NewLine
+ " LogCompleteCheckpointAfterRecovery: {7}" + " Recovered ProgressVector: {8}"
+ Environment.NewLine,
recoveredLastCompletedBeginCheckpointRecord.RecordType,
recoveredLastCompletedBeginCheckpointRecord.Lsn.LSN,
recoveredLastCompletedBeginCheckpointRecord.Psn.PSN,
recoveredLastCompletedBeginCheckpointRecord.RecordPosition,
recoveryStartingPosition,
recoveredLastCompletedBeginCheckpointRecord.Epoch.DataLossNumber,
recoveredLastCompletedBeginCheckpointRecord.Epoch.ConfigurationNumber,
this.logCompleteCheckpointAfterRecovery,
recoveredLastCompletedBeginCheckpointRecord.ProgressVector.ToString(Constants.ProgressVectorMaxStringSizeInKb));
FabricEvents.Events.Api(tracer.Type, trace);
LogRecord lastRecoverableRecord = null;
replicatedLogManager.LogManager.SetSequentialAccessReadSize(
this.RecoveryLogsReader.ReadStream,
LogManager.ReadAheadBytesForSequentialStream);
// Updated to the recovered value in LogRecordsMap during successful recovery
long lastPeriodicTruncationTimeTicks = 0;
using (var records = new LogRecords(this.RecoveryLogsReader.ReadStream, recoveryStartingPosition, this.tailRecordAtStart.RecordPosition))
{
var hasMoved = await records.MoveNextAsync(CancellationToken.None).ConfigureAwait(false);
Utility.Assert(hasMoved == true, "hasMoved == true");
lsn = records.Current.Lsn;
if (recoveredLastCompletedBeginCheckpointRecord.EarliestPendingTransactionOffset != 0)
{
lsn -= 1;
}
var logRecordsMap = new LogRecordsMap(
lsn,
transactionManager.TransactionsMap,
recoveredLastCompletedBeginCheckpointRecord.Epoch,
checkpointManager.LastStableLsn,
recoveredLastCompletedBeginCheckpointRecord.ProgressVector,
recoveredLastCompletedBeginCheckpointRecord,
this.tracer,
this.RecoveredLastEndCheckpointRecord);
do
{
var isRecoverableRecord = true;
var record = records.Current;
record.CompletedFlush(null);
Utility.Assert(
record.PreviousPhysicalRecord == logRecordsMap.LastPhysicalRecord,
"record.PreviousPhysicalRecord == lastPhysicalRecord");
logRecordsMap.ProcessLogRecord(record, out isRecoverableRecord);
if (isRecoverableRecord == true)
{
recoveredRecords.Add(record);
lastRecoverableRecord = record;
if (LoggingReplicator.IsBarrierRecord(record) &&
recoveredRecords.Count >= ReplicatorDynamicConstants.ParallelRecoveryBatchSize)
{
logRecordsDispatcher.DispatchLoggedRecords(new LoggedRecords(recoveredRecords, null));
recoveredRecords = new List <LogRecord>();
this.recoveryException = recordsProcessor.ServiceException;
if (this.recoveryException == null)
{
this.recoveryException = recordsProcessor.LogException;
}
if (this.recoveryException != null)
{
// If there was an apply or unlock failure, report fault does not help during recovery because the replica is not opened yet.
// The only solution here is to throw during OpenAsync
FabricEvents.Events.Api(
tracer.Type,
"PerformRecoveryAsync: RecoveryFailed");
await lastRecoverableRecord.AwaitProcessing().ConfigureAwait(false);
await recordsProcessor.WaitForAllRecordsProcessingAsync().ConfigureAwait(false);
throw this.recoveryException;
}
}
}
else
{
Utility.Assert(LoggingReplicator.IsBarrierRecord(record) == false, "IsBarrierRecord(record) == false");
record.CompletedApply(null);
record.CompletedProcessing(null);
}
hasMoved = await records.MoveNextAsync(CancellationToken.None).ConfigureAwait(false);
} while (hasMoved == true);
this.LastRecoveredAtomicRedoOperationLsn = logRecordsMap.LastRecoveredAtomicRedoOperationLsn;
checkpointManager.ResetStableLsn(logRecordsMap.LastStableLsn);
lastPhysicalRecord = logRecordsMap.LastPhysicalRecord;
lsn = logRecordsMap.LastLogicalSequenceNumber;
if (recoveredRecords.Count > 0)
{
logRecordsDispatcher.DispatchLoggedRecords(new LoggedRecords(recoveredRecords, null));
}
var tailRecord = records.Current;
FabricEvents.Events.Api(
tracer.Type,
"PerformRecoveryAsync: Current tail record Type: " + tailRecord.RecordType + " LSN: "
+ tailRecord.Lsn.LSN + " PSN: " + tailRecord.Psn.PSN + " Position: " + tailRecord.RecordPosition);
Utility.Assert(
lastPhysicalRecord == records.LastPhysicalRecord,
"lastPhysicalRecord == records.LastPhysicalRecord");
Utility.Assert(
(tailRecord == lastPhysicalRecord) || (tailRecord.PreviousPhysicalRecord == lastPhysicalRecord),
"(tailRecord == lastPhysicalRecord) || "
+ "(tailRecord.PreviousPhysicalRecord == lastPhysicalRecord), " + "LastPhysicalRecord PSN: {0}",
lastPhysicalRecord.Psn.PSN);
Utility.Assert(
logRecordsMap.LastCompletedEndCheckpointRecord != null,
"this.lastCompletedEndCheckpointRecord != null");
Utility.Assert(
logRecordsMap.LastInProgressCheckpointRecord == null,
"this.lastInProgressCheckpointRecord == null");
Utility.Assert(logRecordsMap.LastLinkedPhysicalRecord != null, "this.lastLinkedPhysicalRecord != nul");
Utility.Assert(lsn == tailRecord.Lsn, "lsn == tailRecord.LastLogicalSequenceNumber");
// Disable read ahead as indexing physical records will read the log backwards
replicatedLogManager.LogManager.SetSequentialAccessReadSize(this.RecoveryLogsReader.ReadStream, 0);
await this.RecoveryLogsReader.IndexPhysicalRecords(lastPhysicalRecord).ConfigureAwait(false);
var callbackManager = new PhysicalLogWriterCallbackManager(this.flushedRecordsCallback);
callbackManager.FlushedPsn = tailRecord.Psn + 1;
replicatedLogManager.LogManager.PrepareToLog(tailRecord, callbackManager);
replicatedLogManager.Reuse(
recoveredLastCompletedBeginCheckpointRecord.ProgressVector,
logRecordsMap.LastCompletedEndCheckpointRecord,
logRecordsMap.LastInProgressCheckpointRecord,
logRecordsMap.LastLinkedPhysicalRecord,
replicatedLogManager.LastInformationRecord,
(IndexingLogRecord)this.RecoveryLogsReader.StartingRecord,
logRecordsMap.CurrentLogTailEpoch,
lsn);
this.RecoveredLsn = lsn;
// GopalK: The order of the following statements is significant
if (this.logCompleteCheckpointAfterRecovery)
{
replicatedLogManager.CompleteCheckpoint();
}
replicatedLogManager.Information(InformationEvent.Recovered);
await replicatedLogManager.LogManager.FlushAsync("PerformRecovery").ConfigureAwait(false);
await lastRecoverableRecord.AwaitProcessing().ConfigureAwait(false);
await recordsProcessor.WaitForAllRecordsProcessingAsync().ConfigureAwait(false);
lastPeriodicTruncationTimeTicks = logRecordsMap.LastPeriodicTruncationTimeTicks;
}
this.recoveryException = recordsProcessor.ServiceException;
if (this.recoveryException == null)
{
this.recoveryException = recordsProcessor.LogException;
}
if (this.recoveryException != null)
{
FabricEvents.Events.Api(
tracer.Type,
"PerformRecoveryAsync: RecoveryFailed");
// If there was an apply or unlock failure, report fault does not help during recovery because the replica is not opened yet.
// The only solution here is to throw during OpenAsync
throw this.recoveryException;
}
checkpointManager.Recover(
recoveredLastCompletedBeginCheckpointRecord,
lastPeriodicTruncationTimeTicks);
}
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));
}
