ElasticStack系列之十五 & query cache 引起性能問題思考
問題描述
一個線上集群，執行的 Query DSL 都是一樣的，只是參數不同。統計數據顯示 98% ~ 99% 的查詢相應速度都很快，只需要 4 ~ 6ms，但是有 1% 左右的查詢響應時間在 100ms ~ 200ms 之間。集群硬件配置較高，使用的是 SSD 硬盤，系統可用內存遠高於索引所使用內存總和的 2 倍，並且線上已經運行有一段時間了，數據也不存在是否已經預熱的問題。
診斷過程
首先，通過監控系統排出集群所有關鍵數據，未發現任何可能引起查詢耗時高的性能瓶頸問題。因此初步懷疑就是有查詢本身比較慢的原因。從日誌系統裏拿到記錄的一個耗時 150ms 的查詢(這裏只把關鍵內容粘貼出來，隱掉了非關鍵部分)：
POST /xxxindex/xxxdb/_search?routing=Mxxxxxxx { "from": 0, "size": 100, "query": { "bool": { "filter": [ { "bool": { "must": [ { "bool": { "must": [ { "bool": { "should": [ { "match_phrase": { "ord_orders_uid": { "query": "Mxxxxxxx", "slop": 0, "boost": 1 } } } ], "disable_coord": false, "adjust_pure_negative": true, "boost": 1 } }, { "range": { "ord_orders_orderdate": { "from": "1405032032", "to": "1504014193", "include_lower": true, "include_upper": true, "boost": 1 } } }, { "term": { "ord_orders_ispackageorder": { "value": 0, "boost": 1 } } }, { "bool": { "must_not": [ { "exists": { "field": "ord_hideorder_orderid", "boost": 1 } } ], "disable_coord": false, "adjust_pure_negative": true, "boost": 1 } } ], "disable_coord": false, "adjust_pure_negative": true, "boost": 1 } } ], "disable_coord": false, "adjust_pure_negative": true, "boost": 1 } } ], "disable_coord": false, "adjust_pure_negative": true, "boost": 1 } } }
拿到查詢後，自己手動執行了一下，0hits 共耗時 1ms，應該是命中了 query cache 所以才這麽快。
於是使用 clear api 清掉了 query cache，然後再執行幾次，有以下發現歸納如下：
1. 前兩次查詢耗時 36ms 左右，這是因為沒有 cache 需要訪問倒排索引，耗時是符合預期的。之所以兩次同樣耗時，是因為索引有一個副本，兩次查詢分別落在了主分片和副分片上導致。
2. 接下來兩次查詢耗時 150ms 左右，這裏此時是一頭霧水留作思考？
3. 之後不管再怎麽查詢，耗時全部都是在 1~5ms，這是因為又開始命中 cache 了。
至此，大致明白日誌中記錄的高耗時是 步驟2 產生的。那麽到底是什麽操作會導致耗時這麽久呢？根據以往的經驗，我判斷主要是用於為 range filter 生成緩存，也就是生成文檔列表的 bitmap，然後存放到 query cache 中。
我使用的是 ElasticSearch5.5.1 版本，而在 ElasticSearch5.1.1 版本開始，去掉了對 term filter 的 cache，理由是 term filter 已經足夠快了，緩存 term filter 往往得不嘗試反而會白白浪費掉內存空間。那麽我就將註意力集中到了查詢裏唯一的 range filter 上。
單獨執行了一下這個 range filter，match 到的文檔是千萬量級的，為何這個 range filter 會 hit 到這麽多的文檔，通過了解得知，用戶主要就是查詢從當前時間開始至過去 1 年的數據，類似於做一個 [now - 1y TO now] 這樣的過濾。至此初步得出結論，因為這個 range filter 匹配到的文檔樹太多了，在 query cache 裏為這個 filter 構建 bitmap 耗時會有些高，應該就是它帶來了那額外的 100 多毫秒。
但是還有一個待解釋的問題，這種高耗時查詢比例為何這麽高？
再仔細想想也是能夠想明白的：
因為這個集群的搜索並發量還是挺高的，300 ~ 400/s 的樣子，加上時間字段的精度是秒，所以，在某一秒剛開始的時候，前兩次查詢因為沒有 cache，耗時可能在 36ms 左右，之後會有 2 次查詢因為需要緩沖 range filter，耗時會增加到 150 ~ 200ms 的樣子，之後這 1s 裏剩余的查詢都會命中 cache，全部是 幾 ms，直到下一秒開始，周而復始。因為每秒鐘都會產生 2 個這樣需要構建緩存的查詢，耗時較高，對比每秒幾百詞的查詢量，換算成百分比就有點高了。
問題修復
對於大量含有 [now - xxx TO now] 這樣的 range 查詢，實際上官方有對應的加速技巧介紹：Search rounded dates 也就是說，將查詢時間的上下限 round 到整分鐘 或者 整小時，讓 range filter 可以換成的更久，避免出現這種過於頻繁重建 cache 的情況。
{
"range": {
"my_date": {
"gte": "now-1y/h",
"lte": "now-1y/h"
}
}
}
在原始 query 裏，將 range filter 寫成以上形式，手動測試驗證是可行的。range filter 有效期延長到 1小時，從而每個小時裏，只需要為 range filter 重建 2次 cache，至此問題得以解決。
總結
1. cache 並非建的越多越好，因為 cache 的生成 和 銷毀 會帶來額外的開銷，特別是結果集非常大的 filter，緩存的代價相對查詢本身可能非常高。
2. ElasticSearch5.1.1 開始取消了 terms filter cache，因為 terms filter 執行非常快，取消緩存多數情況下反而可以提高性能。
3. 大量用到 [now - xxx TO now] 這樣的 range filter 的時候，可以借助 round date 技巧，提高 cache 的有效期，減輕頻繁重建 cache 帶來的性能問題。
ElasticStack系列之十五 & query cache 引起性能問題思考