In-memory storage engine: delay in acknowledgement from primary when data has successfully replicated

Kim_Hakseon · August 2, 2021, 10:01am

I executed a command in the Replica Set deployment.
And I have confirmed that the order has been completed in other securities. However, at the primary, the message “ok” and the prompt seemed to be still waiting. Or a very long time later, a normal message was printed.

This is the Log Message of the time, can I know what this means?
And can you also tell me why this phenomenon happened?

2021-08-02T16:45:17.868+0700 I COMMAND [conn49] command config.$cmd command: update { update: “system.sessions”, ordered: false, allowImplicitCollectionCreation: false, writeConcern: { w: “majority”, wtimeout: 15000 }, $db: “config” } numYields:0 reslen:494 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } }, Mutex: { acquireCount: { r: 2 } } } flowControl:{ acquireCount: 1, timeAcquiringMicros: 2 } storage:{} protocol:op_msg 15027ms

Manu · August 3, 2021, 2:00pm

@Kim_Hakseon
what is the timelag between Primary and Secondaries ?
When you said: “However, at the primary, the message “ok””, Do you mean that the command completed from application standpoint ?

Kim_Hakseon · August 5, 2021, 12:59am

Hi, @Manu
I’ve recreated the situation.
If you look at the picture, I created a user in Primary. And the message of completion ({“ok”:1}) has not come out.
However, the user was able to log in from Secondarys.

I was asking a question about this.

Kim_Hakseon · August 5, 2021, 1:05am

ps. The log for [conn49] was not released this time, and the user creation of Primary was not completed until about 10 minutes later.

chris · August 5, 2021, 2:18pm

This could be an important question to answer. And could be related to your topology/deployment.

Other information to look at:

The output of db.printSecondaryReplicationInfo()
What is your topology for this replicaSet ?
What write concern are you using ?

Stennie_X · August 6, 2021, 12:56am

Hi @Kim_Hakseon,

In addition to the information that @chris asked about, rs.conf() output and the specific version of MongoDB server would be helpful context.

The initial log snippet you provided has a w:majority write concern, so one possibility is that the delay you are seeing is related to acknowledgement from a majority of data-bearing voting members rather than replication.

10 minutes sounds like a suspiciously round number – perhaps a timeout or delay. More information on your server version & replica set configuration is needed, but by chance do you have a voting delayed secondary or a secondary with significantly different network or disk latency?

Regards,
Stennie

Kim_Hakseon · August 6, 2021, 5:32am

The output of `db.printSecondaryReplicationInfo()

source: #71:27001
        syncedTo: Fri Aug 06 2021 14:24:59 GMT+0900 (KST)
        -10 secs (0 hrs) behind the primary
source: #71:27002
        syncedTo: Fri Aug 06 2021 14:24:49 GMT+0900 (KST)
        0 secs (0 hrs) behind the primary

I don’t know what mean topology. so I show you some informations

MongoDB 4.2.15 enterprise edition


# mongod.conf

storage:
#  engine: wiredTiger
  dbPath: "/home/hskim/data"
#  journal:
#    enabled: true
  engine: inMemory
  inMemory:
    engineConfig:
      inMemorySizeGB: 2

systemLog:
  destination: file
  path: "/home/hskim/log/mongo.log"
  logAppend: true
  logRotate: reopen

net:
#  bindIp: 0.0.0.0
  bindIp: 127.0.0.1,#.71
  port: 27000
  maxIncomingConnections: 65535

.#setParameter:
.#  flowControlTargetLagSeconds: 10

processManagement:
  fork: true
  pidFilePath: "/home/hskim/mongod.pid"

security:
  authorization: enabled
  keyFile: /home/hskim/mongod.key

replication:
  replSetName: rs0
.#  enableMajorityReadConcern: true
.#  oplogSizeMB: 2048

>rs.status()
>{
        "set" : "rs0",
        "date" : ISODate("2021-08-06T05:27:11.165Z"),
        "myState" : 2,
        "term" : NumberLong(1),
        "syncingTo" : "#71:27000",
        "syncSourceHost" : "#71:27000",
        "syncSourceId" : 0,
        "heartbeatIntervalMillis" : NumberLong(2000),
        "majorityVoteCount" : 2,
        "writeMajorityCount" : 2,
        "optimes" : {
                "lastCommittedOpTime" : {
                        "ts" : Timestamp(0, 0),
                        "t" : NumberLong(-1)
                },
                "lastCommittedWallTime" : ISODate("1970-01-01T00:00:00Z"),
                "appliedOpTime" : {
                        "ts" : Timestamp(1628227629, 1),
                        "t" : NumberLong(1)
                },
                "durableOpTime" : {
                        "ts" : Timestamp(0, 0),
                        "t" : NumberLong(-1)
                },
                "lastAppliedWallTime" : ISODate("2021-08-06T05:27:09.277Z"),
                "lastDurableWallTime" : ISODate("1970-01-01T00:00:00Z")
        },
        "lastStableRecoveryTimestamp" : Timestamp(0, 0),
        "electionParticipantMetrics" : {
                "votedForCandidate" : true,
                "electionTerm" : NumberLong(1),
                "lastVoteDate" : ISODate("2021-08-06T05:21:29.240Z"),
                "electionCandidateMemberId" : 0,
                "voteReason" : "",
                "lastAppliedOpTimeAtElection" : {
                        "ts" : Timestamp(1628227278, 1),
                        "t" : NumberLong(-1)
                },
                "maxAppliedOpTimeInSet" : {
                        "ts" : Timestamp(1628227278, 1),
                        "t" : NumberLong(-1)
                },
                "priorityAtElection" : 1,
                "newTermStartDate" : ISODate("2021-08-06T05:21:29.257Z"),
                "newTermAppliedDate" : ISODate("2021-08-06T05:21:30.735Z")
        },
        "members" : [
                {
                        "_id" : 0,
                        "name" : "#71:27000",
                        "health" : 1,
                        "state" : 1,
                        "stateStr" : "PRIMARY",
                        "uptime" : 351,
                        "optime" : {
                                "ts" : Timestamp(1628227629, 1),
                                "t" : NumberLong(1)
                        },
                        "optimeDurable" : {
                                "ts" : Timestamp(1628227400, 4),
                                "t" : NumberLong(1)
                        },
                        "optimeDate" : ISODate("2021-08-06T05:27:09Z"),
                        "optimeDurableDate" : ISODate("2021-08-06T05:23:20Z"),
                        "lastHeartbeat" : ISODate("2021-08-06T05:27:10.882Z"),
                        "lastHeartbeatRecv" : ISODate("2021-08-06T05:27:09.425Z"),
                        "pingMs" : NumberLong(0),
                        "lastHeartbeatMessage" : "",
                        "syncingTo" : "",
                        "syncSourceHost" : "",
                        "syncSourceId" : -1,
                        "infoMessage" : "",
                        "electionTime" : Timestamp(1628227289, 1),
                        "electionDate" : ISODate("2021-08-06T05:21:29Z"),
                        "configVersion" : 1
                },
                {
                        "_id" : 1,
                        "name" : "#71:27001",
                        "health" : 1,
                        "state" : 2,
                        "stateStr" : "SECONDARY",
                        "uptime" : 469,
                        "optime" : {
                                "ts" : Timestamp(1628227629, 1),
                                "t" : NumberLong(1)
                        },
                        "optimeDate" : ISODate("2021-08-06T05:27:09Z"),
                        "syncingTo" : "#71:27000",
                        "syncSourceHost" : "#71:27000",
                        "syncSourceId" : 0,
                        "infoMessage" : "",
                        "configVersion" : 1,
                        "self" : true,
                        "lastHeartbeatMessage" : ""
                },
                {
                        "_id" : 2,
                        "name" : "#71:27002",
                        "health" : 1,
                        "state" : 2,
                        "stateStr" : "SECONDARY",
                        "uptime" : 351,
                        "optime" : {
                                "ts" : Timestamp(1628227629, 1),
                                "t" : NumberLong(1)
                        },
                        "optimeDurable" : {
                                "ts" : Timestamp(0, 0),
                                "t" : NumberLong(-1)
                        },
                        "optimeDate" : ISODate("2021-08-06T05:27:09Z"),
                        "optimeDurableDate" : ISODate("1970-01-01T00:00:00Z"),
                        "lastHeartbeat" : ISODate("2021-08-06T05:27:10.888Z"),
                        "lastHeartbeatRecv" : ISODate("2021-08-06T05:27:10.887Z"),
                        "pingMs" : NumberLong(0),
                        "lastHeartbeatMessage" : "",
                        "syncingTo" : "#71:27000",
                        "syncSourceHost" : "#71:27000",
                        "syncSourceId" : 0,
                        "infoMessage" : "",
                        "configVersion" : 1
                }
        ],
        "ok" : 1
}

What write concern are you using ?
A. I use default write concern

Kim_Hakseon · August 6, 2021, 5:35am

I show you rs.conf() output

>{
        "_id" : "rs0",
        "version" : 1,
        "protocolVersion" : NumberLong(1),
        "writeConcernMajorityJournalDefault" : true,
        "members" : [
                {
                        "_id" : 0,
                        "host" : "#71:27000",
                        "arbiterOnly" : false,
                        "buildIndexes" : true,
                        "hidden" : false,
                        "priority" : 1,
                        "tags" : {
                        },
                        "slaveDelay" : NumberLong(0),
                        "votes" : 1
                },
                {
                        "_id" : 1,
                        "host" : "#71:27001",
                        "arbiterOnly" : false,
                        "buildIndexes" : true,
                        "hidden" : false,
                        "priority" : 1,
                        "tags" : {
                        },
                        "slaveDelay" : NumberLong(0),
                        "votes" : 1
                },
                {
                        "_id" : 2,
                        "host" : "#71:27002",
                        "arbiterOnly" : false,
                        "buildIndexes" : true,
                        "hidden" : false,
                        "priority" : 1,
                        "tags" : {
                        },
                        "slaveDelay" : NumberLong(0),
                        "votes" : 1
                }
        ],
        "settings" : {
                "chainingAllowed" : true,
                "heartbeatIntervalMillis" : 2000,
                "heartbeatTimeoutSecs" : 10,
                "electionTimeoutMillis" : 10000,
                "catchUpTimeoutMillis" : -1,
                "catchUpTakeoverDelayMillis" : 30000,
                "getLastErrorModes" : {
                },
                "getLastErrorDefaults" : {
                        "w" : 1,
                        "wtimeout" : 0
                },
                "replicaSetId" : ObjectId("610cc6cebeeaad7fb28a6e63")
        }
}

And that I said 10 minutes is real time…

Kim_Hakseon · August 6, 2021, 5:39am

And I found that the command was successfully entered directly from the wiretiger
The problem seems to be found in the in-memory.

Stennie_X · August 6, 2021, 6:21am

Hi @Kim_Hakseon,

Thank you for the extra details! Since you have replica set members using the in-memory storage engine you also need to set writeConcernMajorityJournalDefault to false.

Doing so should resolve this issue – can you please test and confirm?

Some commands use a majority write concern by default. For example, the session update that was logged in your first post in this topic or user management commands like db.createUser() which was your test case.

The w:majority write concern on a replica set also implies writing to the journal unless writeConcernMajorityJournalDefault is set to false. Since the in-memory storage engine does not persist any data to disk, majority writes cannot be acknowledged unless you disable the on-disk journal acknowledgement.

Regards,
Stennie

Kim_Hakseon · August 6, 2021, 6:31am

Hi, @Stennie

While waiting for a response, I did test that set {w:1} and run commands.
Then, the result I expected came out.

Do I set {writeConcernMajorityJournalDefault : false} settings in the rs.initiate()?

Stennie_X · August 15, 2021, 6:36am

Hi @Kim_Hakseon,

You can set writeConcernMajorityJournalDefault and other replica set options via rs.initiate() when creating a new replica set.

For an existing replica set you can modify options via rs.reconfig().

Regards,
Stennie

BM_Sharma · August 16, 2021, 11:52am

@Kin_Hakseon

If any voting member of a replica set uses the in-memory storage engine, we must set writeConcernMajorityJournalDefault to false.
Please refer the MongoDB document related to Inmemory Storage engine.