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

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Duplicate
    • Affects Version/s: 3.2.10
    • Fix Version/s: None
    • Component/s: Querying, Sharding
    • Labels:
      None
    • Backwards Compatibility:
      Fully Compatible
    • Operating System:
      ALL
    • Backport Requested:
      v3.4, v3.2
    • Steps To Reproduce:
      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"});
    • Sprint:
      Query 2017-01-23, Query 2017-02-13
    • 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
      

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              esha.maharishi Esha Maharishi
              Reporter:
              kaloian.manassiev Kaloian Manassiev
              Participants:
              Votes:
              0 Vote for this issue
              Watchers:
              18 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: