Es调优的过程

码匠搬砖师

于 2023-09-12 21:44:18 发布

阅读量222

点赞数

文章标签： elasticsearch 大数据搜索引擎

本文链接：https://blog.csdn.net/weixin_45481857/article/details/132841319

版权

使用了新的es集群(elasticsearch7.3.2)。发现在每天早上9点-10点之间，会有偶发的超时报警(平均响应延时>1s)。

每天不定时告警。

当时的es集群读写状况大概是这个样子：

二问题分析

1.硬件资源分析

数据在每天的8点半——10点之间(时间不定)会有全量刷数据的行为，和发生超时的时间段可以吻合上，所以初步怀疑大量写数据的时候会影响搜索，拖慢搜索请求。

回看我们的集群硬件资源配置，3个节点(2C 8G)，并且Elasticsearch节点所在的机器并不是我们独占的。基于以往经验，这个硬件配置和部署方式是对搜索用es集群的不尊重，所以我们初步的想法是先对选品es集群的硬件进行升级，升级后的硬件配置，3个节点(8C 32G 非独占机器资源)。

升级后第二天我们还是在这个时间段内看到慢请求，虽然有一点缓解，但是仍然说明这个时间段内的慢请求本质上并不是受限于硬件资源。

2.慢日志分析

硬件升级并没有解决根本上的问题，详细观察搜索服务日志发现，的确在这个时间段内，存在esTook > 800ms的请求，但是这些请求我们手动再次访问，esTook只有20ms左右，说明还是当时的集群出现了某种不知名的问题。所以我们的思路是排查es机器上的慢查询日志，看这些请求到底是在当时慢在了query阶段还是fetch阶段，然后针对性的分析调优。

目前我们选品索引的慢日志设定是 query 和 fetch 均是超过1s才会打印慢日志，所以在机器上我们并没有看到有请求慢日志打印出来。所以首先要调整慢日志打印阈值，将其调整为200ms，第二天再次观察。

第二天在平均延迟告警的时候，我们欣喜地立马去机器上查看慢日志状况，但是慢日志还是空的，竟然还是空的(What?)。到这个时候心态就有点小崩了，但是也得到了两点结论：

1⃣️ 可能我们参数配置有问题，导致满查询日志没有打印出来。

2⃣️ 可能这个查询确实不慢，还有其他我们没有关注到的问题。

3.GC分析

试想，如果这个查询很快，那是否有其他因素导致es中处理该请求耗时过多呢？

我们知道es是一个java程序，JVM 的 GC 会导致 Stop The World 现象，GC时候节点无法处理任何逻辑。而且这个时候我们有大量写数据的行为，GC 的压力可能会比平时要高。由于GC也是偶发的，那这个现象和我们观察到的偶发的esTook非常高的情况相当吻合。

赶紧查看es日志，这个时间段内的日志大致都类似这样：

2021-05-26T10:17:49.625+0800: 60427.987: Total time for which application threads were stopped: 0.0003486 seconds, Stopping threads took: 0.0000714 seconds
2021-05-26T10:30:39.681+0800: 61198.043: Total time for which application threads were stopped: 0.0005775 seconds, Stopping threads took: 0.0002432 seconds
2021-05-26T10:30:40.681+0800: 61199.044: Total time for which application threads were stopped: 0.0004182 seconds, Stopping threads took: 0.0001280 seconds
2021-05-26T10:31:54.898+0800: 61273.261: Total time for which application threads were stopped: 0.0005835 seconds, Stopping threads took: 0.0002103 seconds
2021-05-26T10:31:55.899+0800: 61274.261: Total time for which application threads were stopped: 0.0006260 seconds, Stopping threads took: 0.0002868 seconds
2021-05-26T10:31:55.995+0800: 61274.358: Total time for which application threads were stopped: 0.0004766 seconds, Stopping threads took: 0.0001818 seconds
2021-05-26T10:31:55.996+0800: 61274.358: Total time for which application threads were stopped: 0.0002543 seconds, Stopping threads took: 0.0000488 seconds
2021-05-26T10:31:56.997+0800: 61275.359: Total time for which application threads were stopped: 0.0007670 seconds, Stopping threads took: 0.0002863 seconds
2021-05-26T10:31:57.997+0800: 61276.359: Total time for which application threads were stopped: 0.0004201 seconds, Stopping threads took: 0.0001545 seconds
2021-05-26T10:32:12.061+0800: 61290.423: Total time for which application threads were stopped: 0.0005901 seconds, Stopping threads took: 0.0002594 seconds
2021-05-26T10:32:12.061+0800: 61290.424: Total time for which application threads were stopped: 0.0004022 seconds, Stopping threads took: 0.0001765 seconds
2021-05-26T10:32:14.395+0800: 61292.757: Total time for which application threads were stopped: 0.0005574 seconds, Stopping threads took: 0.0002075 seconds
2021-05-26T10:32:14.396+0800: 61292.758: Total time for which application threads were stopped: 0.0004211 seconds, Stopping threads took: 0.0001827 seconds
2021-05-26T10:32:17.969+0800: 61296.332: Total time for which application threads were stopped: 0.0006126 seconds, Stopping threads took: 0.0002700 seconds
2021-05-26T10:32:17.970+0800: 61296.332: Total time for which application threads were stopped: 0.0003248 seconds, Stopping threads took: 0.0001184 seconds
2021-05-26T10:32:21.404+0800: 61299.766: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 603979776 bytes, new threshold 15 (max 15)
- age   1:     843856 bytes,     843856 total
- age   2:      12752 bytes,     856608 total
- age   3:       3920 bytes,     860528 total
- age   4:       5768 bytes,     866296 total
- age   5:       3216 bytes,     869512 total
- age   6:       1696 bytes,     871208 total
- age   7:       1272 bytes,     872480 total
- age   8:       5752 bytes,     878232 total
- age   9:       3048 bytes,     881280 total
- age  10:     150072 bytes,    1031352 total
- age  11:     973952 bytes,    2005304 total
- age  12:       2056 bytes,    2007360 total
- age  13:      14160 bytes,    2021520 total
- age  14:      11176 bytes,    2032696 total
- age  15:     194872 bytes,    2227568 total
, 0.0545307 secs]
   [Parallel Time: 48.7 ms, GC Workers: 13]
      [GC Worker Start (ms): Min: 61299766.3, Avg: 61299766.5, Max: 61299766.7, Diff: 0.4]
      [Ext Root Scanning (ms): Min: 0.7, Avg: 3.1, Max: 7.9, Diff: 7.2, Sum: 40.2]
      [Update RS (ms): Min: 0.0, Avg: 0.6, Max: 1.1, Diff: 1.0, Sum: 7.8]
         [Processed Buffers: Min: 0, Avg: 11.2, Max: 30, Diff: 30, Sum: 145]
      [Scan RS (ms): Min: 0.0, Avg: 0.2, Max: 0.5, Diff: 0.4, Sum: 2.7]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.6, Diff: 0.6, Sum: 0.8]
      [Object Copy (ms): Min: 35.8, Avg: 40.3, Max: 45.8, Diff: 10.0, Sum: 523.4]
      [Termination (ms): Min: 0.0, Avg: 3.8, Max: 4.1, Diff: 4.1, Sum: 48.8]
         [Termination Attempts: Min: 1, Avg: 44.4, Max: 68, Diff: 67, Sum: 577]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.6]
      [GC Worker Total (ms): Min: 47.8, Avg: 48.0, Max: 48.3, Diff: 0.5, Sum: 624.3]
      [GC Worker End (ms): Min: 61299814.5, Avg: 61299814.5, Max: 61299814.6, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 1.7 ms]
   [Other: 4.2 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.1 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.6 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.2 ms]
      [Free CSet: 1.7 ms]
   [Eden: 9212.0M(9212.0M)->0.0B(8992.0M) Survivors: 4096.0K->224.0M Heap: 11.2G(15.0G)->2023.2M(15.0G)]
 [Times: user=0.56 sys=0.00, real=0.06 secs]

