Slow first query on huge collection

Ops and Admin Sharding
, , ,
1

Hi All,

I am having an issue where I make a simple find query and the first attempt for particular items might take 20 to 30 seconds, but then if I query for the same items it is under half a second. Pretty sure this is due to caching but the initial query taking so long is causing be quite a lot of grief.

I am aware the first query is likely being pulled from disk, but I don’t believe it should take as long as it does given there is at most about 10K documents for any particular indexed item. So even if I only filtered on the indexed item for all records it should only pull in a reasonably small set.

I am using fairly high spec VMs backed by an enterprise SSD storage data centre.

DB is split across 4 shards each having 2 RS+Arb. 8CPU/32GB/3TB ea
Using 2 mongos. 4CPU/16GB ea

[mongos] ni4cc2> db.data_events.getIndexes()
[
  { v: 2, key: { _id: 1 }, name: '_id_' },
  {
    v: 2,
    key: { 'commonEventHeader.eventFields.msisdn': 'hashed' },
    name: 'commonEventHeader.eventFields.msisdn_hashed'
  },
  {
    v: 2,
    key: { start_epoch_microsec: 1 },
    name: 'start_epoch_microsec_1',
    expireAfterSeconds: 3024000
  }
]

[mongos] ni4cc2> db.data_events.getShardDistribution()
Shard ni4cc2-rs4 at ni4cc2-rs4/dbnode4:27050,dbnode8:27051
{
  data: '2636.88GiB',
  docs: 543863130,
  chunks: 24672,
  'estimated data per chunk': '109.44MiB',
  'estimated docs per chunk': 22043
}
---
Shard ni4cc2-rs3 at ni4cc2-rs3/dbnode3:27040,dbnode7:27041
{
  data: '3970.52GiB',
  docs: 1194578619,
  chunks: 24672,
  'estimated data per chunk': '164.79MiB',
  'estimated docs per chunk': 48418
}
---
Shard ni4cc2-rs1 at ni4cc2-rs1/dbnode1:27020,dbnode5:27021
{
  data: '2640.67GiB',
  docs: 544733199,
  chunks: 24673,
  'estimated data per chunk': '109.59MiB',
  'estimated docs per chunk': 22078
}
---
Shard ni4cc2-rs2 at ni4cc2-rs2/dbnode2:27030,dbnode6:27031
{
  data: '2633.88GiB',
  docs: 543462431,
  chunks: 24672,
  'estimated data per chunk': '109.31MiB',
  'estimated docs per chunk': 22027
}
---
Totals
{
  data: '2.6368893047463394e+42GiB',
  docs: 2826637379,
  chunks: 98689,
  'Shard ni4cc2-rs4': [
    '0 % data',
    '19.24 % docs in cluster',
    '5KiB avg obj size on shard'
  ],
  'Shard ni4cc2-rs3': [
    '0 % data',
    '42.26 % docs in cluster',
    '3KiB avg obj size on shard'
  ],
  'Shard ni4cc2-rs1': [
    '0 % data',
    '19.27 % docs in cluster',
    '5KiB avg obj size on shard'
  ],
  'Shard ni4cc2-rs2': [
    '0 % data',
    '19.22 % docs in cluster',
    '5KiB avg obj size on shard'
  ]
}

