最近对 Elasticsearch（以下简称 ES）进行了升级，升级之后把部分数据从之前的 ES-1.5 集群同步到了现在的 ES-7.5 集群，之后在新集群中进行数据查询的时候发现会有偶发性的查询非常慢的情况。新集群的大部分查询耗时都在 10ms 以内，但是偶尔却会出现 800ms 左右的超高查询耗时，本文记录了该问题的排查过程。

GC 的原因？

首先我们怀疑是 ES 的 GC 导致了偶发性的慢查询，我们知道 JVM 的 GC 会导致 Stop The World 现象，在 GC 时节点无法处理任何逻辑导致查询行为被阻塞最终导致超长的查询耗时，而 GC 这种行为本身也是会偶发的，所以和我们观察到的偶尔出现查询耗时非常高的现象非常吻合。

我们观察 ES 运行的 GC 日志，并未看到有延迟特别高的 GC 行为，而且也没有看到任何 Old GC 的动作，因此这些慢查询应该并不是因为 JVM 的 GC 行为导致的。

顺便介绍一下，我们使用的是 ES-7.5.2 自带的 bundled JDK，它的版本为 13.0.1

~ java -version
openjdk version "13.0.1" 2019-10-15
OpenJDK Runtime Environment AdoptOpenJDK (build 13.0.1+9)
OpenJDK 64-Bit Server VM AdoptOpenJDK (build 13.0.1+9, mixed mode, sharing)

在该版本的 Java 中已经废弃了以前的 GC 日志打印配置方式，新版本的 Java 使用了一种新的叫做 JVM Unified Logging Framework 的方式来控制 GC 日志的打印，它通过 -Xlog 这个属性来进行设置。

我们在当前的 ES 配置 jvm.options 中添加 GC 相关配置如下

## JDK 8 GC logging
8:-XX:+PrintGCDetails
8:-XX:+PrintGCDateStamps
8:-XX:+PrintTenuringDistribution
8:-XX:+PrintGCApplicationStoppedTime
8:-Xloggc:logs/gc.log
8:-XX:+UseGCLogFileRotation
8:-XX:NumberOfGCLogFiles=32
8:-XX:GCLogFileSize=64m

# JDK 9+ GC logging
9-:-Xlog:gc*,gc+age=trace,safepoint:file=logs/gc.log:utctime,pid,tags:filecount=32,filesize=64m

上面我们设置了两种 GC 日志配置，一种是针对 Java8 的配置，还有一种是针对大于或者等于 Java9 的配置，ES 会根据 JVM 的版本选择合适的 GC 日志配置。

因为我们使用的是 Java13，它的版本号是大于 9 的，因此 ES 会自动使用

-Xlog:gc*,gc+age=trace,safepoint:file=logs/gc.log:utctime,pid,tags:filecount=32,filesize=64m

这个 Xlog 的配置来设置 GC LOG 的打印方式。Xlog 属性使用冒号 ( : ) 把它的内容分割为了四个部分：

  1. JVM 中哪些 tag 的日志需要被打印，多个 tag 之间用逗号 ( , ) 分割
  2. 日志打印的目标位置，可以是标准输出或文件等等
  3. 打印日志时同时一起打印的附加属性，例如时间、进程号、tag 名称等等，属性之间用逗号 ( , ) 分割
  4. 一些打印日志时会用到的其它属性

我们再了解一下上面 ES 使用的 - Xlog 属性的各个部分的具体含义，这些属性被分为了四大类

属性 含义
（tags）
gc* 打印 JVM 中 tag 以 gc 开头的日志，级别为默认值 info
gc+age=trace 打印 JVM 中 tag 为 gc+age 的日志，级别为 trace
safepoint 打印 JVM 的 safepoint 日志，级别为默认值 info
（日志打印位置）
file=logs/gc.log GC 日志所保存的文件名
（需要被打印的其它一些属性）
utctime 打印 GC 的时间点
pid JVM 的进程号
tags 打印对应的 tags 信息
（控制日志打印的一些其它属性）
filecount=32,filesize=64m 当日志文件达到 64m 是进行切割，保存 32 个切割文件

