Examples with StreamLogScan org.apache.derby.impl.store.raw.log.StreamLogScan used on opensource projects

Example 1 with StreamLogScan

use of org.apache.derby.impl.store.raw.log.StreamLogScan in project derby by apache.

the class FileLogger method reprepare.

/**
 * During recovery re-prepare a transaction.
 * <p>
 * After redo() and undo(), this routine is called on all outstanding
 * in-doubt (prepared) transactions.  This routine re-acquires all
 * logical write locks for operations in the xact, and then modifies
 * the transaction table entry to make the transaction look as if it
 * had just been prepared following startup after recovery.
 * <p>
 *
 * @param t                 is the transaction performing the re-prepare
 * @param prepareId         is the transaction ID to be re-prepared
 * @param prepareStopAt     is where the log instant (inclusive) where the
 *                          re-prepare should stop.
 * @param prepareStartAt    is the log instant (inclusive) where re-prepare
 *                          should begin, this is normally the log instant
 *                          of the last log record of the transaction that
 *                          is to be re-prepare.  If null, then re-prepare
 *                          starts from the end of the log.
 *
 * @exception  StandardException  Standard exception policy.
 */
public void reprepare(RawTransaction t, TransactionId prepareId, LogInstant prepareStopAt, LogInstant prepareStartAt) throws StandardException {
    if (SanityManager.DEBUG) {
        if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
            if (prepareStartAt != null) {
                SanityManager.DEBUG(LogToFile.DBG_FLAG, "----------------------------------------------------\n" + "\nBegin of RePrepare : " + prepareId.toString() + "start at " + prepareStartAt.toString() + " stop at " + prepareStopAt.toString() + "\n----------------------------------------------------\n");
            } else {
                SanityManager.DEBUG(LogToFile.DBG_FLAG, "----------------------------------------------------\n" + "\nBegin of Reprepare: " + prepareId.toString() + "start at end of log stop at " + prepareStopAt.toString() + "\n----------------------------------------------------\n");
            }
        }
    }
    // statistics
    int clrskipped = 0;
    int logrecordseen = 0;
    RePreparable lop = null;
    // stream to read the log record - initial size 4096, scanLog needs
    // to resize if the log record is larger than that.
    ArrayInputStream rawInput = null;
    try {
        StreamLogScan scanLog;
        if (prepareStartAt == null) {
            // don't know where to start, scan from end of log
            scanLog = (StreamLogScan) logFactory.openBackwardsScan(prepareStopAt);
        } else {
            if (prepareStartAt.lessThan(prepareStopAt)) {
                // nothing to prepare!
                return;
            }
            scanLog = (StreamLogScan) logFactory.openBackwardsScan(((LogCounter) prepareStartAt).getValueAsLong(), prepareStopAt);
        }
        if (SanityManager.DEBUG)
            SanityManager.ASSERT(scanLog != null, "cannot open log for prepare");
        rawInput = new ArrayInputStream(new byte[4096]);
        LogRecord record;
        while ((record = scanLog.getNextRecord(rawInput, prepareId, 0)) != null) {
            if (SanityManager.DEBUG) {
                SanityManager.ASSERT(record.getTransactionId().equals(prepareId), "getNextRecord return unqualified log rec for prepare");
            }
            logrecordseen++;
            if (record.isCLR()) {
                clrskipped++;
                // the loggable is still in the input stream, get rid of it
                record.skipLoggable();
                // read the prepareInstant
                long prepareInstant = rawInput.readLong();
                if (SanityManager.DEBUG) {
                    if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
                        SanityManager.DEBUG(LogToFile.DBG_FLAG, "Skipping over CLRs, reset scan to " + LogCounter.toDebugString(prepareInstant));
                    }
                }
                scanLog.resetPosition(new LogCounter(prepareInstant));
                continue;
            }
            if (record.requiresPrepareLocks()) {
                lop = record.getRePreparable();
            } else {
                continue;
            }
            if (lop != null) {
                // Reget locks based on log record.  reclaim all locks with
                // a serializable locking policy, since we are only
                // reclaiming write locks, isolation level does not matter
                // much.
                lop.reclaimPrepareLocks(t, t.newLockingPolicy(LockingPolicy.MODE_RECORD, TransactionController.ISOLATION_REPEATABLE_READ, true));
                if (SanityManager.DEBUG) {
                    if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
                        SanityManager.DEBUG(LogToFile.DBG_FLAG, "Reprepare log record at instant " + scanLog.getInstant() + " : " + lop);
                    }
                }
            }
        }
    } catch (ClassNotFoundException cnfe) {
        throw logFactory.markCorrupt(StandardException.newException(SQLState.LOG_CORRUPTED, cnfe));
    } catch (IOException ioe) {
        throw logFactory.markCorrupt(StandardException.newException(SQLState.LOG_READ_LOG_FOR_UNDO, ioe));
    } catch (StandardException se) {
        throw logFactory.markCorrupt(StandardException.newException(SQLState.LOG_UNDO_FAILED, se, prepareId, lop, (Object) null));
    } finally {
        if (rawInput != null) {
            try {
                rawInput.close();
            } catch (IOException ioe) {
                throw logFactory.markCorrupt(StandardException.newException(SQLState.LOG_READ_LOG_FOR_UNDO, ioe, prepareId));
            }
        }
    }
    if (SanityManager.DEBUG) {
        if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
            SanityManager.DEBUG(LogToFile.DBG_FLAG, "Finish prepare" + ", clr skipped = " + clrskipped + ", record seen = " + logrecordseen + "\n");
        }
    }
    if (SanityManager.DEBUG) {
        if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
            SanityManager.DEBUG(LogToFile.DBG_FLAG, "----------------------------------------------------\n" + "End of recovery rePrepare\n" + ", clr skipped = " + clrskipped + ", record seen = " + logrecordseen + "\n----------------------------------------------------\n");
        }
    }
}

Example 2 with StreamLogScan

use of org.apache.derby.impl.store.raw.log.StreamLogScan in project derby by apache.

the class FileLogger method redo.

/**
 *		Recovery Redo loop.
 *
 *		<P> The log stream is scanned from the beginning (or
 *		from the undo low water mark of a checkpoint) forward until the end.
 *		The purpose of the redo pass is to repeat history, i.e, to repeat
 *		exactly the same set of changes the rawStore went thru right before it
 *		stopped.   With each log record that is encountered in the redo pass:
 *		<OL>
 *		<LI>if it isFirst(), then the transaction factory is called upon to
 *		    create a new transaction object.
 *		<LI>if it needsRedo(), its doMe() is called (if it is a compensation
 *		    operation, then the undoable operation needs to be created first
 *            before the doMe is called).
 *		<LI>if it isComplete(), then the transaction object is closed.
 *		</OL>
 *
 *		<P> MT - caller provides synchronization
 *
 *		@param transFactory     - the transaction factory
 *		@param redoLWM          - if checkpoint seen, starting from this point
 *                                  on, apply redo if necessary
 *
 *		@return the log instant of the next log record (or the instant just
 *		after the last log record).  This is used to determine where the log
 *		truly ends
 *
 *		@exception StandardException Standard Derby error policy
 *		@exception IOException error reading log file
 *		@exception ClassNotFoundException log file corrupted
 *
 *		@see LogToFile#recover
 */
