diff options
-rw-r--r-- | src/mongo/db/storage/record_store_test_oplog.cpp | 84 | ||||
-rw-r--r-- | src/mongo/db/storage/recovery_unit.h | 4 | ||||
-rw-r--r-- | src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.h | 2 |
3 files changed, 67 insertions, 23 deletions
diff --git a/src/mongo/db/storage/record_store_test_oplog.cpp b/src/mongo/db/storage/record_store_test_oplog.cpp index e398d9d2820..368ba88278d 100644 --- a/src/mongo/db/storage/record_store_test_oplog.cpp +++ b/src/mongo/db/storage/record_store_test_oplog.cpp @@ -271,6 +271,34 @@ TEST(RecordStoreTestHarness, SeekNearOnNonOplog) { ASSERT_EQ(rec->id, RecordId(1)); } +/** + * Stringifies the current 'record', as well as any more records in the 'cursor'. Additionally adds + * the latest oplog visibitility timestamp (this is the current oplog read timestamp, but may not + * have been the timestamp used by the cursor). + */ +std::string stringifyForDebug(OperationContext* opCtx, + boost::optional<Record> record, + SeekableRecordCursor* cursor) { + str::stream output; + + auto optOplogReadTimestampInt = opCtx->recoveryUnit()->getOplogVisibilityTs(); + if (optOplogReadTimestampInt) { + output << "Latest oplog visibility timestamp: " + << Timestamp(optOplogReadTimestampInt.get()); + } + + if (record) { + output << ". Current record: " << record->id << ", " << record->data.toBson(); + while (auto nextRecord = cursor->next()) { + if (nextRecord) { + output << ". Cursor Record: " << nextRecord->id << ", " + << nextRecord->data.toBson(); + } + } + } + + return output; +} TEST(RecordStoreTestHarness, OplogOrder) { std::unique_ptr<RecordStoreHarnessHelper> harnessHelper(newRecordStoreHarnessHelper()); @@ -343,9 +371,10 @@ TEST(RecordStoreTestHarness, OplogOrder) { auto opCtx = harnessHelper->newOperationContext(client2.get()); auto cursor = rs->getCursor(opCtx.get()); auto record = cursor->seekExact(id1); - ASSERT(record); - ASSERT_EQ(id1, record->id); - ASSERT(!cursor->next()); + ASSERT(record) << stringifyForDebug(opCtx.get(), record, cursor.get()); + ASSERT_EQ(id1, record->id) << stringifyForDebug(opCtx.get(), record, cursor.get()); + auto nextRecord = cursor->next(); + ASSERT(!nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get()); } { @@ -353,9 +382,10 @@ TEST(RecordStoreTestHarness, OplogOrder) { auto opCtx = harnessHelper->newOperationContext(client2.get()); auto cursor = rs->getCursor(opCtx.get()); auto record = cursor->seekNear(id2); - ASSERT(record); - ASSERT_EQ(id1, record->id); - ASSERT(!cursor->next()); + ASSERT(record) << stringifyForDebug(opCtx.get(), record, cursor.get()); + ASSERT_EQ(id1, record->id) << stringifyForDebug(opCtx.get(), record, cursor.get()); + auto nextRecord = cursor->next(); + ASSERT(!nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get()); } { @@ -363,9 +393,10 @@ TEST(RecordStoreTestHarness, OplogOrder) { auto opCtx = harnessHelper->newOperationContext(client2.get()); auto cursor = rs->getCursor(opCtx.get()); auto record = cursor->seekNear(id3); - ASSERT(record); - ASSERT_EQ(id1, record->id); - ASSERT(!cursor->next()); + ASSERT(record) << stringifyForDebug(opCtx.get(), record, cursor.get()); + ASSERT_EQ(id1, record->id) << stringifyForDebug(opCtx.get(), record, cursor.get()); + auto nextRecord = cursor->next(); + ASSERT(!nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get()); } w1.commit(); @@ -378,10 +409,13 @@ TEST(RecordStoreTestHarness, OplogOrder) { auto opCtx = harnessHelper->newOperationContext(client2.get()); auto cursor = rs->getCursor(opCtx.get()); auto record = cursor->seekExact(id1); - ASSERT_EQ(id1, record->id); - ASSERT(cursor->next()); - ASSERT(cursor->next()); - ASSERT(!cursor->next()); + ASSERT_EQ(id1, record->id) << stringifyForDebug(opCtx.get(), record, cursor.get()); + auto nextRecord = cursor->next(); + ASSERT(nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get()); + nextRecord = cursor->next(); + ASSERT(nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get()); + nextRecord = cursor->next(); + ASSERT(!nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get()); } // Rollback the last two oplog entries, then insert entries with older optimes and ensure that @@ -430,8 +464,9 @@ TEST(RecordStoreTestHarness, OplogOrder) { auto cursor = rs->getCursor(opCtx.get()); auto record = cursor->seekExact(id1); ASSERT(record); - ASSERT_EQ(id1, record->id); - ASSERT(!cursor->next()); + ASSERT_EQ(id1, record->id) << stringifyForDebug(opCtx.get(), record, cursor.get()); + auto nextRecord = cursor->next(); + ASSERT(!nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get()); } { @@ -440,8 +475,9 @@ TEST(RecordStoreTestHarness, OplogOrder) { auto cursor = rs->getCursor(opCtx.get()); auto record = cursor->seekNear(id2); ASSERT(record); - ASSERT_EQ(id1, record->id); - ASSERT(!cursor->next()); + ASSERT_EQ(id1, record->id) << stringifyForDebug(opCtx.get(), record, cursor.get()); + auto nextRecord = cursor->next(); + ASSERT(!nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get()); } { @@ -450,8 +486,9 @@ TEST(RecordStoreTestHarness, OplogOrder) { auto cursor = rs->getCursor(opCtx.get()); auto record = cursor->seekNear(id3); ASSERT(record); - ASSERT_EQ(id1, record->id); - ASSERT(!cursor->next()); + ASSERT_EQ(id1, record->id) << stringifyForDebug(opCtx.get(), record, cursor.get()); + auto nextRecord = cursor->next(); + ASSERT(!nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get()); } w1.commit(); @@ -464,9 +501,12 @@ TEST(RecordStoreTestHarness, OplogOrder) { auto cursor = rs->getCursor(opCtx.get()); auto record = cursor->seekExact(id1); ASSERT_EQ(id1, record->id); - ASSERT(cursor->next()); - ASSERT(cursor->next()); - ASSERT(!cursor->next()); + auto nextRecord = cursor->next(); + ASSERT(nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get()); + nextRecord = cursor->next(); + ASSERT(nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get()); + nextRecord = cursor->next(); + ASSERT(!nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get()); } } } // namespace diff --git a/src/mongo/db/storage/recovery_unit.h b/src/mongo/db/storage/recovery_unit.h index e53429cb490..80156daeb72 100644 --- a/src/mongo/db/storage/recovery_unit.h +++ b/src/mongo/db/storage/recovery_unit.h @@ -484,6 +484,10 @@ public: return ReadSource::kNoTimestamp; }; + virtual boost::optional<int64_t> getOplogVisibilityTs() { + return boost::none; + } + /** * Pinning informs callers not to change the ReadSource on this RecoveryUnit. Callers are * expected to first check isReadSourcePinned before attempting to change the ReadSource. An diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.h b/src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.h index 70b13ffa3f2..2d75b4e54f1 100644 --- a/src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.h +++ b/src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.h @@ -220,7 +220,7 @@ public: */ void setTxnModified(); - boost::optional<int64_t> getOplogVisibilityTs(); + boost::optional<int64_t> getOplogVisibilityTs() override; static WiredTigerRecoveryUnit* get(OperationContext* opCtx) { return checked_cast<WiredTigerRecoveryUnit*>(opCtx->recoveryUnit()); |