用于查找和修改的 MongoDB 队列非常慢答案

【问题标题】：MongoDB queue very SLOW for findandmodify用于查找和修改的 MongoDB 队列非常慢
【发布时间】：2013-11-05 22:31:02
【问题描述】：

我使用 MongoDB 作为队列，使用 PHP-Queue 作为获取数据的方式。这是一个 POC，我在 OSX 机器上运行。我看到 Mongo 的性能非常缓慢，即 findmodify 函数。我在PHP端做了一堆测试，PHP处理只占5%左右的时间。当我用 10,000 条消息填充 Mongo 集合时，它会很快填充，大约 3-5 秒。但是当我清空它时，大约需要 250 秒。这段时间只有大约 10 秒在 php 端。检查 mongod 进程，它从未超过 60MB，但 CPU 在整个时间内峰值超过 90%。我已经对集合进行了索引，下面是消息数据的示例以及索引。

示例消息（这是队列中 10,000 条类似消息之一）：

{
  "_id": ObjectId("526c47d5c5008c1d5cd63ef8"),
  "payload": {
    "0": {
      "EVENT_HEADER_KEY": NumberInt(9094775),
      "event_name": "Account Change",
      "source_name": "Work",
      "event_category_name": "Complex Events",
      "EVENT_TIMESTAMP": "Aug 17 2013 12:00:00:000AM",
      "PARENT_HEADER_KEY": null,
      "year": NumberInt(2013),
      "month": NumberInt(10),
      "Company_Name": "ACME PRODUCTS, INC.",
      "Company_Email": "blabla",
      "Company_Phone": "555-555-5555",
      "First_Name": "Jon",
      "Last_Name": "Doe",
      "ID_NUMBER": "111111111",
      "created_by": "Load Job Name",
      "created_at": "Oct 18 2013 04:07:31:140PM",
      "product_analytical_category": "blabla",
      "_Event_Type": "blabla",
      "CUSTOMER_ID": "111111111"
   }
 },
  "running": false,
  "resetTimestamp": ISODate("2038-01-19T03:14:07.0Z"),
  "earliestGet": ISODate("1970-01-01T00:00:00.0Z"),
  "priority": 0,
  "created": ISODate("2013-10-26T22:53:09.440Z")
}

这个集合的索引，似乎是自动创建的：

{
   "_id": NumberInt(1)
}

查看mongo.log，我可以看到当我清空队列时，每条消息只需要大约1毫秒，大约70条消息，然后opid会改变，然后会有300-900毫秒的延迟它以每条消息约 1 毫秒的相同速度继续使用新的 opid。在 250 秒的处理时间中，这些 opid 更改约占 50-100 秒，因此还有更多工作要做。

摘自 mongo.log：

**Sat Oct 26 15:15:25.189** [conn4] warning: ClientCursor::yield can't unlock b/c of recursive lock ns: test.abe top: { **opid: 20064**, active: true, secs_running: 0, op: "query", ns: "test", query: { findandmodify: "abe", query: { running: false, earliestGet: { $lte: new Date(1382825725143) } }, update: { $set: { resetTimestamp: new Date(1382825785000), running: true } }, fields: { payload: 1 }, sort: { priority: 1, created: 1 } }, client: "127.0.0.1:53045", desc: "conn4", threadId: "0x119024000", connectionId: 4, locks: { ^: "w", ^test: "W" }, waitingForLock: false, numYields: 0, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: { r: 0, w: 3 } } }

**Sat Oct 26 15:15:25.190** [conn4] warning: ClientCursor::yield can't unlock b/c of recursive lock ns: test.abe top: { **opid: 20064**, active: true, secs_running: 0, op: "query", ns: "test", query: { findandmodify: "abe", query: { running: false, earliestGet: { $lte: new Date(1382825725143) } }, update: { $set: { resetTimestamp: new Date(1382825785000), running: true } }, fields: { payload: 1 }, sort: { priority: 1, created: 1 } }, client: "127.0.0.1:53045", desc: "conn4", threadId: "0x119024000", connectionId: 4, locks: { ^: "w", ^test: "W" }, waitingForLock: false, numYields: 0, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: { r: 0, w: 3 } } }

**Sat Oct 26 15:15:25.507** [conn4] warning: ClientCursor::yield can't unlock b/c of recursive lock ns: test.abe top: { **opid: 20141**, active: true, secs_running: 0, op: "query", ns: "test", query: { findandmodify: "abe", query: { running: false, earliestGet: { $lte: new Date(1382825725501) } }, update: { $set: { resetTimestamp: new Date(1382825785000), running: true } }, fields: { payload: 1 }, sort: { priority: 1, created: 1 } }, client: "127.0.0.1:53045", desc: "conn4", threadId: "0x119024000", connectionId: 4, locks: { ^: "w", ^test: "W" }, waitingForLock: false, numYields: 0, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: { r: 0, w: 3 } } }

这在这 10,000 条消息的整个日志中基本相同。会有一个很长的 findandmodify() 序列，每条消息只需要 1 毫秒，然后 opid 发生变化，并且会有一个延迟，可能需要将近一秒钟。我不知道这是否表明任何重要的事情，但我是 Mongo 的新手，我正在努力寻找任何看起来很有希望的模式。

更新：

