[SERVER-27286] Cluster find command with batchSize of 0 delays initial cursor establishment until 'getMore' time Created: 05/Dec/16  Updated: 25/Apr/17  Resolved: 31/Mar/17

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

Type: Bug Priority: Major - P3
Reporter: Kaloian Manassiev Assignee: Esha Maharishi (Inactive)
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Duplicate
duplicates SERVER-27937 pull apart the AsyncResultsMerger log... Closed
is duplicated by SERVER-28019 shard version not ok: version epoch m... Closed
Related
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v3.4, v3.2
Steps To Reproduce:

let st = new ShardingTest({shards: 2});
let testDB = st.s.getDB("test");
testDB.adminCommand({enableSharding: testDB.getName()});
st.ensurePrimaryShard(testDB.getName(), "shard0000");
let coll = testDB.getCollection("coll");
coll.drop();
testDB.adminCommand({shardCollection: coll.getFullName(), key: {a: 1}});
coll.insert({a: 1});
 
let res = testDB.runCommand({find: "coll", filter: {a: 1}, batchSize: 0});
 
testDB.adminCommand({split: coll.getFullName(), middle: {a: 0}});
testDB.adminCommand({moveChunk: coll.getFullName(), find: {a: 1}, to: "shard0001"});
 
// throws
testDB.runCommand({getMore: res.cursor.id, collection: "coll"});

Sprint: Query 2017-01-23, Query 2017-02-13
Participants:
Case:

 Description   

The underlying cause is not yet known, but it looks like it is possible that the initial cursor establishment is not happening by the find command and instead happens at getMore time. Because of this the stale version checks and metadata refresh are not happening.

This is a snippet of the log:

