Scanning Log: Reconstructing Crash-Time State

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59

struct MasterRecord {
    LSN     last_checkpoint_lsn;  // Points to BEGIN_CHECKPOINT
    uint64  checkpoint_number;     // Monotonically increasing
    uint32  checksum;              // Validates integrity
};
 
LSN RecoveryManager::findLastCheckpoint() {
    // Step 1: Read master record from known location
    MasterRecord master = readMasterRecord();
    
    // Step 2: Validate checksum
    if (!validateChecksum(master)) {
        // Master record corrupted - need backup strategy
        log_warn("Master record checksum failed, searching for checkpoint");
        return findCheckpointByScanning();
    }
    
    // Step 3: Verify the checkpoint record exists and is valid
    LSN ckpt_lsn = master.last_checkpoint_lsn;
    LogRecord ckpt_record = log_manager.readLog(ckpt_lsn);
    
    if (ckpt_record.type != LogType::BEGIN_CHECKPOINT) {
        log_error("Master record points to non-checkpoint LSN %d", ckpt_lsn);
        return findCheckpointByScanning();
    }
    
    // Step 4: Find the corresponding END_CHECKPOINT
    // It contains the actual DPT and Transaction Table snapshots
    LSN end_ckpt_lsn = findEndCheckpoint(ckpt_lsn);
    
    if (end_ckpt_lsn == INVALID_LSN) {
        // Crash occurred during checkpoint - use previous checkpoint
        log_warn("Incomplete checkpoint at %d, seeking earlier", ckpt_lsn);
        return findPreviousCheckpoint(ckpt_lsn);
    }
    
    log_info("Found valid checkpoint: BEGIN=%d, END=%d", ckpt_lsn, end_ckpt_lsn);
    return ckpt_lsn;
}
 
LSN RecoveryManager::findEndCheckpoint(LSN begin_lsn) {
    // Scan forward from BEGIN_CHECKPOINT to find matching END_CHECKPOINT
    LSN current = begin_lsn;
    
    while (current != END_OF_LOG) {
        LogRecord record = log_manager.readLog(current);
        
        if (record.type == LogType::END_CHECKPOINT) {
            // Verify it matches our BEGIN_CHECKPOINT
            if (record.begin_checkpoint_lsn == begin_lsn) {
                return current;
            }
        }
        
        current = record.next_lsn;
    }
    
    return INVALID_LSN;  // No matching END found
}

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57

void AnalysisPhase::initializeFromCheckpoint(LSN checkpoint_lsn) {
    // Read the END_CHECKPOINT record which contains the snapshots
    LSN end_ckpt_lsn = findEndCheckpoint(checkpoint_lsn);
    EndCheckpointRecord end_ckpt = log_manager.readLog(end_ckpt_lsn);
    
    // Initialize Dirty Page Table
    dirty_page_table.clear();
    for (const auto& dpt_entry : end_ckpt.dirty_page_table) {
        DirtyPageEntry entry;
        entry.page_id = dpt_entry.page_id;
        entry.recovery_lsn = dpt_entry.recovery_lsn;
        
        dirty_page_table.insert(dpt_entry.page_id, entry);
    }
    
    log_info("Loaded DPT from checkpoint: %d dirty pages", 
             end_ckpt.dirty_page_table.size());
    
    // Initialize Transaction Table
    transaction_table.clear();
    for (const auto& txn_entry : end_ckpt.transaction_table) {
        TransactionEntry entry;
        entry.txn_id = txn_entry.txn_id;
        entry.state = txn_entry.state;
        entry.last_lsn = txn_entry.last_lsn;
        entry.undo_next_lsn = txn_entry.undo_next_lsn;
        
        transaction_table.insert(txn_entry.txn_id, entry);
    }
    
    log_info("Loaded Transaction Table: %d active transactions",
             end_ckpt.transaction_table.size());
             
    // Set the scan starting point
    // Start from the BEGIN_CHECKPOINT LSN
    // (Some implementations start from END_CHECKPOINT instead)
    scan_start_lsn = checkpoint_lsn;
}
 