protected long redo(RawTransaction recoveryTransaction, TransactionFactory transFactory, StreamLogScan redoScan, long redoLWM, long ttabInstant) throws IOException, StandardException, ClassNotFoundException {
    // begin debug info
    if (SanityManager.DEBUG) {
        if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
            SanityManager.DEBUG(LogToFile.DBG_FLAG, "In recovery redo, redoLWM = " + redoLWM);
        }
    }
    int scanCount = 0;
    int redoCount = 0;
    int prepareCount = 0;
    int clrCount = 0;
    int btranCount = 0;
    int etranCount = 0;
    // end debug info
    TransactionId tranId = null;
    // the current log instant
    long instant = LogCounter.INVALID_LOG_INSTANT;
    // ////////////////////////////////////////////////////////////////////
    // During redo time, the byte array in the logOutputBuffer is not used.
    // Use it to read the log record - if it is not big enough, scan
    // will resize it.  We could create a brand new log input stream that
    // has nothing to do with logIn or logOutputBuffer but that seem like
    // a waste of memory.
    // ////////////////////////////////////////////////////////////////////
    logIn.setData(logOutputBuffer.getByteArray());
    // use this scan to reconstitute operation to be undone
    // when we see a CLR in the redo scan
    StreamLogScan undoScan = null;
    Loggable op = null;
    // we need to determine the log's true end
    long logEnd = 0;
    try {
        // scan the log forward in redo pass and go to the end
        LogRecord record;
        while ((record = redoScan.getNextRecord(logIn, null, 0)) != null) {
            scanCount++;
            long undoInstant = 0;
            // last known good instant
            instant = redoScan.getInstant();
            // last known good log end
            logEnd = redoScan.getLogRecordEnd();
            // NOTE NOTE
            if (SanityManager.DEBUG) {
                if (SanityManager.DEBUG_ON(LogToFile.DUMP_LOG_ONLY) || SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
                    if (SanityManager.DEBUG_ON(LogToFile.DUMP_LOG_ONLY))
                        SanityManager.DEBUG_SET(LogToFile.DBG_FLAG);
                    op = record.getLoggable();
                    tranId = record.getTransactionId();
                    if (record.isCLR()) {
                        // !!!!!!! this moves the file pointer
                        undoInstant = logIn.readLong();
                        SanityManager.DEBUG(LogToFile.DBG_FLAG, "scanned " + tranId + " : " + op + " instant = " + LogCounter.toDebugString(instant) + " undoInstant : " + LogCounter.toDebugString(undoInstant));
                    } else {
                        SanityManager.DEBUG(LogToFile.DBG_FLAG, "scanned " + tranId + " : " + op + " instant = " + LogCounter.toDebugString(instant) + " logEnd = " + LogCounter.toDebugString(logEnd) + " logIn at " + logIn.getPosition() + " available " + logIn.available());
                    }
                    // we only want to dump the log, don't touch it
                    if (SanityManager.DEBUG_ON(LogToFile.DUMP_LOG_ONLY))
                        continue;
                }
            }
            // already been flushed by checkpoint
            if (redoLWM != LogCounter.INVALID_LOG_INSTANT && instant < redoLWM) {
                if (!(record.isFirst() || record.isComplete() || record.isPrepare())) {
                    continue;
                }
            }
            // get the transaction
            tranId = record.getTransactionId();
            // otherwise, make it known to the transaction factory
            if (!transFactory.findTransaction(tranId, recoveryTransaction)) {
                if (redoLWM != LogCounter.INVALID_LOG_INSTANT && instant < redoLWM && (record.isPrepare() || record.isComplete())) {
                    // What is happening here is that a transaction that
                    // started before the undoLWM has commited by the time
                    // the checkpoint undoLWM was taken.  Hence, we only
                    // see the tail end of its log record and its endXact
                    // record.
                    // 
                    // NOTE:
                    // Since we didn't see its beginXact, we cannot do the
                    // endXact's doMe either.  Also if the endXact, is
                    // actually just a prepare, we don't need to do
                    // anything as the transaction will commit or abort
                    // prior to point we are recovering to.
                    // If it is deemed necessary to do the endXact's doMe,
                    // then we should start the transaction right here.
                    // For now, just completely ignore this transaction
                    // 
                    etranCount++;
                    continue;
                }
                if ((ttabInstant == LogCounter.INVALID_LOG_INSTANT) && !record.isFirst()) {
                    throw StandardException.newException(SQLState.LOG_UNEXPECTED_RECOVERY_PROBLEM, MessageService.getTextMessage(MessageId.LOG_RECORD_NOT_FIRST, tranId));
                }
                if (SanityManager.DEBUG) {
                    // instant, error.
                    if (ttabInstant != LogCounter.INVALID_LOG_INSTANT) {
                        if (instant > ttabInstant && !record.isFirst()) {
                            SanityManager.THROWASSERT("log record is Not first but transaction " + "is not in transaction table (2) : " + tranId);
                        }
                    // If we dump the transaction table and the table
                    // does not have the transaction, and we see this
                    // beginXact before the ttab instant, we could have
                    // igored it because we "know" that we should see
                    // the endXact before the ttab instant also.
                    // Leave it in just in case.
                    }
                }
                btranCount++;
                // the long transaction ID is embedded in the beginXact log
                // record.  The short ID is stored in the log record.
                recoveryTransaction.setTransactionId(record.getLoggable(), tranId);
            } else {
                if ((ttabInstant == LogCounter.INVALID_LOG_INSTANT) && record.isFirst()) {
                    throw StandardException.newException(SQLState.LOG_UNEXPECTED_RECOVERY_PROBLEM, MessageService.getTextMessage(MessageId.LOG_RECORD_FIRST, tranId));
                }
                if (SanityManager.DEBUG) {
                    if (ttabInstant != LogCounter.INVALID_LOG_INSTANT && instant > ttabInstant && record.isFirst()) {
                        SanityManager.THROWASSERT("log record is first but transaction is " + "already in transaction table (3): " + tranId);
                    }
                    if (record.isPrepare())
                        prepareCount++;
                }
                // 
                if (record.isFirst()) {
                    btranCount++;
                    continue;
                }
            }
            op = record.getLoggable();
            if (SanityManager.DEBUG) {
                if (!record.isCLR()) {
                    if (logIn.available() < 4) {
                        SanityManager.THROWASSERT("not enough bytes read in : " + logIn.available() + " for " + op + " instant " + LogCounter.toDebugString(instant));
                    }
                }
            }
            if (SanityManager.DEBUG) {
                SanityManager.ASSERT(!recoveryTransaction.handlesPostTerminationWork(), "recovery transaction handles post termination work");
            }
            if (op.needsRedo(recoveryTransaction)) {
                redoCount++;
                if (record.isCLR()) {
                    clrCount++;
                    if (SanityManager.DEBUG)
                        SanityManager.ASSERT(op instanceof Compensation);
                    // this value may be set by sanity xxxx
                    if (undoInstant == 0)
                        undoInstant = logIn.readLong();
                    if (undoScan == null) {
                        undoScan = (StreamLogScan) logFactory.openForwardsScan(undoInstant, (LogInstant) null);
                    } else {
                        undoScan.resetPosition(new LogCounter(undoInstant));
                    }
                    // undoScan now positioned at the beginning of the log
                    // record was rolled back by this CLR.
                    // The scan is a forward one so getNextRecord will get
                    // the log record that needs to be rolled back.
                    // reuse the buffer in logIn and logIn since CLR
                    // has no optional data and has no use for them anymore
                    logIn.clearLimit();
                    LogRecord undoRecord = undoScan.getNextRecord(logIn, null, 0);
                    Undoable undoOp = undoRecord.getUndoable();
                    if (SanityManager.DEBUG) {
                        SanityManager.DEBUG(LogToFile.DBG_FLAG, "Redoing CLR: undoInstant = " + LogCounter.toDebugString(undoInstant) + " clrinstant = " + LogCounter.toDebugString(instant));
                        SanityManager.ASSERT(undoRecord.getTransactionId().equals(tranId));
                        SanityManager.ASSERT(undoOp != null);
                    }
                    ((Compensation) op).setUndoOp(undoOp);
                }
                if (SanityManager.DEBUG) {
                    if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
                        SanityManager.DEBUG(LogToFile.DBG_FLAG, "redoing " + op + " instant = " + LogCounter.toDebugString(instant));
                    }
                }
                int dataLength = logIn.readInt();
                logIn.setLimit(dataLength);
                // even though the log has already been written, we need to
                // tie the page to the log stream so that if redo failed
                // for some reasons, the log factory's corruption will stop
                // the corrupt page from flushing to disk.
                op.doMe(recoveryTransaction, new LogCounter(instant), logIn);
                op.releaseResource(recoveryTransaction);
                op = null;
            }
            // has written any transaction, so in this case, it is a noop.
            if (record.isComplete()) {
                etranCount++;
                if (SanityManager.DEBUG)
                    SanityManager.ASSERT(!recoveryTransaction.handlesPostTerminationWork(), "recovery xact handles post termination work");
                recoveryTransaction.commit();
            }
        }
        // while redoScan.getNextRecord() != null
        // If the scan ended in an empty file, update logEnd to reflect that
        // in order to avoid to continue logging to an older file
        long end = redoScan.getLogRecordEnd();
        if (end != LogCounter.INVALID_LOG_INSTANT && (LogCounter.getLogFileNumber(logEnd) < LogCounter.getLogFileNumber(end))) {
            logEnd = end;
        }
    } catch (StandardException se) {
        throw StandardException.newException(SQLState.LOG_REDO_FAILED, se, op);
    } finally {
        // close all the io streams
        redoScan.close();
        redoScan = null;
        if (undoScan != null) {
            undoScan.close();
            undoScan = null;
        }
        if (op != null)
            op.releaseResource(recoveryTransaction);
    }
    if (SanityManager.DEBUG) {
        if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
            SanityManager.DEBUG(LogToFile.DBG_FLAG, "----------------------------------------------------\n" + "End of recovery redo\n" + "Scanned = " + scanCount + " log records" + ", redid = " + redoCount + " ( clr = " + clrCount + " )" + " begintran = " + btranCount + " endtran = " + etranCount + " preparetran = " + prepareCount + "\n log ends at " + LogCounter.toDebugString(logEnd) + "\n----------------------------------------------------\n");
        }
    }
    if (SanityManager.DEBUG) {
        // make sure logEnd and instant is consistent
        if (instant != LogCounter.INVALID_LOG_INSTANT) {
            SanityManager.ASSERT(LogCounter.getLogFileNumber(instant) < LogCounter.getLogFileNumber(logEnd) || (LogCounter.getLogFileNumber(instant) == LogCounter.getLogFileNumber(logEnd) && LogCounter.getLogFilePosition(instant) <= LogCounter.getLogFilePosition(logEnd)));
        } else {
            SanityManager.ASSERT(logEnd == LogCounter.INVALID_LOG_INSTANT);
        }
    }
    // logEnd is the last good log record position in the log
    return logEnd;
}

Example 3 with StreamLogScan

use of org.apache.derby.impl.store.raw.log.StreamLogScan in project derby by apache.

the class FileLogger method undo.

/**
 *		Undo a part of or the entire transaction.  Begin rolling back the log
 *		record at undoStartAt and stopping at (inclusive) the log record at
 *		undoStopAt.
 *
 *		<P>MT - Not needed. A transaction must be single threaded thru undo,
 *        each RawTransaction has its own logger, therefore no need to
 *        synchronize.  The RawTransaction must handle synchronizing with
 *        multiple threads during rollback.
 *
 *		@param t 			the transaction that needs to be rolled back
 *		@param undoId 		the transaction ID
 *		@param undoStopAt	the last log record that should be rolled back
 *		@param undoStartAt	the first log record that should be rolled back
 *
 *		@exception StandardException	Standard Derby error policy
 *
 *		@see Logger#undo
 */
public void undo(RawTransaction t, TransactionId undoId, LogInstant undoStopAt, LogInstant undoStartAt) throws StandardException {
    if (SanityManager.DEBUG) {
        if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
            if (undoStartAt != null) {
                SanityManager.DEBUG(LogToFile.DBG_FLAG, "\nUndo transaction: " + undoId.toString() + "start at " + undoStartAt.toString() + " stop at " + undoStopAt.toString());
            } else {
                SanityManager.DEBUG(LogToFile.DBG_FLAG, "\nUndo transaction: " + undoId.toString() + "start at end of log stop at " + undoStopAt.toString());
            }
        }
    }
    // statistics
    int clrgenerated = 0;
    int clrskipped = 0;
    int logrecordseen = 0;
    StreamLogScan scanLog;
    Compensation compensation = null;
    Undoable lop = null;
    // stream to read the log record - initial size 4096, scanLog needs
    // to resize if the log record is larget than that.
    ArrayInputStream rawInput = null;
    try {
        if (undoStartAt == null) {
            // don't know where to start, rollback from end of log
            scanLog = (StreamLogScan) logFactory.openBackwardsScan(undoStopAt);
        } else {
            if (undoStartAt.lessThan(undoStopAt)) {
                // nothing to undo!
                return;
            }
            long undoStartInstant = ((LogCounter) undoStartAt).getValueAsLong();
            scanLog = (StreamLogScan) logFactory.openBackwardsScan(undoStartInstant, undoStopAt);
        }
        if (SanityManager.DEBUG)
            SanityManager.ASSERT(scanLog != null, "cannot open log for undo");
        rawInput = new ArrayInputStream(new byte[4096]);
        LogRecord record;
        while ((record = scanLog.getNextRecord(rawInput, undoId, 0)) != null) {
            if (SanityManager.DEBUG) {
                SanityManager.ASSERT(record.getTransactionId().equals(undoId), "getNextRecord return unqualified log record for undo");
            }
            logrecordseen++;
            if (record.isCLR()) {
                clrskipped++;
                // the loggable is still in the input stream, get rid of it
                record.skipLoggable();
                // read the undoInstant
                long undoInstant = rawInput.readLong();
                if (SanityManager.DEBUG) {
                    if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
                        SanityManager.DEBUG(LogToFile.DBG_FLAG, "Skipping over CLRs, reset scan to " + LogCounter.toDebugString(undoInstant));
                    }
                }
                scanLog.resetPosition(new LogCounter(undoInstant));
                continue;
            }
            lop = record.getUndoable();
            if (lop != null) {
                int optionalDataLength = rawInput.readInt();
                int savePosition = rawInput.getPosition();
                rawInput.setLimit(optionalDataLength);
                compensation = lop.generateUndo(t, rawInput);
                if (SanityManager.DEBUG) {
                    if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
                        SanityManager.DEBUG(LogToFile.DBG_FLAG, "Rollback log record at instant " + LogCounter.toDebugString(scanLog.getInstant()) + " : " + lop);
                    }
                }
                clrgenerated++;
                if (compensation != null) {
                    // generateUndo may have read stuff off the
                    // stream, reset it for the undo operation.
                    rawInput.setLimit(savePosition, optionalDataLength);
                    // log the compensation op that rolls back the
                    // operation at this instant
                    t.logAndUndo(compensation, new LogCounter(scanLog.getInstant()), rawInput);
                    compensation.releaseResource(t);
                    compensation = null;
                }
            // if compensation is null, log operation is redo only
            }
        // if this is not an undoable operation, continue with next log
        // record
        }
    } catch (ClassNotFoundException cnfe) {
        throw logFactory.markCorrupt(StandardException.newException(SQLState.LOG_CORRUPTED, cnfe));
    } catch (IOException ioe) {
        throw logFactory.markCorrupt(StandardException.newException(SQLState.LOG_READ_LOG_FOR_UNDO, ioe));
    } catch (StandardException se) {
        throw logFactory.markCorrupt(StandardException.newException(SQLState.LOG_UNDO_FAILED, se, undoId, lop, compensation));
    } finally {
        if (compensation != null) {
            // errored out
            compensation.releaseResource(t);
        }
        if (rawInput != null) {
            try {
                rawInput.close();
            } catch (IOException ioe) {
                throw logFactory.markCorrupt(StandardException.newException(SQLState.LOG_READ_LOG_FOR_UNDO, ioe, undoId));
            }
        }
    }
    if (SanityManager.DEBUG) {
        if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
            SanityManager.DEBUG(LogToFile.DBG_FLAG, "Finish undo" + ", clr generated = " + clrgenerated + ", clr skipped = " + clrskipped + ", record seen = " + logrecordseen + "\n");
        }
    }
}