Solr 不规则地具有 QTime > 50000ms答案

【问题标题】：Solr irregularly having QTime > 50000msSolr 不规则地具有 QTime > 50000ms
【发布时间】：2014-07-07 08:00:54
【问题描述】：

我有一个正在开发的 solr-4.8.1 安装。我有一个脚本，它每分钟运行一次查询 id:* 并提取 QTime 和 numFound。结果如下所示：

2014-07-07:09:30:12 QTime=10 numFound="6095776"
2014-07-07:09:32:02 QTime=50022 numFound="6095776"
2014-07-07:09:33:02 QTime=30 numFound="6095776"
2014-07-07:09:34:02 QTime=19 numFound="6095776"
2014-07-07:09:35:02 QTime=10 numFound="6095776"
2014-07-07:09:36:52 QTime=50029 numFound="6095776"
2014-07-07:09:37:52 QTime=26 numFound="6095776"
2014-07-07:09:38:52 QTime=12 numFound="6095776"
2014-07-07:09:39:52 QTime=11 numFound="6095776"
2014-07-07:09:40:52 QTime=12 numFound="6095776"

如您所见，QTime 有时会大于 50 秒。

进一步观察：

首先我认为它可能与 5 分钟的自动提交间隔相关，但是长 QTimes 之间的时间是不规则的，不是每 5 分钟一次。此外，我没有喂任何东西。
除了每分钟查询一次（或者更确切地说，查询之间有一分钟的增量）之外，机器什么也不做。没有查询负载。
当我们索引的文档少得多时，这种行为就已经开始了。

有什么想法可以去哪里看吗？

编辑：

我仔细查看了日志，发现了奇怪的东西。所有 10 个核心（都在同一台机器上），报告 QTime 为 0 或 1，但其中一个在其他 9 个之后 50 秒记录此时间。（为简洁起见，日志行删减）

10:53:55.452 [core000] params={NOW=1404723235442&shard.url=http://x.x.x.x/solr/core000/&df=content&fl=id,score&start=0&q=id:*&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=0} hits=610796 status=0 QTime=1 
10:53:55.452 [core005] params={NOW=1404723235442&shard.url=http://x.x.x.x/solr/core005/&df=content&fl=id,score&start=0&q=id:*&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=0} hits=609562 status=0 QTime=0 
10:53:55.453 [core002] params={NOW=1404723235442&shard.url=http://x.x.x.x/solr/core002/&df=content&fl=id,score&start=0&q=id:*&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=0} hits=610392 status=0 QTime=1 
10:53:55.453 [core004] params={NOW=1404723235442&shard.url=http://x.x.x.x/solr/core004/&df=content&fl=id,score&start=0&q=id:*&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=0} hits=609186 status=0 QTime=0 
10:53:55.452 [core001] params={NOW=1404723235442&shard.url=http://x.x.x.x/solr/core001/&df=content&fl=id,score&start=0&q=id:*&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=0} hits=608294 status=0 QTime=0 
10:53:55.454 [core003] params={NOW=1404723235442&shard.url=http://x.x.x.x/solr/core003/&df=content&fl=id,score&start=0&q=id:*&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=0} hits=612155 status=0 QTime=1 
10:53:55.455 [core006] params={NOW=1404723235442&shard.url=http://x.x.x.x/solr/core006/&df=content&fl=id,score&start=0&q=id:*&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=0} hits=608606 status=0 QTime=1 
10:53:55.456 [core009] params={NOW=1404723235442&shard.url=http://x.x.x.x/solr/core009/&df=content&fl=id,score&start=0&q=id:*&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=0} hits=608956 status=0 QTime=1 
10:53:55.458 [core008] params={NOW=1404723235442&shard.url=http://x.x.x.x/solr/core008/&df=content&fl=id,score&start=0&q=id:*&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=0} hits=608847 status=0 QTime=1 
10:54:45.469 [core007] params={NOW=1404723235442&shard.url=http://x.x.x.x/solr/core007/&df=content&fl=id,score&start=0&q=id:*&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=0} hits=608982 status=0 QTime=1 
10:54:45.470 [core000] params={start=0&q=id:*&wt=xml&rows=0} hits=6095776 status=0 QTime=50028

而且它似乎总是正好是 50 秒（加上一些最小的开销），好像涉及到一些超时，正好是 50 秒。这使得很难相信它是垃圾收集器（正如在一个答案中提出的，但我仍然会照顾它），特别是因为它独立于索引内容发生。

编辑：我似乎找到了一个完全疯狂的伪解决方案：试图弄清楚发生了什么我将 strace 附加到 solr-process。此后 50 年代的挂起不再出现。

【问题讨论】：

标签： solr

【解决方案1】：

查询时间的大幅峰值通常源于 Solr 的容器 VM 中的 GC 暂停，或者（更罕见的）迫在眉睫的硬件故障（从磁盘读取失败）。后者应在您的系统日志中注明。

然而，前者是一个广泛的问题，可用内存量、专用于 Solr 的内存、负载等都是影响因素。一个好的起点是 wiki 上的Solr GC Pause Problems。该页面的原作者也有a guide for his own settings，尽管您的结果会因查询配置文件和可用内存而异。您可以要求 VM 将 GC 问题记录到文件中，其中会显示 GC 的类型及其运行的总时间。如果您将任何广泛的 GC 与您看到查询时间延迟的时间相关联，它可能会提示 GC 是否确实是一个问题。

【讨论】：