/*
 * Example Checkpoint State:
 * 
 * BEGIN_CHECKPOINT at LSN 5000
 * END_CHECKPOINT at LSN 5050 contains:
 * 
 * Dirty Page Table:
 *   Page 100: recLSN = 4500
 *   Page 200: recLSN = 4800
 *   Page 300: recLSN = 5010 (dirtied between BEGIN and END checkpoint)
 * 
 * Transaction Table:
 *   T1: state=ACTIVE, lastLSN=4900, undoNextLSN=4900
 *   T2: state=ACTIVE, lastLSN=5020, undoNextLSN=5020
 *   T3: state=ABORTING, lastLSN=5040, undoNextLSN=4600
 * 
 * These become the initial state for the log scan.
 */

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51

struct AnalysisResult {
    LSN                 redo_lsn;       // Where redo should start
    vector<UndoTask>    undo_list;      // Transactions needing undo
    DirtyPageTable      final_dpt;      // Crash-time DPT state
    TransactionTable    final_txn_table; // Crash-time transaction state
};
 
AnalysisResult AnalysisPhase::run() {
    // Step 1: Find and load checkpoint
    LSN checkpoint_lsn = findLastCheckpoint();
    initializeFromCheckpoint(checkpoint_lsn);
    
    // Step 2: Scan log from checkpoint to end
    LSN current_lsn = checkpoint_lsn;
    
    while (true) {
        // Read next log record
        LogRecord record = log_manager.readLog(current_lsn);
        
        if (record.type == LogType::END_OF_LOG) {
            break;  // Reached end of log
        }
        
        // Process this record
        processLogRecord(record, current_lsn);
        
        // Move to next record
        current_lsn = record.next_lsn;
        if (current_lsn == INVALID_LSN) {
            break;  // Reached end
        }
    }
    
    // Step 3: Determine RedoLSN
    LSN redo_lsn = computeRedoLSN();
    
    // Step 4: Build undo list from transaction table
    vector<UndoTask> undo_list = buildUndoList();
    
    // Step 5: Return results
    AnalysisResult result;
    result.redo_lsn = redo_lsn;
    result.undo_list = undo_list;
    result.final_dpt = dirty_page_table;
    result.final_txn_table = transaction_table;
    
    log_info("Analysis complete: RedoLSN=%d, %d transactions to undo",
             redo_lsn, undo_list.size());
    
    return result;
}

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49

void AnalysisPhase::processLogRecord(const LogRecord& record, LSN lsn) {
    TransactionID tid = record.txn_id;
    
    switch (record.type) {
        // ===== Data Modification Records =====
        case LogType::UPDATE:
        case LogType::INSERT:
        case LogType::DELETE:
            processDataModification(record, lsn);
            break;
            
        // ===== Compensation Log Records =====
        case LogType::CLR:
            processCLR(record, lsn);
            break;
            
        // ===== Transaction Control Records =====
        case LogType::BEGIN:
            processBegin(record, lsn);
            break;
            
        case LogType::COMMIT:
            processCommit(record, lsn);
            break;
            
        case LogType::ABORT:
            processAbort(record, lsn);
            break;
            
        case LogType::END:
            processEnd(record, lsn);
            break;
            
        // ===== Checkpoint Records =====
        case LogType::BEGIN_CHECKPOINT:
        case LogType::END_CHECKPOINT:
            // Already processed during initialization - skip
            break;
            
        // ===== Other Records =====
        case LogType::PREPARE:  // For 2PC
            processPrepare(record, lsn);
            break;
            
        default:
            log_warn("Unknown log record type %d at LSN %d", 
                    record.type, lsn);
    }
}

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39

/*
 * Scenario Timeline:
 * 
 * LSN 1000: T1 UPDATE page 10
 * LSN 1050: T1 UPDATE page 20
 * LSN 1100: T1 COMMIT
 * LSN 1110: Log flushed to disk (commit is durable)
 * --- CRASH before END record written ---
 * 
 * Analysis sees: COMMIT at 1100, no END
 * Transaction state: COMMITTING
 * 
 * Correct behavior: Do NOT undo T1's operations
 * During Redo: Replay T1's operations if needed
 * After Redo: Write END record for T1 to clean up
 */
 
vector<UndoTask> AnalysisPhase::buildUndoList() {
    vector<UndoTask> undo_list;
    
    for (const auto& [tid, entry] : transaction_table) {
        if (entry.state == TransactionState::COMMITTING) {
            // COMMIT seen but no END - transaction IS committed
            // Will write END during redo phase cleanup
            log_info("Transaction %d committed but incomplete - will write END", tid);
            continue;  // Do NOT add to undo list
        }
        
        if (entry.state == TransactionState::UNDO) {
            // Needs undo
            UndoTask task;
            task.txn_id = tid;
            task.undo_next_lsn = entry.undo_next_lsn;
            undo_list.push_back(task);
        }
    }
    
    return undo_list;
}

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34

/*
 * Scenario Timeline:
 * 
 * LSN 100: T1 UPDATE page 10
 * LSN 150: T1 UPDATE page 20
 * LSN 200: T1 UPDATE page 30
 * LSN 250: T1 ABORT (user requested rollback)
 * LSN 260: T1 CLR undoing LSN 200 (undoNextLSN = 150)
 * --- CRASH ---
 * 
 * Analysis finds:
 *   T1: state=UNDO, lastLSN=260, undoNextLSN=150
 * 
 * Undo phase will:
 *   1. Start from undoNextLSN=150 (NOT from 260)
 *   2. Undo LSN 150 (write CLR with undoNextLSN=100)
 *   3. Undo LSN 100 (write CLR with undoNextLSN=null)
 *   4. Write END for T1
 * 
 * LSN 200's undo is skipped because CLR 260 already handled it
 */
 
void AnalysisPhase::processCLR(const LogRecord& record, LSN lsn) {
    TransactionID tid = record.txn_id;
    
    TransactionEntry& entry = transaction_table.getOrCreate(tid);
    entry.last_lsn = lsn;
    
    // CLR's undoNextLSN tells us where rollback will resume
    // This is the KEY to avoiding repeated undo work
    entry.undo_next_lsn = record.undo_next_lsn;
    
    log_debug("T%d CLR: undoNextLSN advances to %d", tid, record.undo_next_lsn);
}

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39

/*
 * Why the DPT might be conservative:
 * 
 * 1. Checkpoint captures DPT with Page 100 (recLSN=500)
 * 2. Background flush writes Page 100 to disk at LSN 600
 * 3. Page 100 is now clean, but Analysis doesn't know this
 * 4. Crash occurs
 * 5. Analysis still has Page 100 in DPT
 * 
 * Is this a problem? NO!
 * 
 * During Redo:
 *   - For each log record at LSN >= recLSN
 *   - Read the page from disk
 *   - Check page's pageLSN
 *   - If pageLSN >= log record's LSN, skip (already applied)
 *   - If pageLSN < log record's LSN, apply redo
 * 
 * So even if Page 100 was flushed at LSN 600:
 *   - Page's on-disk pageLSN = 600
 *   - Any log record with LSN <= 600 will be skipped
 *   - Only records with LSN > 600 will be applied (if any)
 * 
 * The redo phase is IDEMPOTENT - applying the same operation
 * multiple times produces the same result as applying it once.
 */
 
bool RedoPhase::shouldApplyRedo(const LogRecord& record, Page* page) {
    // Check if this operation is already reflected on disk
    LSN page_lsn = page->getPageLSN();
    
    if (page_lsn >= record.lsn) {
        // Page already has this (and possibly later) changes
        log_debug("Skip redo of LSN %d: page LSN is %d", record.lsn, page_lsn);
        return false;
    }
    
    return true;  // Need to apply this redo
}