mongodb executionStats 时间与实际执行时间不同答案

【问题标题】：mongodb executionStats time is different than real executionmongodb executionStats 时间与实际执行时间不同
【发布时间】：2021-11-13 16:05:43
【问题描述】：

我正在使用 M10 mongodb atlas (2GB RAM, 2CPU) 进行测试。我在集合中有 101330 个文档。每个文档看起来像

{
  _id: ObjectId("618d3bf93de582a797f28df3"),
  applicantName: 'a57cgMwpX6EsMca',
  amount: 6391,
  status: 'Pending',
  date: ISODate("2021-11-11T15:51:21.115Z")
}

使用 mongo shell，我运行查询 db.test.find({}).toArray() 以返回所有记录。它不会在 1 分钟内完成。我很惊讶它花了这么长时间。是因为我使用的资源少还是正常。使用 db.test.find({}).explain("executionStats") 运行解释命令以查看详细信息。

{
  queryPlanner: {
    plannerVersion: 1,
    namespace: 'policymatrix_dev.indextest',
    indexFilterSet: false,
    parsedQuery: {},
    winningPlan: { stage: 'COLLSCAN', direction: 'forward' },
    rejectedPlans: []
  },
  executionStats: {
    executionSuccess: true,
    nReturned: 101330,
    executionTimeMillis: 26,
    totalKeysExamined: 0,
    totalDocsExamined: 101330,
    executionStages: {
      stage: 'COLLSCAN',
      nReturned: 101330,
      executionTimeMillisEstimate: 2,
      works: 101332,
      advanced: 101330,
      needTime: 1,
      needYield: 0,
      saveState: 101,
      restoreState: 101,
      isEOF: 1,
      direction: 'forward',
      docsExamined: 101330
    }
  },
  serverInfo: {
    host: '',
    port: 27017,
    version: '4.4.10',
    gitVersion: ''
  },
  ok: 1,
  '$clusterTime': {
    clusterTime: Timestamp({ t: 1636723868, i: 1 }),
    signature: {
      hash: 
      keyId: Long("6968661901790150660")
    }
  },
  operationTime: Timestamp({ t: 1636723868, i: 1 })
}

从结果中，我可以看到它给出的 executionTimeMillis 等于 26，这是一个非常小的值。现在我很困惑为什么统计数据的实际查询执行时间和 executionTimeMillis 存在差异。它们是相同的还是不同的。

要添加更多内容，我在 AWS lambda 函数中运行相同的查询。它在 5314 毫秒内完成。这真是令人困惑。

module.exports.handler = async() => {
    try {
        const db = await connectDB("database");

        const start = new Date();
        const response = await test.find({});
        const end = new Date();

        console.log("time required", end - start)  // returns 5314
        console.log(response.length)   // returns 101330

        return {success: true}
    }

【问题讨论】：

标签： mongodb mongodb-query

【解决方案1】：

当您运行db.test.find({}).explain("executionStats") 时，您会返回一个文档。执行时间将包括从磁盘/缓存中获取所花费的时间，但这些文档实际上从未离开服务器。

当您运行db.test.find({}).toArray() 时，您看不到幕后发生的许多事情。

该请求的结构类似于：

驱动程序向服务器发送“查找”请求
mongod 获取全局、数据库和集合锁
mongod 创建一个新的游标来检索文档
当文档从存储引擎返回时，mongod 会构建一个响应对象
当响应对象达到 BSON 对象大小限制 16MB 时，mongod 释放锁并将文档发送给驱动程序
驱动程序接收包含多个文档的响应对象
驱动程序迭代那些返回的文档，将每个文档推送到一个数组中
当响应对象用完时，向服务器发送 getMore 请求
mongod 重新获取锁并恢复光标
重复步骤 4-9，直到光标用完
将最终数组返回给调用进程

如果您有 100k 个文档，平均大小约为 1k，则至少需要 6 次往返。

解释报告的时间将包括步骤 2,3 和 4。如果在解释和实际运行之间缓存、内存、磁盘或 CPU 利用率有任何变化，这些步骤将不会花费相同数量的时间。

实际执行还会在步骤 5、6、7 和 8 中暂停服务器端执行，因此如果网络或客户端阵列处理不是即时的（即在现实世界中），则真正的执行需要更长的时间。

如果您想查看详细信息，可以查看客户端和/或服务器上的网络数据包，以准确了解每个批次的请求和完成时间。

您还可以调整探查器设置，例如 slowms，以便获得每个批次的日志条目，其中将详细说明使用的锁，以及从磁盘读取的时间。

【讨论】：

这是有道理的。但是从 mongosh 和应用程序运行之间的区别呢？我在 aws lambda 函数中使用了 mongodb nodejs 驱动程序。它给了我 5 秒。

【解决方案2】：

MongoDB 使用 LRU（Least Recent First）算法从内存中丢弃最近的数据，尤其是当您的资源较少时。所以似乎发生的情况是数据位于存储中并且很长时间没有使用它需要一些时间让VM将它加载到内存中并处理它，特别是当你不使用索引时，所以你运行查询并且它处理数据的时间 > 1 分钟，但是当您之后立即运行解释（“执行统计”）时，数据已经在内存中，并且估计需要更少的时间来处理它。如果您重新启动服务或刷新缓存并在实际查询之前执行说明（“executionStats”），它将显示> 1分钟时间（这里取决于后端存储利用率）

此外，M10 和 M20 集群层支持开发环境和低流量应用程序，它们不适用于生产和高性能活动。

【讨论】：