QTime >500的Solr不规则性

Question

我有一个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秒。

进一步意见：

1. 首先，我认为这可能与5分钟的自动提交间隔有关，但长QTimes之间的时间是不规则的，而不是每5分钟一次。而且，我什么也不吃。
2. 除了每分钟一次的查询(或者更确切地说，在查询之间的增量为1分钟)之外，机器绝对什么也不做。没有查询负载。
3. 当我们的文档索引少得多时，行为就已经开始了。

知道去哪找吗？

编辑：

我仔细观察了一下日志，发现了一些奇怪的东西。所有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进程上是怎么回事。从那时起，50年代的绞刑就不再出现了。

Answer 1

查询时间的大峰值通常来自容器VM中用于Solr的GC暂停，或者(更少)即将发生的硬件故障(从磁盘读取失败)。后者应在您的syslog中指明。

然而，前者是一个宽泛的问题，在这些问题中，可用的内存量、专用于Solr的内存、load等都是促成因素。一个很好的起点是wiki上的Solr GC暂停问题。该页面的原始作者也有他自己的设置指南，但您的结果将因查询配置文件和可用内存的不同而有所不同。您可以要求VM将GC问题记录到文件中，在文件中显示GC的类型和运行的总时间。如果将任何广泛的GC与查询时的延迟联系起来，它可能会提示GC实际上是一个问题。