[SERVER-20895] Strange behavior with wired tiger oplog and duplicate ts values Created: 13/Oct/15  Updated: 06/Dec/22  Resolved: 04/Jan/20

Status: Closed
Project: Core Server
Component/s: Replication, Storage
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Minor - P4
Reporter: Scott Hernandez (Inactive) Assignee: Backlog - Replication Team
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File oplog_insert_duplicate_ts.js    
Assigned Teams:
Replication
Operating System: ALL
Participants:

 Description   

It seems like inserts are fine with duplicate ts values but mask older documents, or replace them.

test:PRIMARY> db.getSiblingDB("local").oplog.rs.insert({ts: new Timestamp(1444669076,3), op:"n", h: NumberLong("12312")})
WriteResult({ "nInserted" : 1 })
test:PRIMARY> db.getSiblingDB("local").oplog.rs.insert({ts: new Timestamp(1444669076,3), op:"n", h: NumberLong("12312")})
WriteResult({ "nInserted" : 1 })
test:PRIMARY> db.getSiblingDB("local").oplog.rs.insert({ts: new Timestamp(1444669076,3), op:"n", h: NumberLong("12312")})
WriteResult({ "nInserted" : 1 })
test:PRIMARY> db.getSiblingDB("local").oplog.rs.find()
{ "_id" : ObjectId("561d0d5e30adac216043a161"), "ts" : Timestamp(1444669076, 3), "op" : "n", "h" : NumberLong(12312) }
{ "ts" : Timestamp(1444669605, 1), "t" : NumberLong(0), "h" : NumberLong("-6898850243195961135"), "v" : 2, "op" : "n", "ns" : "", "o" : { "msg" : "initiating set" } }
{ "ts" : Timestamp(1444669606, 1), "t" : NumberLong(1), "h" : NumberLong("-1589401225501337977"), "v" : 2, "op" : "n", "ns" : "", "o" : { "msg" : "new primary" } }
{ "ts" : Timestamp(1444669631, 1), "t" : NumberLong(1), "h" : NumberLong("1621003532950817417"), "v" : 2, "op" : "n", "ns" : "", "o" : { "foo" : 1 } }
{ "ts" : Timestamp(1444744494, 1), "t" : NumberLong(2), "h" : NumberLong("-7504719105121076257"), "v" : 2, "op" : "n", "ns" : "", "o" : { "msg" : "new primary" } }
test:PRIMARY> db.getSiblingDB("local").oplog.rs.insert({ts: new Timestamp(1444669076,3), op:"n", h: NumberLong("12312")})
WriteResult({ "nInserted" : 1 })
test:PRIMARY> db.getSiblingDB("local").oplog.rs.find()
{ "_id" : ObjectId("561d0d6930adac216043a162"), "ts" : Timestamp(1444669076, 3), "op" : "n", "h" : NumberLong(12312) }
{ "ts" : Timestamp(1444669605, 1), "t" : NumberLong(0), "h" : NumberLong("-6898850243195961135"), "v" : 2, "op" : "n", "ns" : "", "o" : { "msg" : "initiating set" } }
{ "ts" : Timestamp(1444669606, 1), "t" : NumberLong(1), "h" : NumberLong("-1589401225501337977"), "v" : 2, "op" : "n", "ns" : "", "o" : { "msg" : "new primary" } }
{ "ts" : Timestamp(1444669631, 1), "t" : NumberLong(1), "h" : NumberLong("1621003532950817417"), "v" : 2, "op" : "n", "ns" : "", "o" : { "foo" : 1 } }
{ "ts" : Timestamp(1444744494, 1), "t" : NumberLong(2), "h" : NumberLong("-7504719105121076257"), "v" : 2, "op" : "n", "ns" : "", "o" : { "msg" : "new primary" } }
test:PRIMARY> db.getSiblingDB("local").oplog.rs.count()
8
test:PRIMARY> db.getSiblingDB("local").oplog.rs.stats().count
8
test:PRIMARY> db.getSiblingDB("local").oplog.rs.insert({ts: new Timestamp(1444669076,3), op:"n", h: NumberLong("12312")})
WriteResult({ "nInserted" : 1 })
test:PRIMARY> db.getSiblingDB("local").oplog.rs.stats().count
9
test:PRIMARY> db.getSiblingDB("local").oplog.rs.count()
9

The mmapv1 storage engine does not show this behavior:

> db.getSiblingDB("local").oplog.rs.find()
{ "ts" : Timestamp(1444744966, 1), "t" : NumberLong(0), "h" : NumberLong("373345472902605703"), "v" : 2, "op" : "n", "ns" : "", "o" : { "msg" : "initiating set" } }
{ "ts" : Timestamp(1444744967, 1), "t" : NumberLong(1), "h" : NumberLong("5520691837775396305"), "v" : 2, "op" : "n", "ns" : "", "o" : { "msg" : "new primary" } }
test:PRIMARY> db.getSiblingDB("local").oplog.rs.insert({ts: new Timestamp(1444669076,3), op:"n", h: NumberLong("12312")})
WriteResult({ "nInserted" : 1 })
test:PRIMARY> db.getSiblingDB("local").oplog.rs.find()
{ "ts" : Timestamp(1444744966, 1), "t" : NumberLong(0), "h" : NumberLong("373345472902605703"), "v" : 2, "op" : "n", "ns" : "", "o" : { "msg" : "initiating set" } }
{ "ts" : Timestamp(1444744967, 1), "t" : NumberLong(1), "h" : NumberLong("5520691837775396305"), "v" : 2, "op" : "n", "ns" : "", "o" : { "msg" : "new primary" } }
{ "_id" : ObjectId("561d0f0e30adac216043a164"), "ts" : Timestamp(1444669076, 3), "op" : "n", "h" : NumberLong(12312) }
test:PRIMARY> db.getSiblingDB("local").oplog.rs.insert({ts: new Timestamp(1444669076,3), op:"n", h: NumberLong("12312")})
WriteResult({ "nInserted" : 1 })
test:PRIMARY> db.getSiblingDB("local").oplog.rs.insert({ts: new Timestamp(1444669076,3), op:"n", h: NumberLong("12312")})
WriteResult({ "nInserted" : 1 })
test:PRIMARY> db.getSiblingDB("local").oplog.rs.find()
{ "ts" : Timestamp(1444744966, 1), "t" : NumberLong(0), "h" : NumberLong("373345472902605703"), "v" : 2, "op" : "n", "ns" : "", "o" : { "msg" : "initiating set" } }
{ "ts" : Timestamp(1444744967, 1), "t" : NumberLong(1), "h" : NumberLong("5520691837775396305"), "v" : 2, "op" : "n", "ns" : "", "o" : { "msg" : "new primary" } }
{ "_id" : ObjectId("561d0f0e30adac216043a164"), "ts" : Timestamp(1444669076, 3), "op" : "n", "h" : NumberLong(12312) }
{ "_id" : ObjectId("561d0f1330adac216043a165"), "ts" : Timestamp(1444669076, 3), "op" : "n", "h" : NumberLong(12312) }
{ "_id" : ObjectId("561d0f1430adac216043a166"), "ts" : Timestamp(1444669076, 3), "op" : "n", "h" : NumberLong(12312) }



 Comments   
Comment by Judah Schvimer [ 04/Jan/20 ]

This is still the behavior. This is how WT works and I don't know of more preferable behavior that would work with WT's oplog structure. In the absence of a better behavior with a concrete usecase, closing as "Works As Designed".

Generated at Thu Feb 08 03:55:37 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.