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

Stuck creating index with "Index Build: draining writes received during build"

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: 5.0.14
    • Component/s: None
    • ALL

      I have checked out the previous issues: https://jira.mongodb.org/browse/SERVER-50665 and https://jira.mongodb.org/browse/SERVER-48516

      I have ensured a keyfile exists, and I then stopped and started the servers again (in the recommended order, first stop secondaries then master, etc.)

      None of this helped and I have no idea what to do.

      Mongo version 5.0.14

       

      The `op` output for example:

      ```
      {
        type: 'op',
        host: 'mongo02:27017',
        desc: 'IndexBuildsCoordinatorMongod-2',
        active: false,
        currentOpTime: '2022-12-29T16:15:18.739+00:00',
        opid: 7,
        secs_running: Long("840"),
        microsecs_running: Long("840383035"),
        op: 'command',
        ns: 'captainup.actions',
        command: {
          createIndexes: 'actions',
          indexes: [
           

      {         v: 2,         key: [Object],         name: 'store_id_1_name_1_timestamp_1',         sparse: false       }

          ]
        },
        msg: 'Index Build: draining writes received during build',
        numYields: 3114,
        locks: {},
        waitingForLock: false,
        lockStats: {
          FeatureCompatibilityVersion: { acquireCount:

      { w: Long("4136") }

      },
          ReplicationStateTransition:

      {       acquireCount: \{ w: Long("4137") }

      ,
            acquireWaitCount: { w: Long("1") },
            timeAcquiringMicros: { w: Long("779") }
          },
          Global:

      {       acquireCount: \{ w: Long("4136") }

      ,
            acquireWaitCount: { w: Long("5") },
            timeAcquiringMicros: { w: Long("14438") }
          },
          Database: { acquireCount:

      { w: Long("4136") }

      },
          Collection: { acquireCount:

      { w: Long("4135"), R: Long("1") }

      }
        },
        waitingForFlowControl: false,
        flowControlStats: { acquireCount: Long("3944"), timeAcquiringMicros: Long("2025") }
      }
      ```
       
      A few lines relevant from the `mongod.log`:
      ```

      {"t":\{"$date":"2022-12-29T16:17:12.123+00:00"}

      ,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":534,"totalInserted":534,"totalDeleted":0,"durationMillis":2}}

      {"t":\{"$date":"2022-12-29T16:17:12.706+00:00"}

      ,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build: drained side writes","attr":{"index":"timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":529,"totalInserted":529,"totalDeleted":0,"durationMillis":24}}

      {"t":\{"$date":"2022-12-29T16:17:13.127+00:00"}

      ,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":547,"totalInserted":547,"totalDeleted":0,"durationMillis":2}}

      {"t":\{"$date":"2022-12-29T16:17:13.709+00:00"}

      ,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build: drained side writes","attr":{"index":"timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":534,"totalInserted":534,"totalDeleted":0,"durationMillis":2}}

      {"t":\{"$date":"2022-12-29T16:17:14.131+00:00"}

      ,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":511,"totalInserted":511,"totalDeleted":0,"durationMillis":2}}

      {"t":\{"$date":"2022-12-29T16:17:14.712+00:00"}

      ,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build: drained side writes","attr":{"index":"timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":523,"totalInserted":523,"totalDeleted":0,"durationMillis":1}}

      {"t":\{"$date":"2022-12-29T16:17:15.135+00:00"}

      ,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":528,"totalInserted":528,"totalDeleted":0,"durationMillis":2}}

      {"t":\{"$date":"2022-12-29T16:17:15.715+00:00"}

      ,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build: drained side writes","attr":{"index":"timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":498,"totalInserted":498,"totalDeleted":0,"durationMillis":2}}

      {"t":\{"$date":"2022-12-29T16:17:16.138+00:00"}

      ,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":515,"totalInserted":515,"totalDeleted":0,"durationMillis":2}}

      {"t":\{"$date":"2022-12-29T16:17:16.717+00:00"}

      ,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build: drained side writes","attr":{"index":"timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":519,"totalInserted":519,"totalDeleted":0,"durationMillis":1}}

      {"t":\{"$date":"2022-12-29T16:17:17.142+00:00"}

      ,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":517,"totalInserted":517,"totalDeleted":0,"durationMillis":2}}

      {"t":\{"$date":"2022-12-29T16:17:17.720+00:00"}

      ,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build: drained side writes","attr":{"index":"timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":536,"totalInserted":536,"totalDeleted":0,"durationMillis":1}}

      {"t":\{"$date":"2022-12-29T16:17:18.145+00:00"}

      ,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":527,"totalInserted":527,"totalDeleted":0,"durationMillis":2}}

      {"t":\{"$date":"2022-12-29T16:17:18.722+00:00"}

      ,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build: drained side writes","attr":{"index":"timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":471,"totalInserted":471,"totalDeleted":0,"durationMillis":1}}

      {"t":\{"$date":"2022-12-29T16:17:19.148+00:00"}

      ,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":413,"totalInserted":413,"totalDeleted":0,"durationMillis":1}}

      {"t":\{"$date":"2022-12-29T16:17:19.725+00:00"}

      ,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build: drained side writes","attr":{"index":"timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":433,"totalInserted":433,"totalDeleted":0,"durationMillis":1}}

      {"t":\{"$date":"2022-12-29T16:17:20.152+00:00"}

      ,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":542,"totalInserted":542,"totalDeleted":0,"durationMillis":2}}

      {"t":\{"$date":"2022-12-29T16:17:20.727+00:00"}

      ,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build: drained side writes","attr":{"index":"timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":533,"totalInserted":533,"totalDeleted":0,"durationMillis":1}}

      {"t":\{"$date":"2022-12-29T16:17:21.155+00:00"}

      ,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":486,"totalInserted":486,"totalDeleted":0,"durationMillis":2}}

      {"t":\{"$date":"2022-12-29T16:17:21.729+00:00"}

      ,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build: drained side writes","attr":{"index":"timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":500,"totalInserted":500,"totalDeleted":0,"durationMillis":1}}

      {"t":\{"$date":"2022-12-29T16:17:22.158+00:00"}

      ,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":492,"totalInserted":492,"totalDeleted":0,"durationMillis":2}}
      ```
       
      Important to say: indexes did work before in my setup. Nothing changed, I just tried to create a few new indices and that happened.

            Assignee:
            chris.kelly@mongodb.com Chris Kelly
            Reporter:
            snirda@gmail.com Snir David
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: