为什么 MongoDB 在负载测试期间没有响应？答案

【问题标题】：Why is MongoDB unresponsive during a load test?为什么 MongoDB 在负载测试期间没有响应？
【发布时间】：2013-09-10 22:20:54
【问题描述】：

我的问题是 MongoDB 在生产中变得无响应并拒绝连接。

在测试中，我能够通过向我的应用发送大量请求来始终如一地重现“锁定”。

这是 mongostat 的示例输出：

     0      0      0      0       0       1       0   1.3g   1.8g   177m      0        0          0       0|0     0|0    62b     1k    18   19:40:11
     0      0      0      0       0       1       0   1.3g   1.8g   177m      0        0          0       0|0     0|0    62b     1k    18   19:40:12
--------------LOAD TEST BEGINS-----------------------   
     1     56      0      0       1      58       0   1.3g  1.81g   177m      0        0          0       0|0     0|0    10k   302k    18   19:40:13
    10    116      0      0       2     127       0   1.3g  1.81g   177m      0        0          0       0|0     1|0    32k   263k    19   19:40:14
insert  query update delete getmore command flushes mapped  vsize    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn       time
   206    431      0      0       2     638       0   1.3g  1.82g   177m      0      1.1          0       0|0     0|0   206k   339k    22   19:40:15
   331    649      0      0       2     983       0   1.3g  1.81g   177m      0        1          0       0|0     0|0   317k   521k    21   19:40:16
   367    723      0      0      10    1090       0   1.3g  1.81g   177m      0      0.9          0       0|1     1|1   297k     1m    20   19:40:17
   500    961      0      0      11    1461       0   1.3g  1.81g   177m      0      1.2          0       0|0     0|0   390k     1m    19   19:40:18
   543   1073      0      0      10    1618       0   1.3g  1.82g   177m      0      1.2          0       0|0     2|0   433k     1m    21   19:40:19
   461    909      0      0      11    1370       0   1.3g  1.81g   177m      0      1.1          0       0|0     2|0   365k     1m    20   19:40:20
   347    685      0      0       6    1033       0   1.3g  1.81g   177m      0      0.8          0       0|0     1|0   411k   962k    21   19:40:21
   482    938      0      0       9    1421       0   1.3g  1.81g   177m      0      1.1          0       0|0     0|0   492k     1m    20   19:40:22
   444    877      0      0      10    1322       0   1.3g  1.81g   177m      0      1.1          0       0|0     0|1   479k     1m    22   19:40:23
   528   1019      0      0       9    1549       0   1.3g  1.81g   177m      0      1.2          0       0|0     0|0   446k     1m    21   19:40:24
insert  query update delete getmore command flushes mapped  vsize    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn       time
   520   1033      0      0      10    1554       0   1.3g  1.81g   177m      0      1.2          0       0|0     1|0   418k     1m    22   19:40:25
   448    878      0      0      10    1326       0   1.3g  1.81g   177m      0      1.2          0       0|0     1|0   349k     1m    22   19:40:26
   503    979      0      0       8    1483       0   1.3g  1.82g   177m      0      1.3          0       0|0     1|0   397k     1m    21   19:40:27
   379    743      0      0      10    1123       0   1.3g  1.81g   177m      0        1          0       0|0     0|0   315k     1m    22   19:40:28
   456    896      0      0       7    1354       0   1.3g  1.81g   177m      0      1.1          0       0|0     0|0   436k     1m    22   19:40:29
   371    715      0      0      10    1086       0   1.3g  1.81g   175m      0      0.9          0       0|0     0|0   299k     1m    20   19:40:30
   505    993      0      0       7    1499       0   1.3g  1.81g   175m      0      1.2          0       0|0     2|0   394k     1m    21   19:40:31
   493   1023      0      0      10    1519       0   1.3g  1.82g   175m      0      1.1          0       0|0     1|0   392k     1m    22   19:40:32
   426    868      0      0      11    1295       0   1.3g  1.81g   170m      0        1          0       0|0     1|0   363k     1m    21   19:40:33
   352    772      0      0       7    1125       0   1.3g  1.81g   163m     19      4.4          0       0|1     0|1   368k     1m    22   19:40:34
insert  query update delete getmore command flushes mapped  vsize    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn       time
   330    656      0      0       5     985       0   1.3g  1.81g   159m      4      1.5          0       0|0     0|0   325k   876k    19   19:40:35
   398    817      0      0       8    1218       0   1.3g  1.81g   155m      9      1.3          0       0|0     1|0   372k     1m    21   19:40:36
   464   1015      0      0       8    1479       0   1.3g  1.81g   155m      2      1.2          0       0|0     1|0   381k     1m    21   19:40:37
   457    915      0      0      11    1372       0   1.3g  1.81g   155m      0      1.1          0       0|0     0|0   356k     1m    22   19:40:38
   458    960      0      0       7    1419       0   1.3g  1.83g   155m      0      1.1          0       0|0     0|0   376k     1m    22   19:40:39
   391    760      0      0      11    1153       0   1.3g  1.81g   155m      0        1          0       0|0     1|0   321k     1m    21   19:40:40
   315    639      0      0       5     956       0   1.3g  1.81g   155m      0      0.8          0       0|0     0|0   325k   877k    21   19:40:41
   303    696      0      0       7     998       0   1.3g  1.81g   155m      0      0.8          0       0|0     0|0   279k     1m    21   19:40:42
   388    772      0      0       8    1163       0   1.3g  1.81g   155m      0        1          0       0|0     0|0   308k     1m    20   19:40:43
   273    623      0      0       7     895       0   1.3g  1.81g   155m      0      0.7          0       0|0     2|0   232k     1m    20   19:40:44
insert  query update delete getmore command flushes mapped  vsize    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn       time
   397    796      0      0       7    1194       0   1.3g  1.81g   155m      0      0.9          0       0|0     0|0   311k     1m    19   19:40:45
   347    754      0      0       4    1103       0   1.3g  1.81g   155m      0      0.9          0       0|0     0|0   329k   771k    20   19:40:46
   336    700      0      0       8    1042       0   1.3g  1.82g   160m     20      0.8          0       2|2     3|2   370k     1m    23   19:40:47
   272    525      0      0       5     805       0   1.3g  1.79g   167m    188      0.6          0       0|0     0|0   306k   818k    18   19:40:48
   103    246      0      0       1     350       0   1.3g  1.78g   166m      0      0.4          0       0|0     0|0   136k   234k    15   19:40:49
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:40:50
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:40:51
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:40:52
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:40:53
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:40:54
insert  query update delete getmore command flushes mapped  vsize    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn       time
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:40:55
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:40:56
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:40:57
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:40:58
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:40:59
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:00
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:01
     0      3      0      0       0       4       0   1.3g  1.78g   166m      0        0          0       0|0     0|0   775b     4k    15   19:41:02
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:03
     0      0      0      0       0       1       1   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:04
insert  query update delete getmore command flushes mapped  vsize    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn       time
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:05
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:06
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:07
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:08
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:09
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:10
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:11
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:12
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:13
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:14
insert  query update delete getmore command flushes mapped  vsize    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn       time
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:15
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:16
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:17
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:18
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:19
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:20
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:21
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:22
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:23
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:24
insert  query update delete getmore command flushes mapped  vsize    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn       time
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:25
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:26
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:27
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:28
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:29
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:30
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:31
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:32
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:33
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:34
insert  query update delete getmore command flushes mapped  vsize    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn       time
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:35
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:36
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:37
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:38
     0      0      0      0       0       1       0   1.3g  1.78g   166m      0        0          0       0|0     0|0    62b     1k    15   19:41:39
     0     28      0      0       0      29       0   1.3g  1.78g   166m      0        0          0       0|0     0|0     5k    27k    15   19:41:40
    86    234      0      0       1     322       0   1.3g  1.79g   166m      0      0.2          0       0|0     1|0   145k   217k    17   19:41:41
   216    445      0      0       5     663       0   1.3g  1.79g   167m      0      0.5          0       0|0     0|0   220k   807k    16   19:41:42
   302    612      0      0       6     916       0   1.3g  1.79g   167m      0      0.6          0       0|0     0|0   236k   950k    16   19:41:43
   113    247      0      0       1     362       0   1.3g  1.79g   167m      0      0.2          0       0|0     0|0    95k   192k    17   19:41:44
insert  query update delete getmore command flushes mapped  vsize    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn       time
    38     63      0      0       2     103       0   1.3g  1.79g   167m      0        0          0       0|0     0|0    26k   289k    16   19:41:45
--------------LOAD TEST ENDS----------------------- 
     0      0      0      0       0       2       0   1.3g  1.79g   167m      0        0          0       0|0     0|0   124b     2k    16   19:41:46
     0      0      0      0       0       2       0   1.3g  1.79g   167m      0        0          0       0|0     0|0   124b     2k    16   19:41:47
     0      0      0      0       0       2       0   1.3g  1.79g   167m      0        0          0       0|0     0|0   124b     2k    16   19:41:48
     0      0      0      0       0       2       0   1.3g  1.79g   167m      0        0          0       0|0     0|0   124b     2k    16   19:41:49

如您所见，在负载测试的中间，读取和写入几乎为零。在此期间，我无法通过 mongo 或 mongostat 本地连接到 MongoDB（连接被拒绝）。如您所见，连接数非常低，mongo 的最大连接数为 16000 个。

我能够始终如一地重现这一点。但是，每次“锁定”都是不同的长度。我观察到了 51 秒、20 秒、28 秒。在每种情况下，我仍然通过 mongostat 连接到 mongo（并接收输出），但新连接将被拒绝。

user@myhostname:~# mongostat
couldn't connect to [127.0.0.1] couldn't connect to server 127.0.0.1

可能是什么问题？我正在运行 MongoDB v1.8.2。

顺便说一句，我能够重现一个类似的问题，其中命令不会完全下降，但数量很少并且波动很大。

【问题讨论】：

我对此很好奇，但正如结尾所暗示的，可能更适合@Server Fault
@tymeJV 我是这个应用程序的首席开发人员，我也在寻找可能在 MongoDB 源代码中的解决方案。 TBH，我会为任何来源解决问题。 :-)
Mongo 曾经有一些非常粗粒度的锁——你试过更新版本吗？
@FrederickCheung 我现在正在尝试。将返回结果。我假设如果锁是问题所在，它可能会用 lock% 指标来指示，但您可能对未报告的不同锁（甚至可能是临时死锁）是正确的。
@FrederickCheung 升级到 2.4.6 无效。问题依然存在。

标签： mongodb

【解决方案1】：

已修复：

sudo sysctl net.ipv4.tcp_tw_reuse=1

然后，重启 mongo。

或者，您可以将其添加到 /etc/sysctl.conf（这样它将在重新启动时运行）：

net.ipv4.tcp_tw_reuse=1

然后运行这个来重新加载（无需重新启动）

sudo sysctl -p /etc/sysctl.conf

此“修复”将禁用 TCP 套接字（服务器范围）的时间等待状态。所以，这根本不是解决办法。但是，在 mongo 使用 SO_LINGER 减少它们的 timewait 状态之前，大量的服务器套接字将在 TIME_WAIT 状态中汇集，并且对于新连接仍然不可用。您可以通过以下方式查看 TIME_WAIT 中的连接数：

netstat -an | grep TIME_WAIT | wc -l

这样，我可以看到它在大约 28k TIME_WAIT 连接时失败。使用这个内核标志：

sysctl net.ipv4.ip_local_port_range="18000 65535"

服务器在 45k 连接时失败。因此，为了更轻松地重现错误，您可以将范围降低到 200 或较小的值。

所以，这个的结果毕竟是一个编程问题（你可以从最后一个链接看到）：

TCP option SO_LINGER (zero) - when it's required

http://alas.matf.bg.ac.rs/manuals/lspe/snode=105.html

【讨论】：

我在 Mongo 的 JIRA 中创建了一个与此问题相关的错误报告：jira.mongodb.org/browse/SERVER-10710
另外，请注意，当我从 1.8.2 升级到 2.4.6 时，模式发生了变化。在 2.4.6 下，每次负载测试（并且时间更短）的“锁定”次数会增加数倍。

【解决方案2】：

花费大量时间调试类似问题。最后，事实证明我们有太多短暂的联系，每个人都在一次小手术后关闭。但是，这会在 mongo 服务器进程上留下一堆 CLOSE_WAIT 连接，并且与您在问题中描述的症状完全相同。解决方案是重用连接，而不是在每个命令中打开和关闭连接。

【讨论】：