2016-10-11T16:53:28.427+0000 D SHARDING [conn152969] command: TestDB.$cmd { $query: { find: "TestColl", filter: { user_id: "ScrubbedUserID", timestamp: { $gte: new Date(1474330447254), $lt: new Date(1476204808430) } }, projection: { uuid: 1, _id: 0 }, batchSize: 0 }, $readPreference: { mode: "primaryPreferred" } } ntoreturn: -1 options: 4
2016-10-11T16:53:28.428+0000 D SHARDING [conn152969] Request::process end ns: TestDB.$cmd msg id: 5084 op: 2004 attempt: 0
...
2016-10-11T16:53:28.428+0000 D SHARDING [conn152969] Request::process begin ns: TestDB.$cmd msg id: 5085 op: 2004 attempt: 0
2016-10-11T16:53:28.428+0000 D SHARDING [conn152969] command: TestDB.$cmd { getMore: 332647071905637049, collection: "TestColl" } ntoreturn: -1 options: 0
2016-10-11T16:53:28.428+0000 D EXECUTOR [conn152969] Scheduling remote command request: RemoteCommand 320502955 -- target:host-1a.scrubbedhost.name:27018 db:TestDB cmd:{ find: "TestColl", filter: { user_id: "ScrubbedUserID", timestamp: { $gte: new Date(1474330447254), $lt: new Date(1476204808430) } }, projection: { uuid: 1, _id: 0 }, batchSize: 0, shardVersion: [ Timestamp 42000|0, ObjectId('56708b32a4b9e68df2afbb4e') ] }
2016-10-11T16:53:28.428+0000 D ASIO     [conn152969] startCommand: RemoteCommand 320502955 -- target:host-1a.scrubbedhost.name:27018 db:TestDB cmd:{ find: "TestColl", filter: { user_id: "ScrubbedUserID", timestamp: { $gte: new Date(1474330447254), $lt: new Date(1476204808430) } }, projection: { uuid: 1, _id: 0 }, batchSize: 0, shardVersion: [ Timestamp 42000|0, ObjectId('56708b32a4b9e68df2afbb4e') ] }
2016-10-11T16:53:28.428+0000 D EXECUTOR [conn152969] Scheduling remote command request: RemoteCommand 320502956 -- target:host-2a.scrubbedhost.name:27018 db:TestDB cmd:{ find: "TestColl", filter: { user_id: "ScrubbedUserID", timestamp: { $gte: new Date(1474330447254), $lt: new Date(1476204808430) } }, projection: { uuid: 1, _id: 0 }, batchSize: 0, shardVersion: [ Timestamp 43000|0, ObjectId('56708b32a4b9e68df2afbb4e') ] }
2016-10-11T16:53:28.428+0000 D ASIO     [conn152969] startCommand: RemoteCommand 320502956 -- target:host-2a.scrubbedhost.name:27018 db:TestDB cmd:{ find: "TestColl", filter: { user_id: "ScrubbedUserID", timestamp: { $gte: new Date(1474330447254), $lt: new Date(1476204808430) } }, projection: { uuid: 1, _id: 0 }, batchSize: 0, shardVersion: [ Timestamp 43000|0, ObjectId('56708b32a4b9e68df2afbb4e') ] }
2016-10-11T16:53:28.428+0000 D EXECUTOR [conn152969] Scheduling remote command request: RemoteCommand 320502957 -- target:host-3a.scrubbedhost.name:27018 db:TestDB cmd:{ find: "TestColl", filter: { user_id: "ScrubbedUserID", timestamp: { $gte: new Date(1474330447254), $lt: new Date(1476204808430) } }, projection: { uuid: 1, _id: 0 }, batchSize: 0, shardVersion: [ Timestamp 53000|0, ObjectId('56708b32a4b9e68df2afbb4e') ] }
2016-10-11T16:53:28.428+0000 D ASIO     [conn152969] startCommand: RemoteCommand 320502957 -- target:host-3a.scrubbedhost.name:27018 db:TestDB cmd:{ find: "TestColl", filter: { user_id: "ScrubbedUserID", timestamp: { $gte: new Date(1474330447254), $lt: new Date(1476204808430) } }, projection: { uuid: 1, _id: 0 }, batchSize: 0, shardVersion: [ Timestamp 53000|0, ObjectId('56708b32a4b9e68df2afbb4e') ] }
2016-10-11T16:53:28.428+0000 D EXECUTOR [conn152969] Scheduling remote command request: RemoteCommand 320502958 -- target:host-4a.scrubbedhost.name:27018 db:TestDB cmd:{ find: "TestColl", filter: { user_id: "ScrubbedUserID", timestamp: { $gte: new Date(1474330447254), $lt: new Date(1476204808430) } }, projection: { uuid: 1, _id: 0 }, batchSize: 0, shardVersion: [ Timestamp 52000|0, ObjectId('56708b32a4b9e68df2afbb4e') ] }
2016-10-11T16:53:28.428+0000 D ASIO     [conn152969] startCommand: RemoteCommand 320502958 -- target:host-4a.scrubbedhost.name:27018 db:TestDB cmd:{ find: "TestColl", filter: { user_id: "ScrubbedUserID", timestamp: { $gte: new Date(1474330447254), $lt: new Date(1476204808430) } }, projection: { uuid: 1, _id: 0 }, batchSize: 0, shardVersion: [ Timestamp 52000|0, ObjectId('56708b32a4b9e68df2afbb4e') ] }
2016-10-11T16:53:28.428+0000 D EXECUTOR [conn152969] Scheduling remote command request: RemoteCommand 320502959 -- target:host-5a.scrubbedhost.name:27018 db:TestDB cmd:{ find: "TestColl", filter: { user_id: "ScrubbedUserID", timestamp: { $gte: new Date(1474330447254), $lt: new Date(1476204808430) } }, projection: { uuid: 1, _id: 0 }, batchSize: 0, shardVersion: [ Timestamp 53000|1, ObjectId('56708b32a4b9e68df2afbb4e') ] }
2016-10-11T16:53:28.429+0000 D ASIO     [conn152969] startCommand: RemoteCommand 320502959 -- target:host-5a.scrubbedhost.name:27018 db:TestDB cmd:{ find: "TestColl", filter: { user_id: "ScrubbedUserID", timestamp: { $gte: new Date(1474330447254), $lt: new Date(1476204808430) } }, projection: { uuid: 1, _id: 0 }, batchSize: 0, shardVersion: [ Timestamp 53000|1, ObjectId('56708b32a4b9e68df2afbb4e') ] }
2016-10-11T16:53:28.429+0000 D EXECUTOR [conn152969] Scheduling remote command request: RemoteCommand 320502961 -- target:host-6a.scrubbedhost.name:27018 db:TestDB cmd:{ find: "TestColl", filter: { user_id: "ScrubbedUserID", timestamp: { $gte: new Date(1474330447254), $lt: new Date(1476204808430) } }, projection: { uuid: 1, _id: 0 }, batchSize: 0, shardVersion: [ Timestamp 46000|0, ObjectId('56708b32a4b9e68df2afbb4e') ] }
2016-10-11T16:53:28.429+0000 D ASIO     [conn152969] startCommand: RemoteCommand 320502961 -- target:host-6a.scrubbedhost.name:27018 db:TestDB cmd:{ find: "TestColl", filter: { user_id: "ScrubbedUserID", timestamp: { $gte: new Date(1474330447254), $lt: new Date(1476204808430) } }, projection: { uuid: 1, _id: 0 }, batchSize: 0, shardVersion: [ Timestamp 46000|0, ObjectId('56708b32a4b9e68df2afbb4e') ] }
2016-10-11T16:53:28.429+0000 D EXECUTOR [conn152969] Scheduling remote command request: RemoteCommand 320502962 -- target:host-7a.scrubbedhost.name:27018 db:TestDB cmd:{ find: "TestColl", filter: { user_id: "ScrubbedUserID", timestamp: { $gte: new Date(1474330447254), $lt: new Date(1476204808430) } }, projection: { uuid: 1, _id: 0 }, batchSize: 0, shardVersion: [ Timestamp 47000|0, ObjectId('56708b32a4b9e68df2afbb4e') ] }
2016-10-11T16:53:28.429+0000 D ASIO     [conn152969] startCommand: RemoteCommand 320502962 -- target:host-7a.scrubbedhost.name:27018 db:TestDB cmd:{ find: "TestColl", filter: { user_id: "ScrubbedUserID", timestamp: { $gte: new Date(1474330447254), $lt: new Date(1476204808430) } }, projection: { uuid: 1, _id: 0 }, batchSize: 0, shardVersion: [ Timestamp 47000|0, ObjectId('56708b32a4b9e68df2afbb4e') ] }
2016-10-11T16:53:28.429+0000 D EXECUTOR [conn152969] Scheduling remote command request: RemoteCommand 320502963 -- target:host-8a.scrubbedhost.name:27018 db:TestDB cmd:{ find: "TestColl", filter: { user_id: "ScrubbedUserID", timestamp: { $gte: new Date(1474330447254), $lt: new Date(1476204808430) } }, projection: { uuid: 1, _id: 0 }, batchSize: 0, shardVersion: [ Timestamp 51000|0, ObjectId('56708b32a4b9e68df2afbb4e') ] }
2016-10-11T16:53:28.429+0000 D ASIO     [conn152969] startCommand: RemoteCommand 320502963 -- target:host-8a.scrubbedhost.name:27018 db:TestDB cmd:{ find: "TestColl", filter: { user_id: "ScrubbedUserID", timestamp: { $gte: new Date(1474330447254), $lt: new Date(1476204808430) } }, projection: { uuid: 1, _id: 0 }, batchSize: 0, shardVersion: [ Timestamp 51000|0, ObjectId('56708b32a4b9e68df2afbb4e') ] }
2016-10-11T16:53:28.429+0000 D EXECUTOR [conn152969] Scheduling remote command request: RemoteCommand 320502964 -- target:host-9a.scrubbedhost.name:27018 db:TestDB cmd:{ find: "TestColl", filter: { user_id: "ScrubbedUserID", timestamp: { $gte: new Date(1474330447254), $lt: new Date(1476204808430) } }, projection: { uuid: 1, _id: 0 }, batchSize: 0, shardVersion: [ Timestamp 50000|0, ObjectId('56708b32a4b9e68df2afbb4e') ] }
2016-10-11T16:53:28.429+0000 D ASIO     [conn152969] startCommand: RemoteCommand 320502964 -- target:host-9a.scrubbedhost.name:27018 db:TestDB cmd:{ find: "TestColl", filter: { user_id: "ScrubbedUserID", timestamp: { $gte: new Date(1474330447254), $lt: new Date(1476204808430) } }, projection: { uuid: 1, _id: 0 }, batchSize: 0, shardVersion: [ Timestamp 50000|0, ObjectId('56708b32a4b9e68df2afbb4e') ] }
2016-10-11T16:53:28.430+0000 D SHARDING [conn152969] Request::process end ns: TestDB.$cmd msg id: 5085 op: 2004 attempt: 0



 Comments   