[mongos] ni4cc2> db.data_events.explain("allPlansExecution").find({
...     "commonEventHeader.eventFields.msisdn":'8stringOFnums8',
...     "start_epoch_microsec": {
.....         "$gte": new Date("2022-10-09T00:00:00+10:00"),
.....         "$lt" : new Date("2022-10-11T00:00:00+10:00")
.....     }
... })
{
  queryPlanner: {
    mongosPlannerVersion: 1,
    winningPlan: {
      stage: 'SINGLE_SHARD',
      shards: [
        {
          shardName: 'ni4cc2-rs3',
          connectionString: 'ni4cc2-rs3/dbnode3:27040,dbnode7:27041',
          serverInfo: {
            host: '1c921c1e4ec1',
            port: 27017,
            version: '6.0.2',
            gitVersion: '94fb7dfc8b974f1f5343e7ea394d0d9deedba50e'
          },
          namespace: 'ni4cc2.data_events',
          indexFilterSet: false,
          parsedQuery: {
            '$and': [
              {
                'commonEventHeader.eventFields.msisdn': { '$eq': '8stringOFnums8' }
              },
              {
                start_epoch_microsec: { '$lt': ISODate("2022-10-10T14:00:00.000Z") }
              },
              {
                start_epoch_microsec: { '$gte': ISODate("2022-10-08T14:00:00.000Z") }
              }
            ]
          },
          queryHash: 'C12E761C',
          planCacheKey: '3E585050',
          maxIndexedOrSolutionsReached: false,
          maxIndexedAndSolutionsReached: false,
          maxScansToExplodeReached: false,
          winningPlan: {
            stage: 'FETCH',
            filter: {
              '$and': [
                {
                  'commonEventHeader.eventFields.msisdn': { '$eq': '8stringOFnums8' }
                },
                {
                  start_epoch_microsec: { '$lt': ISODate("2022-10-10T14:00:00.000Z") }
                },
                {
                  start_epoch_microsec: { '$gte': ISODate("2022-10-08T14:00:00.000Z") }
                }
              ]
            },
            inputStage: {
              stage: 'IXSCAN',
              keyPattern: { 'commonEventHeader.eventFields.msisdn': 'hashed' },
              indexName: 'commonEventHeader.eventFields.msisdn_hashed',
              isMultiKey: false,
              isUnique: false,
              isSparse: false,
              isPartial: false,
              indexVersion: 2,
              direction: 'forward',
              indexBounds: {
                'commonEventHeader.eventFields.msisdn': [ '[3554060079612239688, 3554060079612239688]' ]
              }
            }
          },
          rejectedPlans: [
            {
              stage: 'FETCH',
              filter: {
                'commonEventHeader.eventFields.msisdn': { '$eq': '8stringOFnums8' }
              },
              inputStage: {
                stage: 'IXSCAN',
                keyPattern: { start_epoch_microsec: 1 },
                indexName: 'start_epoch_microsec_1',
                isMultiKey: false,
                multiKeyPaths: { start_epoch_microsec: [] },
                isUnique: false,
                isSparse: false,
                isPartial: false,
                indexVersion: 2,
                direction: 'forward',
                indexBounds: {
                  start_epoch_microsec: [
                    '[new Date(1665237600000), new Date(1665410400000))'
                  ]
                }
              }
            }
          ]
        }
      ]
    }
  },
  executionStats: {
    nReturned: 0,
    executionTimeMillis: 22,
    totalKeysExamined: 6,
    totalDocsExamined: 6,
    executionStages: {
      stage: 'SINGLE_SHARD',
      nReturned: 0,
      executionTimeMillis: 22,
      totalKeysExamined: 6,
      totalDocsExamined: 6,
      totalChildMillis: Long("21"),
      shards: [
        {
          shardName: 'ni4cc2-rs3',
          executionSuccess: true,
          nReturned: 0,
          executionTimeMillis: 21,
          totalKeysExamined: 6,
          totalDocsExamined: 6,
          executionStages: {
            stage: 'FETCH',
            filter: {
              '$and': [
                {
                  'commonEventHeader.eventFields.msisdn': { '$eq': '8stringOFnums8' }
                },
                {
                  start_epoch_microsec: { '$lt': ISODate("2022-10-10T14:00:00.000Z") }
                },
                {
                  start_epoch_microsec: { '$gte': ISODate("2022-10-08T14:00:00.000Z") }
                }
              ]
            },
            nReturned: 0,
            executionTimeMillisEstimate: 11,
            works: 8,
            advanced: 0,
            needTime: 6,
            needYield: 0,
            saveState: 1,
            restoreState: 1,
            isEOF: 1,
            docsExamined: 6,
            alreadyHasObj: 0,
            inputStage: {
              stage: 'IXSCAN',
              nReturned: 6,
              executionTimeMillisEstimate: 1,
              works: 7,
              advanced: 6,
              needTime: 0,
              needYield: 0,
              saveState: 1,
              restoreState: 1,
              isEOF: 1,
              keyPattern: { 'commonEventHeader.eventFields.msisdn': 'hashed' },
              indexName: 'commonEventHeader.eventFields.msisdn_hashed',
              isMultiKey: false,
              isUnique: false,
              isSparse: false,
              isPartial: false,
              indexVersion: 2,
              direction: 'forward',
              indexBounds: {
                'commonEventHeader.eventFields.msisdn': [ '[3554060079612239688, 3554060079612239688]' ]
              },
              keysExamined: 6,
              seeks: 1,
              dupsTested: 0,
              dupsDropped: 0
            }
          },
          allPlansExecution: [
            {
              nReturned: 0,
              executionTimeMillisEstimate: 11,
              totalKeysExamined: 6,
              totalDocsExamined: 6,
              score: 2.0002,
              executionStages: {
                stage: 'FETCH',
                filter: {
                  '$and': [
                    {
                      'commonEventHeader.eventFields.msisdn': { '$eq': '8stringOFnums8' }
                    },
                    {
                      start_epoch_microsec: { '$lt': ISODate("2022-10-10T14:00:00.000Z") }
                    },
                    {
                      start_epoch_microsec: { '$gte': ISODate("2022-10-08T14:00:00.000Z") }
                    }
                  ]
                },
                nReturned: 0,
                executionTimeMillisEstimate: 11,
                works: 7,
                advanced: 0,
                needTime: 6,
                needYield: 0,
                saveState: 1,
                restoreState: 1,
                isEOF: 1,
                docsExamined: 6,
                alreadyHasObj: 0,
                inputStage: {
                  stage: 'IXSCAN',
                  nReturned: 6,
                  executionTimeMillisEstimate: 1,
                  works: 7,
                  advanced: 6,
                  needTime: 0,
                  needYield: 0,
                  saveState: 1,
                  restoreState: 1,
                  isEOF: 1,
                  keyPattern: { 'commonEventHeader.eventFields.msisdn': 'hashed' },
                  indexName: 'commonEventHeader.eventFields.msisdn_hashed',
                  isMultiKey: false,
                  isUnique: false,
                  isSparse: false,
                  isPartial: false,
                  indexVersion: 2,
                  direction: 'forward',
                  indexBounds: {
                    'commonEventHeader.eventFields.msisdn': [ '[3554060079612239688, 3554060079612239688]' ]
                  },
                  keysExamined: 6,
                  seeks: 1,
                  dupsTested: 0,
                  dupsDropped: 0
                }
              }
            },
            {
              nReturned: 0,
              executionTimeMillisEstimate: 6,
              totalKeysExamined: 7,
              totalDocsExamined: 7,
              score: 1.0002,
              executionStages: {
                stage: 'FETCH',
                filter: {
                  'commonEventHeader.eventFields.msisdn': { '$eq': '8stringOFnums8' }
                },
                nReturned: 0,
                executionTimeMillisEstimate: 6,
                works: 7,
                advanced: 0,
                needTime: 7,
                needYield: 0,
                saveState: 1,
                restoreState: 1,
                isEOF: 0,
                docsExamined: 7,
                alreadyHasObj: 0,
                inputStage: {
                  stage: 'IXSCAN',
                  nReturned: 7,
                  executionTimeMillisEstimate: 2,
                  works: 7,
                  advanced: 7,
                  needTime: 0,
                  needYield: 0,
                  saveState: 1,
                  restoreState: 1,
                  isEOF: 0,
                  keyPattern: { start_epoch_microsec: 1 },
                  indexName: 'start_epoch_microsec_1',
                  isMultiKey: false,
                  multiKeyPaths: { start_epoch_microsec: [] },
                  isUnique: false,
                  isSparse: false,
                  isPartial: false,
                  indexVersion: 2,
                  direction: 'forward',
                  indexBounds: {
                    start_epoch_microsec: [
                      '[new Date(1665237600000), new Date(1665410400000))'
                    ]
                  },
                  keysExamined: 7,
                  seeks: 1,
                  dupsTested: 0,
                  dupsDropped: 0
                }
              }
            }
          ]
        }
      ]
    },
    allPlansExecution: [
      {
        shardName: 'ni4cc2-rs3',
        allPlans: [
          {
            nReturned: 0,
            executionTimeMillisEstimate: 11,
            totalKeysExamined: 6,
            totalDocsExamined: 6,
            score: 2.0002,
            executionStages: {
              stage: 'FETCH',
              filter: {
                '$and': [
                  {
                    'commonEventHeader.eventFields.msisdn': { '$eq': '8stringOFnums8' }
                  },
                  {
                    start_epoch_microsec: { '$lt': ISODate("2022-10-10T14:00:00.000Z") }
                  },
                  {
                    start_epoch_microsec: { '$gte': ISODate("2022-10-08T14:00:00.000Z") }
                  }
                ]
              },
              nReturned: 0,
              executionTimeMillisEstimate: 11,
              works: 7,
              advanced: 0,
              needTime: 6,
              needYield: 0,
              saveState: 1,
              restoreState: 1,
              isEOF: 1,
              docsExamined: 6,
              alreadyHasObj: 0,
              inputStage: {
                stage: 'IXSCAN',
                nReturned: 6,
                executionTimeMillisEstimate: 1,
                works: 7,
                advanced: 6,
                needTime: 0,
                needYield: 0,
                saveState: 1,
                restoreState: 1,
                isEOF: 1,
                keyPattern: { 'commonEventHeader.eventFields.msisdn': 'hashed' },
                indexName: 'commonEventHeader.eventFields.msisdn_hashed',
                isMultiKey: false,
                isUnique: false,
                isSparse: false,
                isPartial: false,
                indexVersion: 2,
                direction: 'forward',
                indexBounds: {
                  'commonEventHeader.eventFields.msisdn': [ '[3554060079612239688, 3554060079612239688]' ]
                },
                keysExamined: 6,
                seeks: 1,
                dupsTested: 0,
                dupsDropped: 0
              }
            }
          },
          {
            nReturned: 0,
            executionTimeMillisEstimate: 6,
            totalKeysExamined: 7,
            totalDocsExamined: 7,
            score: 1.0002,
            executionStages: {
              stage: 'FETCH',
              filter: {
                'commonEventHeader.eventFields.msisdn': { '$eq': '8stringOFnums8' }
              },
              nReturned: 0,
              executionTimeMillisEstimate: 6,
              works: 7,
              advanced: 0,
              needTime: 7,
              needYield: 0,
              saveState: 1,
              restoreState: 1,
              isEOF: 0,
              docsExamined: 7,
              alreadyHasObj: 0,
              inputStage: {
                stage: 'IXSCAN',
                nReturned: 7,
                executionTimeMillisEstimate: 2,
                works: 7,
                advanced: 7,
                needTime: 0,
                needYield: 0,
                saveState: 1,
                restoreState: 1,
                isEOF: 0,
                keyPattern: { start_epoch_microsec: 1 },
                indexName: 'start_epoch_microsec_1',
                isMultiKey: false,
                multiKeyPaths: { start_epoch_microsec: [] },
                isUnique: false,
                isSparse: false,
                isPartial: false,
                indexVersion: 2,
                direction: 'forward',
                indexBounds: {
                  start_epoch_microsec: [
                    '[new Date(1665237600000), new Date(1665410400000))'
                  ]
                },
                keysExamined: 7,
                seeks: 1,
                dupsTested: 0,
                dupsDropped: 0
              }
            }
          }
        ]
      }
    ]
  },
  serverInfo: {
    host: '5d950768592c',
    port: 27017,
    version: '6.0.2',
    gitVersion: '94fb7dfc8b974f1f5343e7ea394d0d9deedba50e'
  },
  serverParameters: {
    internalQueryFacetBufferSizeBytes: 104857600,
    internalQueryFacetMaxOutputDocSizeBytes: 104857600,
    internalLookupStageIntermediateDocumentMaxSizeBytes: 104857600,
    internalDocumentSourceGroupMaxMemoryBytes: 104857600,
    internalQueryMaxBlockingSortMemoryUsageBytes: 104857600,
    internalQueryProhibitBlockingMergeOnMongoS: 0,
    internalQueryMaxAddToSetBytes: 104857600,
    internalDocumentSourceSetWindowFieldsMaxMemoryBytes: 104857600
  },
  command: {
    find: 'data_events',
    filter: {
      'commonEventHeader.eventFields.msisdn': '8stringOFnums8',
      start_epoch_microsec: {
        '$gte': ISODate("2022-10-08T14:00:00.000Z"),
        '$lt': ISODate("2022-10-10T14:00:00.000Z")
      }
    },
    lsid: { id: UUID("bcf5d84a-6a4e-49f9-b53b-dd606a732347") },
    '$clusterTime': {
      clusterTime: Timestamp({ t: 1665616627, i: 347 }),
      signature: {
        hash: Binary(Buffer.from("0000000000000000000000000000000000000000", "hex"), 0),
        keyId: Long("0")
      }
    },
    '$db': 'ni4cc2',
    '$readPreference': { mode: 'secondaryPreferred' }
  },
  ok: 1,
  '$clusterTime': {
    clusterTime: Timestamp({ t: 1665616950, i: 404 }),
    signature: {
      hash: Binary(Buffer.from("0000000000000000000000000000000000000000", "hex"), 0),
      keyId: Long("0")
    }
  },
  operationTime: Timestamp({ t: 1665616950, i: 402 })
}

