[SERVER-24109] getMore with awaitData does not awaitData on first empty batch Created: 09/May/16  Updated: 11/Jul/19  Resolved: 13/Jun/16

Status: Closed
Project: Core Server
Component/s: Querying
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Judah Schvimer Assignee: Max Hirschhorn
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Steps To Reproduce:

var rs = ReplSetTest({nodes: 1});
rs.startSet();
rs.initiate();
var db = rs.nodes[0].getDB("local");
 
var findCmdRes = db.runCommand({
	find: "oplog.rs",
	tailable: true,
	awaitData: true,
	maxTimeMS: 60000
});
print("Time after find: " + (new Date()).toString());
printjson(findCmdRes);
 
var getMoreRes = db.runCommand({getMore: findCmdRes.cursor.id, collection: "oplog.rs", maxTimeMS: 5000});
print("Time after first getMore: " + (new Date()).toString());
printjson(getMoreRes);
 
getMoreRes = db.runCommand({getMore: findCmdRes.cursor.id, collection: "oplog.rs", maxTimeMS: 5000});
print("Time after second getMore: " + (new Date()).toString());
printjson(getMoreRes);
 
getMoreRes = db.runCommand({getMore: findCmdRes.cursor.id, collection: "oplog.rs", maxTimeMS: 5000});
print("Time after third getMore: " + (new Date()).toString());
printjson(getMoreRes);

Output

Time after find: Fri Jun 10 2016 13:23:23 GMT-0400 (EDT)
{
    "waitedMS" : NumberLong(0),
    "cursor" : {
        "firstBatch" : [
            {
                "ts" : Timestamp(1465579402, 1),
                "h" : NumberLong("9006574743864708869"),
                "v" : 2,
                "op" : "n",
                "ns" : "",
                "o" : {
                    "msg" : "initiating set"
                }
            },
            {
                "ts" : Timestamp(1465579403, 1),
                "t" : NumberLong(1),
                "h" : NumberLong("3841223321967630675"),
                "v" : 2,
                "op" : "n",
                "ns" : "",
                "o" : {
                    "msg" : "new primary"
                }
            }
        ],
        "id" : NumberLong("28093652894"),
        "ns" : "local.oplog.rs"
    },
    "ok" : 1
}
Time after first getMore: Fri Jun 10 2016 13:23:23 GMT-0400 (EDT)
{
    "cursor" : {
        "nextBatch" : [ ],
        "id" : NumberLong("28093652894"),
        "ns" : "local.oplog.rs"
    },
    "ok" : 1
}
Time after second getMore: Fri Jun 10 2016 13:23:28 GMT-0400 (EDT)
{
    "cursor" : {
        "nextBatch" : [ ],
        "id" : NumberLong("28093652894"),
        "ns" : "local.oplog.rs"
    },
    "ok" : 1
}
Time after third getMore: Fri Jun 10 2016 13:23:33 GMT-0400 (EDT)
{
    "cursor" : {
        "nextBatch" : [ ],
        "id" : NumberLong("28093652894"),
        "ns" : "local.oplog.rs"
    },
    "ok" : 1
}

Sprint: Query 16 (06/24/16)
Participants:
Case:

 Description   

a getMore with awaitData=true is supposed to block until maxTimeMS runs out when there is no data for it to return. On the first getMore in a series of empty getMores, the getMore will return immediately with no new data. Subsequent getMores will wait maxTimeMS before returning as they are supposed to.



 Comments   
Comment by Eric Milkie [ 13/Jun/16 ]

Thanks for the diagnosis! It's clear now this is working as designed.

Comment by Max Hirschhorn [ 12/Jun/16 ]

The CappedInsertNotifier for the oplog is getting signaled when the durable optime advances, which causes the getMore request to stop awaiting new data and to try and generate a batch. The resulting batch is empty and is returned prior to the maxTimeMS expiry when no data has actually been inserted since the getMore request.

More specifically, the WTJournalFlusher thread periodically calls WiredTigerSessionCache::waitUntilDurable(), which eventually updates the last committed optime and thus signals any readers on the oplog, even though no new data has actually been inserted into the oplog since the getMore request was issued.

Adding db.adminCommand({ fsync: 1 }) or db.fake.insert({}, { writeConcern: { j: true }}) after initiating the replica set and prior to creating the awaitData cursor on the oplog makes it so that the durable optime is current when issuing the getMore request. milkie is there anything that actually needs to be done here?

Comment by Eric Milkie [ 03/Jun/16 ]

Nope, he really means the first getMore command. Try the repro steps yourself and see.

Comment by Ian Whalen (Inactive) [ 03/Jun/16 ]

judah.schvimer are you talking about the initial find? it is the case that the initial find will not block because the awaitData implementation is done exclusively inside getMore. is this just some behavior you've observed or is it causing a problem?

Generated at Thu Feb 08 04:05:24 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.