Solr不規則地有QTime> 50000ms

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. 除了每分鐘查詢一次（或者說，查詢之間有一分鐘的增量）之外，機器什麼都不做。沒有查詢負載。
3. 當我們對索引的文檔少得多時，行爲就開始了。

任何想法在哪裏看？

編輯：

我把在日誌定睛一看，發現奇怪的事情。所有10個核心（全部在同一臺機器上），報告的0或1的QTIME，但其他9（削減簡潔loglines）

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秒（加上一些最小的開銷），就好像有一些超時涉及到了，這正好是50秒。這使得很難相信它是垃圾收集器（正如在一個答案中提出的那樣，而我將在之後尋找），特別是因爲它獨立於索引內容而發生。

編輯： 我似乎已經找到了一個完整的瘋狂的僞解決方案：試圖找出發生了什麼我附加strar到solr進程。從那時起，50年代不再出現。

Answer 1

查詢時間內的大型尖峯通常來自Solr的容器VM中的GC暫停，或者（很少發生）即將發生的硬件故障（從磁盤讀取失敗）。後者應該在你的系統日誌中指出。

然而前者是一個廣泛的問題，其中可用的內存量，專用於Solr的內存，加載等等都是影響因素。在wiki上開始的一個好地方是Solr GC Pause Problems。該頁面的原作者也有a guide for his own settings，但您的結果將因查詢配置文件和可用RAM而異。您可以要求VM將GC問題記錄到文件，其中顯示了GC的類型和運行的總時間。如果您將任何廣泛的GC與查詢時間延遲相關聯時，它可能會提示GC是否實際上是一個問題。