观察完 GC 日志后，整个人都不好了，GC 比较正常啊，没有发现有 Full GC，并且young gc也没有发现有特别高的延时，Stop The World 的时间也很短。看来慢查询并不是 GC 的行为导致的。

4.集群和机器参数分析

到这个地方，已经并没有什么更好的排查思路了，只能寄希望于从linux机器参数、es集群配置参数、es索引分片分布、es使用上。排查寻找一些端倪了。

大致摸排了一下，参数上存在的比较明显的问题如下：

1⃣️ swap没有关闭(es性能的坟墓)

/etc/sysctl.conf 下 vm.swappiness没有配置，默认应该是60，需要配置为0/1
elasticsearch.yml下 bootstrap.memory_lock: false 没有锁定物理内存，应该配置为true

目前在这些配置下，一旦机器预留内存不足，就会与swap交换，极大拖慢es性能。

2⃣️ index buffer感觉设置的有些大

indices.memory.index_buffer_size: 30% ,默认是10%

index_buffer_size过大虽然在理论上能够提升写入速度，但是在某些情况下，也会造成refresh压力增大。

3⃣️ 选品索引在设置为5分片1副本，在3个节点的情况下，必然无法均匀分配，这在搜索量起来后很容易产生压力节点，而且node1 全是副本，node2上全是主分片。这样node2在写入时会承载更多的压力。

建议索引的主分片个数和节点个数保持一致，以后扩容的时候扩容副本就好，扩缩容后如果实在无法均匀分配，则需要重建索引，调整主分片个数。

4⃣️ 在使用上，为了保证读相同的读请求多次查询不会发生不一致的情况，我们采用了preference(hash)指定了请求应该去哪个分片查询，这样会使得elasticsearch7.x版本集群默认打开的自适应分片路由规则失效(实际观测，这个规则能很大程度上规避压力节点的出现)，很可能在某段时间出现某些分片过忙过闲状态，同一时间段查询都被打在相同节点上有可能出现查询抖动。

通过观察上述情况：

针对1⃣️，虽然配置不规范，可能造成隐患，但是目前选品的量(数据量和请求量)并不高，查看报警时候的机器内存，还有大量的空闲机器内存可用(如下图)，不会交换到swap上，看来不太会是这个因素。由于修改该配置需要修改linux配置和elasticsearch静态配置重启集群(集群非独占，可能造成其他es集群的节点问题)，操作风险太大，所以在这个因素不是瓶颈之前都不会考虑动手。

针对2⃣️，在index buffer 区域写满之后，由于buffer区域扩大到了30%，refresh耗时就会考验磁盘的性能了。相对于写，我们更重要的是要保障读的稳定性和低延迟性，可以适当缩小这个区域，针对目前的写入量使用默认配置(10%)就ok，但该配置也是elasticsearch.yml中的静态参数，修改需要重启集群，并且还没有足够的证据佐证是查询耗时久是该配置的影响，暂时先不考虑动手。

针对3⃣️，es的写入请求是先写主分片后写副本的，目前选品索引的分片分配有些混乱，node2上承担了主分片太多的压力，如果在某一时间段，读写都打在该节点的分片上，是有可能造成抖动的。所以我们预计对主副本的位置进行调整，将node2上的一个主分片和node1上的一个副本调换位置。

针对4⃣️，目前并没有太好的办法来对这个做调整，我们搜索请求需要保证同样请求访问多次查询到的结果排序是一致的。从业务上需要通过preference(hash)请求，自适应分片路由的失效暂时没有太好的办法解决。

综上分析，我们决定对选品索引的主副分片的位置做移动，移动命令如下：

POST /_cluster/reroute
{
    "commands" : [
        {
            "move" : {
                "index" : "xuanpin_items_20210423", 
              	"shard" : 2,
                "from_node" : "node2", 
              	"to_node" : "node1"
            }
        }
    ]
}

移动后各分片位置如下：

但是，但是，在第二天我们又收到了延时的报警，本次调整并没有解决根本问题，至此心态已经崩了。

5.ES特性分析

到了这一步，其实已经开始有点束手无策了，虽说上述分析过程中对linux机器内核参数调整以及es集群静态配置文件的调整可能能使我们的集群稳定性更高。但就目前的请求量来看，这不是根本的影响因素。那会不会是es7.x以上的版本和es7.x以下的版本有某些不同，会不会是我们使用姿势上出现了问题？带着这个疑问，我去社区和es 官方文档上寻找答案。

仔细阅读官方文档，发现了在es7.x版本对 refresh_interval的介绍：

index.refresh_interval

How often to perform a refresh operation, which makes recent changes to the index visible to search. Defaults to 1s. Can be set to -1 to disable refresh. If this setting is not explicitly set, shards that haven’t seen search traffic for at least index.search.idle.after seconds will not receive background refreshes until they receive a search request. Searches that hit an idle shard where a refresh is pending will wait for the next background refresh (within 1s). This behavior aims to automatically optimize bulk indexing in the default case when no searches are performed. In order to opt out of this behavior an explicit value of 1s should set as the refresh interval.

根据官方文档的说法，es默认 1s refresh 一次，但是如果分片在 index.search.idle.after 的时间内没有收到search请求，则停止刷新，需要显示指定 "refresh_interval" 才可以退出这种状态。那 index.search.idle.after 是什么意思呢？官方文档这样解释：

index.search.idle.after

How long a shard can not receive a search or get request until it’s considered search idle. (default is 30s)

这个参数是es7.x才有的，默认值为30s，意思是当一个分片30s没有搜索请求的时候，那这个分片就会进入搜索空闲状态，不会执行refresh，在下一个请求进来的时候，会先调用执行refresh，再进行搜索。

同时在es社区也找到了类似的问题：Slow first request on an index after a short amount of time - Elasticsearch - Discuss the Elastic Stack

看到这，切合我们遇到的实际问题，感觉问题原因逐渐明朗了起来。分析如下：

1.选品的流量很低，在大部分时间都是没有什么查询的，在 index.search.idle.after 没有调整的情况下，分片很容易进入 search idle状态；

2.大量写的时候，分片进入search idle状态下，index buffer区域不断增大，导致下一次请求打到该分片上，执行refresh耗时很长，导致整体响应变慢；

3.indices.memory.index_buffer_size: 30% ,默认是10% 使得分片的refresh的压力更大；

4.自适应副本分片的失效，在该情况下，更不容易使得所有的分片预热。

根据问题分析，相应的解决方法可能如下：

1.增大 index.search.idle.after 的值，延缓分片进入search idle 状态的时间。但是选品的流量太低了，增大到多少是个头。

2.显式指定 "refresh_interval" : "1s"，使分片不会进入search idle状态。执行命令如下：

PUT xuanpin_items_20210423/_settings
{
   "index" : {
        "refresh_interval" : "1s"
    }
}

执行后，持续观察了两天，果然消停了，在全量写入的情况下，请求没有高耗时的情况了。

三调优结果和总结

1.调优是一个持续的过程，很难一蹴而就。在本次调优排查，在解决最终问题的过程中，我们也发现了很多之后可调整也是有必要调整的问题；

2.对es的了解要深入到某一个版本中，es版本高速迭代，需要了解我们所使用的版本的特性参数；

3.es的took值，并不是es 内部真正查询(query & fetch)的耗时，而是请求从进入es到查询完成的耗时，比如选品的高took值，是请求等待refresh的时间 + query + fetch 的耗时，这也是为什么打印不出慢日志的原因。