I did notice it seems to favor the Hashed index based on the partitioning key. Ignoring the date index.

[mongos] ni4cc2> db.data_events.latencyStats()
[
  {
    ns: 'ni4cc2.data_events',
    shard: 'ni4cc2-rs4',
    host: '947f417ee9e7:27017',
    localTime: ISODate("2022-10-13T00:40:04.611Z"),
    latencyStats: {
      reads: { latency: Long("30374180"), ops: Long("351") },
      writes: { latency: Long("0"), ops: Long("0") },
      commands: { latency: Long("15483"), ops: Long("8") },
      transactions: { latency: Long("0"), ops: Long("0") }
    }
  },
  {
    ns: 'ni4cc2.data_events',
    shard: 'ni4cc2-rs2',
    host: '1198a80e3a0d:27017',
    localTime: ISODate("2022-10-13T00:40:04.611Z"),
    latencyStats: {
      reads: { latency: Long("5680449"), ops: Long("306") },
      writes: { latency: Long("0"), ops: Long("0") },
      commands: { latency: Long("0"), ops: Long("0") },
      transactions: { latency: Long("0"), ops: Long("0") }
    }
  },
  {
    ns: 'ni4cc2.data_events',
    shard: 'ni4cc2-rs1',
    host: 'b5b60ccde536:27017',
    localTime: ISODate("2022-10-13T00:40:04.612Z"),
    latencyStats: {
      reads: { latency: Long("14913376"), ops: Long("319") },
      writes: { latency: Long("0"), ops: Long("0") },
      commands: { latency: Long("0"), ops: Long("0") },
      transactions: { latency: Long("0"), ops: Long("0") }
    }
  },
  {
    ns: 'ni4cc2.data_events',
    shard: 'ni4cc2-rs3',
    host: '1c921c1e4ec1:27017',
    localTime: ISODate("2022-10-13T00:40:04.611Z"),
    latencyStats: {
      reads: { latency: Long("541987744"), ops: Long("2957") },
      writes: { latency: Long("1531416588"), ops: Long("444521") },
      commands: { latency: Long("4452502327"), ops: Long("13") },
      transactions: { latency: Long("0"), ops: Long("0") }
    }
  }
]

[mongos] config> db.chunks.latencyStats()
[
  {
    ns: 'config.chunks',
    host: 'e89bcffaddb9:27017',
    localTime: ISODate("2022-10-13T00:44:30.624Z"),
    latencyStats: {
      reads: { latency: Long("3099752"), ops: Long("3273") },
      writes: { latency: Long("0"), ops: Long("0") },
      commands: { latency: Long("0"), ops: Long("0") },
      transactions: { latency: Long("0"), ops: Long("0") }
    }
  }
]

I am seeing a lot of IOWait on some nodes with top and vmstat, yet iostat shows not very much and also the data rate for the disks is only around 50MB/s yet it can push upwards of 250MB/s on a file copy.

Also wondered if the config DB was contributing! How much of the chunk distrubution is cached? I don’t see any index on the config database for the partition key, how does the mongos determine the RS?

[mongos] config> db.chunks.getIndexes()
[
  { v: 2, key: { _id: 1 }, name: '_id_' },
  {
    v: 2,
    key: { uuid: 1, min: 1 },
    name: 'uuid_1_min_1',
    unique: true
  },
  {
    v: 2,
    key: { uuid: 1, shard: 1, min: 1 },
    name: 'uuid_1_shard_1_min_1',
    unique: true
  },
  {
    v: 2,
    key: { uuid: 1, lastmod: 1 },
    name: 'uuid_1_lastmod_1',
    unique: true
  }
]