上面的 Xlog 可以得到日志如下，包含了 gc*、gc+age 和 safepoint 等 tag 的一些日志

查看代码块 
[2020-08-01T09:54:10.551+0000][1836][gc,heap] Heap region size: 4M
[2020-08-01T09:54:14.339+0000][1836][gc     ] Using G1
[2020-08-01T09:54:14.339+0000][1836][gc,heap,coops] Heap address: 0x0000000600000000, size: 8192 MB, Compressed Oops mode: Zero based, Oop shift amount: 3
[2020-08-01T09:54:14.339+0000][1836][gc,cds       ] Mark closed archive regions in map: [0x00000007ffc00000, 0x00000007ffc77ff8]
[2020-08-01T09:54:14.339+0000][1836][gc,cds       ] Mark open archive regions in map: [0x00000007ffb00000, 0x00000007ffb47ff8]
[2020-08-01T09:54:14.355+0000][1836][gc           ] Periodic GC disabled
[2020-08-01T09:54:14.376+0000][1836][safepoint    ] Safepoint "EnableBiasedLocking", Time since last: 26126542 ns, Reaching safepoint: 711439 ns, At safepoint: 88387 ns, Total: 799826 ns
[2020-08-01T09:54:14.381+0000][1836][safepoint    ] Safepoint "RevokeBias", Time since last: 4864660 ns, Reaching safepoint: 286521 ns, At safepoint: 99576 ns, Total: 386097 ns
...省略部分日志...
[2020-08-01T09:54:17.374+0000][1836][safepoint    ] Safepoint "RevokeBias", Time since last: 743562 ns, Reaching safepoint: 193154 ns, At safepoint: 51118 ns, Total: 244272 ns
[2020-08-01T09:54:17.374+0000][1836][safepoint    ] Safepoint "RevokeBias", Time since last: 198778 ns, Reaching safepoint: 375962 ns, At safepoint: 58373 ns, Total: 434335 ns
[2020-08-01T09:54:17.410+0000][1836][gc,start     ] GC(0) Pause Young (Normal) (G1 Evacuation Pause)
[2020-08-01T09:54:17.412+0000][1836][gc,task      ] GC(0) Using 13 workers of 13 for evacuation
[2020-08-01T09:54:17.413+0000][1836][gc,age       ] GC(0) Desired survivor size 27262976 bytes, new threshold 15 (max threshold 15)
[2020-08-01T09:54:17.452+0000][1836][gc,age       ] GC(0) Age table with threshold 15 (max threshold 15)
[2020-08-01T09:54:17.452+0000][1836][gc,age       ] GC(0) - age   1:   13104680 bytes,   13104680 total
[2020-08-01T09:54:17.452+0000][1836][gc,phases    ] GC(0)   Pre Evacuate Collection Set: 1.8ms
[2020-08-01T09:54:17.452+0000][1836][gc,phases    ] GC(0)   Evacuate Collection Set: 25.5ms
[2020-08-01T09:54:17.452+0000][1836][gc,phases    ] GC(0)   Post Evacuate Collection Set: 2.3ms
[2020-08-01T09:54:17.452+0000][1836][gc,phases    ] GC(0)   Other: 12.1ms
[2020-08-01T09:54:17.452+0000][1836][gc,heap      ] GC(0) Eden regions: 102->0(98)
[2020-08-01T09:54:17.452+0000][1836][gc,heap      ] GC(0) Survivor regions: 0->4(13)
[2020-08-01T09:54:17.452+0000][1836][gc,heap      ] GC(0) Old regions: 0->0
[2020-08-01T09:54:17.452+0000][1836][gc,heap      ] GC(0) Archive regions: 2->2
[2020-08-01T09:54:17.452+0000][1836][gc,heap      ] GC(0) Humongous regions: 0->0
[2020-08-01T09:54:17.452+0000][1836][gc,metaspace ] GC(0) Metaspace: 20335K->20335K(1067008K)
[2020-08-01T09:54:17.452+0000][1836][gc           ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 411M->16M(8192M) 41.802ms
[2020-08-01T09:54:17.452+0000][1836][gc,cpu       ] GC(0) User=0.17s Sys=0.14s Real=0.04s
[2020-08-01T09:54:17.452+0000][1836][safepoint    ] Safepoint "G1CollectForAllocation", Time since last: 35223271 ns, Reaching safepoint: 235074 ns, At safepoint: 42013632 ns, Total: 42248706 ns
[2020-08-01T09:54:17.452+0000][1836][safepoint    ] Safepoint "RevokeBias", Time since last: 274881 ns, Reaching safepoint: 134481 ns, At safepoint: 40119 ns, Total: 174600 ns
[2020-08-01T09:54:17.452+0000][1836][safepoint    ] Safepoint "RevokeBias", Time since last: 43491 ns, Reaching safepoint: 140798 ns, At safepoint: 26232 ns, Total: 167030 ns
[2020-08-01T09:54:17.453+0000][1836][safepoint    ] Safepoint "RevokeBias", Time since last: 64481 ns, Reaching safepoint: 129088 ns, At safepoint: 25018 ns, Total: 154106 ns
[2020-08-01T09:54:17.453+0000][1836][safepoint    ] Safepoint "RevokeBias", Time since last: 35003 ns, Reaching safepoint: 129551 ns, At safepoint: 28893 ns, Total: 158444 ns
[2020-08-01T09:54:17.453+0000][1836][safepoint    ] Safepoint "RevokeBias", Time since last: 111722 ns, Reaching safepoint: 113937 ns, At safepoint: 37371 ns, Total: 151308 ns
[2020-08-01T09:54:17.453+0000][1836][safepoint    ] Safepoint "RevokeBias", Time since last: 36233 ns, Reaching safepoint: 128605 ns, At safepoint: 30396 ns, Total: 159001 ns
[2020-08-01T09:54:17.454+0000][1836][safepoint    ] Safepoint "RevokeBias", Time since last: 44610 ns, Reaching safepoint: 129399 ns, At safepoint: 28918 ns, Total: 158317 ns
[2020-08-01T09:54:17.456+0000][1836][gc,start     ] GC(1) Pause Young (Concurrent Start) (Metadata GC Threshold)
[2020-08-01T09:54:17.456+0000][1836][gc,task      ] GC(1) Using 13 workers of 13 for evacuation
[2020-08-01T09:54:17.456+0000][1836][gc,age       ] GC(1) Desired survivor size 27262976 bytes, new threshold 15 (max threshold 15)
[2020-08-01T09:54:17.473+0000][1836][gc,age       ] GC(1) Age table with threshold 15 (max threshold 15)
[2020-08-01T09:54:17.473+0000][1836][gc,age       ] GC(1) - age   1:      29256 bytes,      29256 total
[2020-08-01T09:54:17.473+0000][1836][gc,age       ] GC(1) - age   2:   13077648 bytes,   13106904 total
[2020-08-01T09:54:17.473+0000][1836][gc,phases    ] GC(1)   Pre Evacuate Collection Set: 0.4ms
[2020-08-01T09:54:17.473+0000][1836][gc,phases    ] GC(1)   Evacuate Collection Set: 15.3ms
[2020-08-01T09:54:17.473+0000][1836][gc,phases    ] GC(1)   Post Evacuate Collection Set: 0.9ms
[2020-08-01T09:54:17.473+0000][1836][gc,phases    ] GC(1)   Other: 0.6ms
[2020-08-01T09:54:17.473+0000][1836][gc,heap      ] GC(1) Eden regions: 1->0(98)
[2020-08-01T09:54:17.473+0000][1836][gc,heap      ] GC(1) Survivor regions: 4->4(13)
[2020-08-01T09:54:17.473+0000][1836][gc,heap      ] GC(1) Old regions: 0->0
[2020-08-01T09:54:17.473+0000][1836][gc,heap      ] GC(1) Archive regions: 2->2
[2020-08-01T09:54:17.473+0000][1836][gc,heap      ] GC(1) Humongous regions: 0->0
[2020-08-01T09:54:17.473+0000][1836][gc,metaspace ] GC(1) Metaspace: 20366K->20366K(1069056K)
[2020-08-01T09:54:17.473+0000][1836][gc           ] GC(1) Pause Young (Concurrent Start) (Metadata GC Threshold) 20M->16M(8192M) 17.263ms
[2020-08-01T09:54:17.473+0000][1836][gc,cpu       ] GC(1) User=0.06s Sys=0.03s Real=0.02s
[2020-08-01T09:54:17.473+0000][1836][gc           ] GC(2) Concurrent Cycle
[2020-08-01T09:54:17.473+0000][1836][gc,marking   ] GC(2) Concurrent Clear Claimed Marks
[2020-08-01T09:54:17.473+0000][1836][gc,marking   ] GC(2) Concurrent Clear Claimed Marks 0.039ms
[2020-08-01T09:54:17.473+0000][1836][gc,marking   ] GC(2) Concurrent Scan Root Regions
[2020-08-01T09:54:17.473+0000][1836][safepoint    ] Safepoint "RevokeBias", Time since last: 93450 ns, Reaching safepoint: 129146 ns, At safepoint: 17510480 ns, Total: 17639626 ns
[2020-08-01T09:54:17.474+0000][1836][safepoint    ] Safepoint "RevokeBias", Time since last: 59519 ns, Reaching safepoint: 157428 ns, At safepoint: 40661 ns, Total: 198089 ns

关于 Xlog 的更加详细的信息可以查看 ** 参考文档 **。有的时候我们只想看到 GC 的日志而不在意其它的日志信息，此时可以只设置 gc 日志的 tag 而移除其它日志的 tag，同时我们停止打印 tags 信息并且将打印时间修改为 ISO-8601 格式。那么根据参考文档，具体设置如下

-Xlog:gc:file=logs/gc.log:t,pid:filecount=32,filesize=64m

改完之后得到的日志如下

查看代码块 
[2020-08-07T14:41:42.809+0800][25593] Using G1
[2020-08-07T14:41:42.827+0800][25593] Periodic GC disabled
[2020-08-07T14:41:54.322+0800][25593] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 411M->16M(8192M) 32.843ms
[2020-08-07T14:41:54.339+0800][25593] GC(1) Pause Young (Concurrent Start) (Metadata GC Threshold) 20M->16M(8192M) 12.395ms
[2020-08-07T14:41:54.339+0800][25593] GC(2) Concurrent Cycle
[2020-08-07T14:41:54.357+0800][25593] GC(2) Pause Remark 24M->24M(8192M) 2.347ms
[2020-08-07T14:41:54.359+0800][25593] GC(2) Pause Cleanup 24M->24M(8192M) 0.409ms
[2020-08-07T14:41:54.393+0800][25593] GC(2) Concurrent Cycle 53.919ms
[2020-08-07T14:41:54.889+0800][25593] GC(3) Pause Young (Normal) (G1 Evacuation Pause) 408M->19M(8192M) 16.746ms
[2020-08-07T14:41:55.335+0800][25593] GC(4) Pause Young (Normal) (G1 Evacuation Pause) 411M->22M(8192M) 13.978ms
[2020-08-07T14:41:56.946+0800][25593] GC(5) Pause Young (Normal) (G1 Evacuation Pause) 426M->42M(8192M) 38.684ms
[2020-08-07T14:41:57.545+0800][25593] GC(6) Pause Young (Concurrent Start) (Metadata GC Threshold) 104M->50M(8192M) 106.594ms
[2020-08-07T14:41:57.545+0800][25593] GC(7) Concurrent Cycle
[2020-08-07T14:41:57.566+0800][25593] GC(7) Pause Remark 52M->52M(8192M) 3.391ms
[2020-08-07T14:41:57.571+0800][25593] GC(7) Pause Cleanup 52M->52M(8192M) 0.689ms
[2020-08-07T14:41:57.599+0800][25593] GC(7) Concurrent Cycle 54.224ms
[2020-08-07T14:42:00.515+0800][25593] GC(8) Pause Young (Concurrent Start) (Metadata GC Threshold) 364M->59M(8192M) 135.170ms
[2020-08-07T14:42:00.515+0800][25593] GC(9) Concurrent Cycle
[2020-08-07T14:42:00.544+0800][25593] GC(9) Pause Remark 63M->63M(8192M) 3.422ms
[2020-08-07T14:42:00.560+0800][25593] GC(9) Pause Cleanup 65M->65M(8192M) 0.432ms
[2020-08-07T14:42:00.591+0800][25593] GC(9) Concurrent Cycle 75.614ms
[2020-08-07T14:42:01.937+0800][25593] GC(10) Pause Young (Normal) (G1 Evacuation Pause) 447M->84M(8192M) 33.470ms
[2020-08-07T14:42:02.786+0800][25593] GC(11) Pause Young (Normal) (G1 Evacuation Pause) 448M->117M(8192M) 42.285ms
[2020-08-07T14:42:09.939+0800][25593] GC(12) Pause Young (Normal) (G1 Evacuation Pause) 1088M->730M(8192M) 60.019ms
[2020-08-07T14:42:19.286+0800][25593] GC(13) Pause Young (Normal) (G1 Evacuation Pause) 1854M->769M(8192M) 51.429ms
[2020-08-07T14:43:19.996+0800][25593] GC(14) Pause Young (Normal) (G1 Evacuation Pause) 4924M->770M(8192M) 43.029ms
[2020-08-07T14:44:50.846+0800][25593] GC(15) Pause Young (Normal) (G1 Evacuation Pause) 6717M->771M(8192M) 50.404ms
[2020-08-07T14:46:32.710+0800][25593] GC(16) Pause Young (Normal) (G1 Evacuation Pause) 7767M->774M(8192M) 41.461ms
[2020-08-07T14:47:38.164+0800][25593] GC(17) Pause Young (Normal) (G1 Evacuation Pause) 5766M->855M(8192M) 48.741ms
[2020-08-07T14:47:53.993+0800][25593] GC(18) Pause Young (Normal) (G1 Evacuation Pause) 5667M->809M(8192M) 40.445ms

和我们之前看到的详细日志相比，现在的日志已经显得清晰多了。对于线上 ES 的 JVM 而言，这些日志一般已经足够我们在出现问题时进行相应的排查了。当然，如果你需要了解 JVM 的详细工作情况，那么也可以将尽可能多 tag 的日志都打印出来以方便进行分析，具体需要哪些日志还是根据实际情况进行考虑。

最后再放一些其它的关于 JVM GC LOG 打印的参考文档

https://stackoverflow.com/q/54144713/4614538
GC logging - Elasticsearch
Setting JVM options - Elasticsearch
JEP 158: Unified JVM Logging

ES 本身的 Cache？

排除了 GC 的问题之后，我们又考虑到可能是 ES 本身的缓存失效导致的慢查询。验证方式非常简单，针对指定的索引我们调用 ES 清除缓存的接口清掉其缓存

POST /index-name/_cache/clear

清除掉缓存之后我们立即进行一次查询，发现该次查询耗时 80ms 左右。虽然清除缓存在一定程度上降低了查询速度，但是也并没有降低到 800ms 那么慢，可见 ES 缓存失效也不是偶发性慢查询的真正原因。因为如果是 ES 缓存失效导致的慢查询，那么在清除掉 ES 缓存之后查询速度也应该降低到 800ms 才对。

Page cache

我们知道在 Linux 操作系统中，内核是按页来管理内存的。如果想要访问磁盘上的一段数据，操作系统会分配一页（一般是 4K）物理内存，之后把这些数据读取到这一页内存中以进行后续的操作。读取流程如下参考

  1. 进程调用库函数 read 发起读取文件请求
  2. 内核检查已打开的文件列表，调用文件系统提供的 read 接口
  3. 找到文件对应的 inode，然后计算出要读取的具体的页
  4. 通过 inode 查找对应的页缓存
    1. 如果页缓存节点命中，则直接返回文件内容
    2. 如果没有对应的页缓存，则会产生一个缺页异常（page fault）
    3. 操作系统创建新的空的页缓存并从磁盘中读取文件内容，更新页缓存，然后重复第 4 步
  5. 读取文件返回

页缓存，也叫做文件缓存或磁盘缓存，它对于 ES 的核心部件 Lucene 十分重要。Lucene 的读写文件十分依赖操作系统的页缓存来提高访问速度，以至于 ES 在官方文档中都提到 ES 的 JVM 进程只应该占用操作系统的一半物理内存，而把剩下的一半物理内存留给 Lucene 用作读写文件的页缓存。空闲内存越多，操作系统可用于 Page Cache 的内存也就越多，Lucene 也就可以缓存越多的数据在内存中，这样就可以大大的提高 Lucene 的读写速度。当物理内存不足时，操作系统也会让部分缓存失效以空出内存空间。

需要注意的是，Page Cache 是完全由操作系统控制的，程序无法干预。在程序读写文件时操作系统会自动的创建 Page Cache 来提高访问速度，但是在程序看来它只是进行了一次文件读写操作，而并不知道在读写操作背后操作系统具体是如何完成这次读写的、以及操作系统是否使用了缓存。

背景知识介绍到此。我们怀疑 ES 的偶发性慢查询是否是因为 Page Cache 的失效导致数据查询无法通过缓存获得，因此从磁盘上获取数据导致了比平时更长的查询时间呢？通过对慢查询发生时机器状态的监控我们发现，在发生慢查询时对应查询较慢的分片所在的机器节点 CPU 负载很低、内存空闲资源充足，并不存在内存资源不足的情况。因此应该并不是内存资源不足导致 Page Cache 失效而引发的慢查询。

index.search.idle.after

以上两个因素都不是偶发慢查询的真正原因，我们继续在 Google 上搜索相关的问题，最后我们发现了这个帖子。帖子里面提到了一个叫做 index.search.idle.after 的属性，它是在 ES-7.0 中新增的一个配置属性。

按照官方文档的说法，只要一个分片在 index.search.idle.after 时间段（默认 30s）没有能够收到任何请求，就会进入 search idle 状态。

但是！！！按照官方文档的说法是即使进入了 search idle 状态，只要 index.refresh_interval 设置了刷新间隔，分片依旧会刷新，** 这部分好像与事实不符 **。

事实上，一旦分片进入了 search idle 状态，该分片就会停止 refresh 以节省资源（即使设置了 index.refresh_interval）。等到后面再有 search 请求在该分片发生时，分片首先需要进行一次 refresh，refresh 完成之后才会执行真正的 search。所以一旦分片进入 search idle 之后再次查询时就会比平时消耗更多的时间。

至此我们偶发性的慢查询问题就找到原因了。因为我们新的集群刚刚搭建不久，还处于测试阶段，所以我们只切了很少的一部分查询流量到新的集群，那么每个分片在两次查询之间的间隔就有可能会大于 30s。而一个分片一旦 30s 都没有任何查询就会进入 search idle 状态，那么下一次的查询自然就会比普通的查询慢很多。

知道了原因之后我们就开始着手解决这个问题，目前有两个解决方案。

1. 修改 index.search.idle.after 的值

我们可以把 index.search.idle.after 值改大一些，避免分片频繁的进入 search idle，例如我们可以把其从默认值 30 秒修改为 5 分钟

PUT /index-name/_settings
{
    "index.search.idle.after": "5m"
}

修改完之后我们可以看下修改是否生效

GET /index-name/_settings

得到结果如下，可见该值已经被修改 5m 了

{
    "index-name": {
        "settings": {
            "index": {
                "search": {
                    "idle": {
                        "after": "5m"
                    }
                },
                "number_of_shards": "2",
                ...省略部分内容...
            }
        }
    }
}

当然我们也可以恢复该值的默认设置

PUT /index-name/_settings
{
    "index.search.idle.after": null
}

2. 增加请求频率

上面我们介绍了第一个解决方案是增加进入 idle 的时间，还有一个办法是我们把更多的查询流量切到新的集群中去，这样因为查询之间的间隔变低，也就不会进入 idle 状态了。

考虑到我们已经测试了一段时间的新集群了，所以我们选择第二种方案把所有的查询流量都切到新集群中，查询频率增加后也没有再出现偶尔查询很慢的情况了。