Comment by David Storch [ 31/Mar/17 ]

Resolving as a duplicate instead of as "Fixed", since this was fixed by Esha's work under SERVER-27937.

Comment by Esha Maharishi (Inactive) [ 30/Mar/17 ]

Fixed on master by commit https://github.com/mongodb/mongo/commit/ba1fa56004826b42bd8fa7d5b5a0c78fc1b57af9 for SERVER-27937.

Comment by David Storch [ 13/Mar/17 ]

This issue only affects find commands which specify a batchSize of 0. However, the driver specification for handling the find, getMore, and killCursors commands clearly specifies that drivers should not pass find commands with batchSize:0 through to the server:

https://github.com/mongodb/specifications/blob/master/source/find_getmore_killcursors_commands.rst#mapping-op_query-behavior-to-the-find-command-limit-and-batchsize-fields

Therefore, this issue should not affect applications whose drivers correctly conform to this specification. Given this fact, and the complexity of the fix, a backport of this work to the 3.4 or 3.2 branch is not likely. However, work is in progress which will resolve the issue in the 3.5.x development release series.

Comment by David Storch [ 14/Dec/16 ]

It looks like this problem occurs due to the fact that the find command delivered by the client to mongos specifies a batchSize of 0:

{ find: "TestColl", filter: { user_id: "ScrubbedUserID", timestamp: { $gte: new Date(1474330447254), $lt: new Date(1476204808430) } }, projection: { uuid: 1, _id: 0 }, batchSize: 0 }

The mongos query path in 3.2 will establish cursors on the shards as part of the process of retrieving the first result from the shards. If the batchSize is 0, work to retrieve any results is skipped, which in turn skips the logic to establish cursors on the shards and receive initial result batches.

This is not the case for the aggregate command, which also supports a batchSize of 0. Before actually beginning to retrieve any results, the aggregate command on mongos will forward a batchSize:0 query to the participating shards in order to set up cursors:

https://github.com/mongodb/mongo/blob/v3.2/src/mongo/s/commands/cluster_pipeline_cmd.cpp#L177-L178

It then transfers ownership of these cursors to the mongos cursor manager before returning an empty batch to the client. In order to properly handle the batchSize:0 case, the find command should probably do the same. Namely, it should eagerly forward batchSize:0 queries to the shards and hand off ownership of the resulting cursors to the ClusterCursorManager.

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