I have set the following tuning suggestions, Which didn’t seem to make any difference:

  • vm.max_map_count=128000
  • transparent_hugepages=never
  • transparent_hugepage.defrag=never
  • readahead=32
  • IO Scheduler=noop

It doesn’t seem to make a difference if I specify date range or not, So I suspect this ties in with the unutilized date index.

Some options I have thought about:

  • More ReplicaSets, Perhaps putting 4 replicasets per node for a total of 16
  • Splitting the collection up into multiple collections with a two digit hash appended to collection name to simulate internal partitioning. EG: data_events → data_events_[00-ff] then manually hash the msisdn to know which collection to insert or query

Many hours spent already investigating, Appreciate any suggestions on checks, strategies, issues?

3

Hi @John_Torr and welcome to the MongoDB community forum!!

Firstly would appreciate you sharing a post with much detailed information.

There might be more than one reason why you are seeing the issue.
Firstly read operation in MongoDB, it needs to fetch from disk if the documents are not in memory yet and since disk is usually the slowest part of a machine, loading a lot of data from disk might take some time.

Secondly, the next time you fetch the same data, it would be faster since they’re already cached in memory.

The other reason which might cause the delay in the query operation may be because of the way the shard key has been defined in your sharding deployment.

By “partition key” do you mean shard key?

MongoDB typically attempt to involve as few shards as possible when answering a query since generally it’s more performant and allow better parallelisation, thus it will select the index which can avoid a scatter-gather response.

To answer a your questions on:

The config DB is basically responsible for storing the metadata and only has internal use. The application and administration should not modify or depend on the content in course of normal operation.

It basically stores information like routing information, list of sharded collections, status of the balancer etc.
The shards and the mongos are the ones mostly responsible for the performance of the sharding deployment. However, they use the config servers DB to get the copy of the metadata.

The mongos queries the config servers for cluster information and then routes queries to the respective shards. You can visit the documentation for more information.

Let us know if you have any further queries.

Best Regards
Aasawari