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)); }