查询检查字段'running' 是否为假，它还检查earlyGet 字段是否比纪元（即1-1-1970）更新。我为这些字段添加了索引无济于事。由于这些字段对于集合中的所有消息（“假”和 1970 年 1 月 1 日）都是相同的，也许这就是为什么我对它们的索引只会增加查询时间的原因。我不知道我应该怎么做才能让它正常工作。似乎它应该抓取它发现的第一个比 1970 年 1 月 1 日更新的记录，但显然 Mongo 仍然遍历整个集合，这使得查询太慢而无法实用。此外，即使我没有选择标准，我仍然可以获得 202 秒的响应时间 - 更快，但仍然无法接受。我还看到那些“yield can't unlock b/c of recursive lock ns:”消息，我认为这些消息只会在查询未索引的字段时出现。

【问题讨论】：

顺便说一句，yield 无法解锁消息是与此查询效率低下（即不使用索引）这一事实直接相关的虚假日志记录
这些消息出现在慢查询上——通常这意味着没有索引。在 {priority:1,created:1} 上添加索引怎么样 - 因为您的查询不是选择性的，所以您想要优化排序时间 - 这应该会有所帮助。总的来说，虽然看起来真正的问题是 earlyGet 的值相同，但该字段的意义何在？
我认为编码人员想要一个选择标准，它可以在 1970 年之后得到任何东西。我实际上删除了所有查询标准，它确实缩短了清除队列的时间 - 但它仍然是非常慢，我仍然在 mongo.log 文件中看到那些解锁通知。我会尝试您的建议，但似乎由于我目前没有查询条件，因此无论索引如何，它都应该很快，但事实并非如此。
使用索引进行排序对于良好的性能至关重要。如果你删除排序，它会非常快，或者如果你为排序添加索引。

标签： php mongodb queue message-queue

【解决方案1】：

您缺少一个非常关键的索引，该索引将用于findAndModify 命令的查询和排序部分。如果没有该索引，您将强制每个命令扫描整个集合，然后对整个结果集进行排序，这是低效的。现在您说“我已为集合编制索引”，但您只提到了始终存在且无法帮助您的 '_id' 索引。

建议：至少对正在运行的字段和最早获取的字段添加复合索引。索引可能包含排序字段可能会有所帮助，但由于我预计每个查询的匹配文档数量会相对较少，因此内存排序可能不是一个因素。

命令：

db.abe.ensureIndex({running:1, earliestGet:1})

在 cmets 讨论中发现，运行中的 earlyGet 索引根本没有选择性 - 但由于您正在排序以仅获取第一个匹配的文档，因此替代方法是在排序列上添加索引：

命令：

db.abe.ensureIndex({ priority: 1, created: 1 })

【讨论】：

我认为你在正确的轨道上，但我运行了你建议的命令，它实际上将响应时间再减慢了 50-60 秒。我将检查我的数据并确保正确输入了 ensureIndex 字段。
您可能需要扩展索引以包含被排序的字段（因为我不知道有多少文档可以满足查询，所以我无法猜测）但其次，您的 findAndModify 还会更新索引字段，因此它不是完全免费的。最后，如果您没有足够的 RAM，那么如果它只是导致更多的交换，那么索引将无济于事 - 查看系统在负载下的样子可以显示可能的瓶颈所在。
我读到 Mongo 会根据需要分配尽可能多的 RAM？也许那是错误的。但是我在这台机器上有 16GB 的内存，mongod 进程从未超过 100MB 内存。这似乎是 CPU 使用率，我认为您关于索引字段的建议是正确的，但实现可能是错误的。我是否需要等待很长时间才能索引 10,000 行这些数据？根据 mongo CLI，当它有 10,000 行时，这个集合只占用 9MB 的空间。
当您从 mongo shell 运行 ensureIndex 时，当您返回提示时，这意味着索引已完全构建。
另一种查看索引是否存在的方法是运行 db.collectionName.getIndexes()

【解决方案2】：

如果没有更详细的描述，您在修改阶段到底在做什么，很难给出明确的答案。从日志来看，您似乎执行了这样的更新：

db.abc.findAndModify(
    query: { running: false, earliestGet: { $lte: new Date(1382825725143) } },
    update: { $set: { resetTimestamp: new Date(1382825785000), running: true } }
)

并且earliestGet 字段和running 字段上没有索引。由于基数低，在running 上添加索引应该不会产生真正的影响，但在earliestGet 上缺少索引可能是一个真正的问题。

关于warning: ClientCursor::yield can't unlock b/c of recursive lock ns:的留言可以看到这个问题：MongoDB: Geting "Client Cursor::yield can't unlock b/c of recursive lock" warning when use findAndModify in two process instances

【讨论】：

作为复合索引的一部分，“运行”字段会产生很大的不同，只要它是索引中的第一个字段。
@AsyaKamsky 你能详细说明一下吗？我知道如果running 的分布高度偏斜并且对最稀有的群体感兴趣，它可能会有所不同，但我认为否则通过{earliestGet: 1} 仅搜索索引至少可以与使用{running:1, earliestGet:1} 一样快。我已经用简单的随机生成数据集测试了这个假设，看起来这正是发生的事情，但现在是清晨，我没睡多少，还在等咖啡，所以很可能我搞砸了.
earliestGet alone 只会和运行一样快，earliestGet 如果运行只有一个值。
我运行了一个空查询的 explain()，但我仍然看到它扫描了我当时拥有的所有 1000 条消息： db.abe.find().explain() { "cursor" : “BasicCursor”，“isMultiKey”：假，“n”：1000，“nscannedObjects”：1000，“nscanned”：1000，“nscannedObjectsAllPlans”：1000，“nscannedAllPlans”：1000，“scanAndOrder”：假，“indexOnly”： false, "nYields" : 0, "nChunkSkips" : 0, "millis" : 1, "indexBounds" : { }, "server" : "mycomputer.local:27017" } 我猜这是正常行为？或者有什么不对劲。搜索仍在继续。