Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-27286

Cluster find command with batchSize of 0 delays initial cursor establishment until 'getMore' time

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Duplicate
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: 3.2.10
    • Component/s: Querying, Sharding
    • None
    • Fully Compatible
    • ALL
    • v3.4, v3.2
    • Hide 
      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"});
      Show
      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" });
    • Query 2017-01-23, Query 2017-02-13

      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

            Assignee:
            esha.maharishi@mongodb.com Esha Maharishi (Inactive)
            Reporter:
            kaloian.manassiev@mongodb.com Kaloian Manassiev
            Votes:
            0 Vote for this issue
            Watchers:
            18 Start watching this issue

              Created:
              Updated:
              Resolved: