❌

阅读视图

发现新文章，点击刷新页面。
🔲 ⭐

使用Elasticsearch分析腾讯云EO日志

✇御坂研究所
Raymond

腾讯云EO可以查看一些指标信息，但是更加详细的信息需要我们下载离线日志自行分析。

获取日志下载链接

腾讯云会将日志打包为.gz格式，解压后文件会包含多行，每一行都是一个JSON格式的数据，对应一条EO的请求日志，日志格式可以参考腾讯云文档。

我们可以批量获取最近一个月的日志下载链接

之后复制所有链接并保存到urls.txt文件中。

启动Elasticsearch集群

我们参考官方文档使用docker来启动集群，首先下载.env和docker-compose.yml，之后在.env文件中设置es和kibana的密码都是123456，然后设置STACK_VERSION=9.2.3。考虑到数据量比较大，可以提高容器的内存大小，我这里设置了一台8G。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
# Password for the 'elastic' user (at least 6 characters)
ELASTIC_PASSWORD=123456

# Password for the 'kibana_system' user (at least 6 characters)
KIBANA_PASSWORD=123456

# Version of Elastic products
STACK_VERSION=9.2.3

# Set the cluster name
CLUSTER_NAME=elasticsearch-cluster

# Set to 'basic' or 'trial' to automatically start the 30-day trial
LICENSE=basic

# Port to expose Elasticsearch HTTP API to the host
ES_PORT=9200

# Port to expose Kibana to the host
KIBANA_PORT=5601

# Increase or decrease based on the available host memory (in bytes)
MEM_LIMIT=8589934592

# Project namespace (defaults to the current folder name if not set)
COMPOSE_PROJECT_NAME=elasticsearch-project

设置好了之后使用命令docker-compose up -d启动ES集群。

之后可以通过http://127.0.0.1:5601访问kibana，用户名elastic，密码123456。

写入日志

使用如下的代码下载解析日志，并保存到ES中

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
import gzip
import json
import os
from datetime import datetime
from urllib.parse import urlparse

import requests
from elasticsearch import Elasticsearch, helpers

ES_URL = "https://localhost:9200"
ES_USER = "elastic"
ES_PASSWORD = "123456"
INDEX_NAME = "eo_logs"
DOWNLOAD_DIR = "downloaded_logs"

es = Elasticsearch([ES_URL], basic_auth=(ES_USER, ES_PASSWORD), verify_certs=False, ssl_show_warn=False)
os.makedirs(DOWNLOAD_DIR, exist_ok=True)


def download_file(url):
    filename = os.path.basename(urlparse(url).path)
    filepath = os.path.join(DOWNLOAD_DIR, filename)
    if os.path.exists(filepath):
        print(f"文件已存在: {filename}")
        return filepath
    print(f"下载: {filename}")
    response = requests.get(url, stream=True, timeout=300)
    with open(filepath, 'wb') as f:
        for chunk in response.iter_content(chunk_size=8192):
            if chunk:
                f.write(chunk)
    return filepath


def parse_gz(filepath):
    logs = []
    print(f"解析: {os.path.basename(filepath)}")
    with gzip.open(filepath, 'rt', encoding='utf-8') as f:
        for line in f:
            line = line.strip()
            if line:
                log = json.loads(line)
                log['_source_file'] = os.path.basename(filepath)
                log['_import_time'] = datetime.utcnow().isoformat()
                logs.append(log)

    print(f"解析完成: {len(logs)} 条")
    return logs


def save_to_es(logs):
    if not logs:
        return
    print(f"保存 {len(logs)} 条到 ES")
    actions = [{"_index": INDEX_NAME, "_source": log} for log in logs]
    success, _ = helpers.bulk(es, actions, chunk_size=1000, request_timeout=60)
    print(f"保存完成: {success} 条")


def process_url(url):
    filepath = download_file(url)
    logs = parse_gz(filepath)
    save_to_es(logs)


def main():
    with open("urls.txt", 'r') as f:
        urls = [line.strip() for line in f if line.strip()]
    print(f"开始处理 {len(urls)} 个文件\n")
    for i, url in enumerate(urls, 1):
        print(f"\n[{i}/{len(urls)}]")
        process_url(url)
    print("\n处理完成!")


if __name__ == "__main__":
    main()

执行如上代码，就能够下载日志并保存到ES了（这会花费比较多的时间，我这里花费了100多分钟）。

分析日志

数据索引完毕之后，我们可以查看索引信息

1
2
~ curl 'https://127.0.0.1:9200/eo_logs/_count' --header 'Authorization: Basic ZWxhc3RpYzo9dk5Cc0QwSTNZRWFPa2RoZFFhZg==' -k
{"count":31398691,"_shards":{"total":1,"successful":1,"skipped":0,"failed":0}}%

可以看到一共索引了3000多万条数据，我们还可以查看索引的mapping和详细信息如下

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
{
  "eo_logs": {
    "aliases": {},
    "mappings": {
      "properties": {
        "ClientIP": {
          "type": "text",
          "fields": {
            "keyword": {
              "type": "keyword",
              "ignore_above": 256
            }
          }
        },
        "ClientISP": {
          "type": "text",
          "fields": {
            "keyword": {
              "type": "keyword",
              "ignore_above": 256
            }
          }
        },
        "ClientRegion": {
          "type": "text",
          "fields": {
            "keyword": {
              "type": "keyword",
              "ignore_above": 256
            }
          }
        },
        "ClientState": {
          "type": "text",
          "fields": {
            "keyword": {
              "type": "keyword",
              "ignore_above": 256
            }
          }
        },
        "ContentID": {
          "type": "text",
          "fields": {
            "keyword": {
              "type": "keyword",
              "ignore_above": 256
            }
          }
        },
        "EdgeCacheStatus": {
          "type": "text",
          "fields": {
            "keyword": {
              "type": "keyword",
              "ignore_above": 256
            }
          }
        },
        "EdgeFunctionSubrequest": {
          "type": "long"
        },
        "EdgeInternalTime": {
          "type": "long"
        },
        "EdgeResponseBodyBytes": {
          "type": "long"
        },
        "EdgeResponseBytes": {
          "type": "long"
        },
        "EdgeResponseStatusCode": {
          "type": "long"
        },
        "EdgeResponseTime": {
          "type": "long"
        },
        "EdgeServerID": {
          "type": "text",
          "fields": {
            "keyword": {
              "type": "keyword",
              "ignore_above": 256
            }
          }
        },
        "EdgeServerIP": {
          "type": "text",
          "fields": {
            "keyword": {
              "type": "keyword",
              "ignore_above": 256
            }
          }
        },
        "ParentRequestID": {
          "type": "text",
          "fields": {
            "keyword": {
              "type": "keyword",
              "ignore_above": 256
            }
          }
        },
        "RemotePort": {
          "type": "long"
        },
        "RequestBytes": {
          "type": "long"
        },
        "RequestHost": {
          "type": "text",
          "fields": {
            "keyword": {
              "type": "keyword",
              "ignore_above": 256
            }
          }
        },
        "RequestID": {
          "type": "text",
          "fields": {
            "keyword": {
              "type": "keyword",
              "ignore_above": 256
            }
          }
        },
        "RequestMethod": {
          "type": "text",
          "fields": {
            "keyword": {
              "type": "keyword",
              "ignore_above": 256
            }
          }
        },
        "RequestProtocol": {
          "type": "text",
          "fields": {
            "keyword": {
              "type": "keyword",
              "ignore_above": 256
            }
          }
        },
        "RequestRange": {
          "type": "text",
          "fields": {
            "keyword": {
              "type": "keyword",
              "ignore_above": 256
            }
          }
        },
        "RequestReferer": {
          "type": "text",
          "fields": {
            "keyword": {
              "type": "keyword",
              "ignore_above": 256
            }
          }
        },
        "RequestStatus": {
          "type": "text",
          "fields": {
            "keyword": {
              "type": "keyword",
              "ignore_above": 256
            }
          }
        },
        "RequestTime": {
          "type": "date"
        },
        "RequestUA": {
          "type": "text",
          "fields": {
            "keyword": {
              "type": "keyword",
              "ignore_above": 256
            }
          }
        },
        "RequestUrl": {
          "type": "text",
          "fields": {
            "keyword": {
              "type": "keyword",
              "ignore_above": 256
            }
          }
        },
        "RequestUrlQueryString": {
          "type": "text",
          "fields": {
            "keyword": {
              "type": "keyword",
              "ignore_above": 256
            }
          }
        },
        "_import_time": {
          "type": "date"
        },
        "_source_file": {
          "type": "text",
          "fields": {
            "keyword": {
              "type": "keyword",
              "ignore_above": 256
            }
          }
        }
      }
    },
    "settings": {
      "index": {
        "routing": {
          "allocation": {
            "include": {
              "_tier_preference": "data_content"
            }
          }
        },
        "number_of_shards": "1",
        "provided_name": "eo_logs",
        "creation_date": "1766816305347",
        "number_of_replicas": "1",
        "uuid": "wi9l88cjRh-Kq7lgl4NReg",
        "version": {
          "created": "9039003"
        }
      }
    }
  }
}

具体每个字段的含义如下

字段名含义说明
ClientIP客户端 IP访问 EdgeOne 边缘节点的真实用户 IP
ClientISP客户端运营商用户网络所属运营商，如电信、联通、移动
ClientRegion客户端地区用户所在国家或地区
ClientState客户端省份/州用户所在省份或州级行政区
ContentID内容标识EO 内部用于标识访问资源的唯一 ID
EdgeCacheStatus缓存状态边缘节点缓存命中情况：Hit / Miss / RefreshHit / Bypass
EdgeFunctionSubrequest子请求数量边缘函数触发的内部子请求次数
EdgeInternalTime内部处理耗时边缘节点内部处理请求所消耗的时间（毫秒）
EdgeResponseBodyBytes响应体大小返回给客户端的响应 Body 字节数
EdgeResponseBytes响应总大小返回给客户端的总字节数（Header + Body）
EdgeResponseStatusCode响应状态码边缘节点返回的 HTTP 状态码
EdgeResponseTime总响应耗时从边缘节点接收请求到完成响应的总耗时（毫秒）
EdgeServerID边缘节点 ID实际处理请求的 EdgeOne 节点标识
EdgeServerIP边缘节点 IP实际处理请求的边缘节点 IP 地址
ParentRequestID父请求 ID关联内部转发或子请求的父级请求标识
RemotePort客户端端口客户端发起连接时使用的端口
RequestBytes请求大小客户端请求报文大小（字节）
RequestHost请求域名客户端请求的 Host 域名
RequestID请求 IDEdgeOne 为请求生成的唯一标识
RequestMethod请求方法HTTP 请求方法，如 GET、POST
RequestProtocol请求协议使用的 HTTP 协议版本（HTTP/1.1、HTTP/2、HTTP/3）
RequestRangeRange 请求请求头中的 Range 字段，用于分段或断点下载
RequestReferer来源页面请求头中的 Referer 信息
RequestStatus请求状态EdgeOne 定义的请求处理状态
RequestTime请求时间请求到达 EdgeOne 的时间
RequestUAUser-Agent客户端 User-Agent 信息
RequestUrl请求路径请求的 URL 路径（不包含查询参数）
RequestUrlQueryString查询参数请求 URL 中的 Query String
_import_time导入时间日志被导入 Elasticsearch 的时间
_source_file日志来源生成该日志的原始文件或对象标识

然后我们想看指定域名的请求耗时情况（从EdgeOne接收到客户端发起的请求开始，到响应给客户端最后一个字节，整个过程的耗时，对应字段EdgeResponseTime），可以使用如下DSL

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
POST /eo_logs/_search
{
    "size": 0,
    "query": {
        "bool": {
            "filter": [
                {
                    "term": {
                        "RequestHost.keyword": "static.example.com"
                    }
                }
            ]
        }
    },
    "aggs": {
        "edge_response_stats": {
            "stats": {
                "field": "EdgeResponseTime"
            }
        },
        "edge_response_percentiles": {
            "percentiles": {
                "field": "EdgeResponseTime",
                "percents": [
                    50,
                    90,
                    95,
                    99
                ]
            }
        },
        "edge_response_hist": {
            "histogram": {
                "field": "EdgeResponseTime",
                "interval": 50,
                "min_doc_count": 1
            }
        }
    }
}

得到结果如下

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
{
  "took": 3128,
  "timed_out": false,
  "_shards": {
    "total": 1,
    "successful": 1,
    "skipped": 0,
    "failed": 0
  },
  "hits": {
    "total": {
      "value": 10000,
      "relation": "gte"
    },
    "max_score": null,
    "hits": []
  },
  "aggregations": {
    "edge_response_percentiles": {
      "values": {
        "50.0": 5.014287434842656,
        "90.0": 25.778307762642324,
        "95.0": 73.78316545752277,
        "99.0": 593.9728031414846
      }
    },
    "edge_response_hist": {
      "buckets": [
        {
          "key": 0.0,
          "doc_count": 25997272
        },
        {
          "key": 50.0,
          "doc_count": 841843
        },
        {
          "key": 100.0,
          "doc_count": 377168
        },
        {
          "key": 150.0,
          "doc_count": 109181
        },
        {
          "key": 200.0,
          "doc_count": 53672
        },
        {
          "key": 250.0,
          "doc_count": 37425
        },
        {
          "key": 300.0,
          "doc_count": 32744
        },
        {
          "key": 350.0,
          "doc_count": 36445
        },
        {
          "key": 400.0,
          "doc_count": 26137
        },
        {
          "key": 450.0,
          "doc_count": 22807
        },
        {
          "key": 500.0,
          "doc_count": 21111
        },
        {
          "key": 550.0,
          "doc_count": 16784
        },
        {
          "key": 600.0,
          "doc_count": 13214
        },
        {
          "key": 650.0,
          "doc_count": 11211
        },
        {
          "key": 700.0,
          "doc_count": 11760
        },
        {
          "key": 750.0,
          "doc_count": 11911
        },
        {
          "key": 800.0,
          "doc_count": 10381
        },
        {
          "key": 850.0,
          "doc_count": 9158
        },
        {
          "key": 900.0,
          "doc_count": 6851
        },
        {
          "key": 950.0,
          "doc_count": 5822
        },
        {
          "key": 1000.0,
          "doc_count": 5195
        },
        ...
      ]
    },
    "edge_response_stats": {
      "count": 27840645,
      "min": 1.0,
      "max": 707706.0,
      "avg": 46.91420216737076,
      "sum": 1.306121648E9
    }
  }
}

我们重点关注百分比：

百分位含义解读
p505 ms一半请求 5ms 内完成（极快）
p9025 ms90% 的请求很健康
p9574 ms95% 的请求 < 100ms（优秀）
p99594 ms1% 请求接近 / 超过 0.5s

可以看到这个域名的请求速度还是很快的。

此外，我们还可以分析哪些资源的下载比较慢

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
POST /eo_logs/_search
{
    "size": 0,
    "query": {
        "bool": {
            "filter": [
                {
                    "term": {
                        "RequestHost.keyword": "static.example.com"
                    }
                },
                {
                    "exists": {
                        "field": "RequestUrl.keyword"
                    }
                },
                {
                    "exists": {
                        "field": "EdgeResponseTime"
                    }
                }
            ]
        }
    },
    "aggs": {
        "by_url": {
            "terms": {
                "field": "RequestUrl.keyword",
                "size": 200,
                "order": {
                    "p95_edge_response[95.0]": "desc"
                }
            },
            "aggs": {
                "p95_edge_response": {
                    "percentiles": {
                        "field": "EdgeResponseTime",
                        "percents": [
                            95
                        ]
                    }
                },
                "avg_edge_response": {
                    "avg": {
                        "field": "EdgeResponseTime"
                    }
                },
                "count_requests": {
                    "value_count": {
                        "field": "EdgeResponseTime"
                    }
                }
            }
        }
    }
}

我们可以针对上面查询到的慢速URL去做特定的优化和缓存预热。只是，上面的这个DSL不够严谨，因为单纯使用请求时间来判断速度快慢是不足够的，请求时间也会受到资源大小的影响。因此，我们使用资源的大小比上请求耗时，这个就代表这个资源的下载速度，之后我们从小到大排序，就可以知道哪些资源可能会下载比较慢了。具体DSL如下

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
POST /eo_logs/_search
{
    "size": 0,
    "query": {
        "bool": {
            "filter": [
                {
                    "term": {
                        "RequestHost.keyword": "static.example.com"
                    }
                },
                {
                    "exists": {
                        "field": "RequestUrl.keyword"
                    }
                },
                {
                    "exists": {
                        "field": "EdgeResponseTime"
                    }
                },
                {
                    "exists": {
                        "field": "EdgeResponseBodyBytes"
                    }
                },
                {
                    "range": {
                        "EdgeResponseBodyBytes": {
                            "gt": 0
                        }
                    }
                },
                {
                    "range": {
                        "EdgeResponseTime": {
                            "gt": 0
                        }
                    }
                }
            ]
        }
    },
    "aggs": {
        "by_url": {
            "terms": {
                "field": "RequestUrl.keyword",
                "size": 2000,
                "order": {
                    "avg_kbps": "asc"
                }
            },
            "aggs": {
                "avg_kbps": {
                    "avg": {
                        "script": {
                            "lang": "painless",
                            "source": "double b = doc['EdgeResponseBodyBytes'].value; double t = doc['EdgeResponseTime'].value; return (b / t) * (1000.0 / 1024.0);"
                        }
                    }
                },
                "p95_kbps": {
                    "percentiles": {
                        "script": {
                            "lang": "painless",
                            "source": "double b = doc['EdgeResponseBodyBytes'].value; double t = doc['EdgeResponseTime'].value; return (b / t) * (1000.0 / 1024.0);"
                        },
                        "percents": [
                            95
                        ]
                    }
                },
                "avg_time_ms": {
                    "avg": {
                        "field": "EdgeResponseTime"
                    }
                },
                "avg_body_bytes": {
                    "avg": {
                        "field": "EdgeResponseBodyBytes"
                    }
                },
                "req_count": {
                    "value_count": {
                        "field": "EdgeResponseTime"
                    }
                }
            }
        }
    }
}

根据上面的查询结果，我们就可以知道哪些资源的下载速度可能比较慢，之后就可以针对这些URL对应的资源去做专门的优化了。

🔲 ☆

Elasticsearch 海量数据查询原理 | 小记

✇yiyun's Blog
yiyun

𠄗𠳵

𡎱𤶼𤟴𣢚𮪀𧵄𤸳，𢠫𥫑𨩥𩟠𡎱𮰾𦉋𬤍𬱉，𨗿𩎄𭶽𦉭𭏫𮔚𮜛𩭙𡦲𢛛𠻙𪲧。𪇅𩫵𮯱𨏍𩊼𯊐𡢉𤒪Filebeat𤒪𤺸𬦞𢠫𥫑，𣐃𪇅𬻡𤒪Logstash𤒪𠪵𥎶𥷷𬻗𢠫𥫑𮑟𠨜𫳺𤒪Elasticsearch𤒪𤸳𮃀𧙹𮡈𢽮𬜁𥽁𣇓𨩥𭧨。

𪯧𣠃，𡽷𬎨𧟭𯒉𤜾𨥋𣝡𯒉𣏅𧟭𩊺𣝡𣰀𤒪𪳒𨝶𫙹𡸌𣅸𤶙𦷗𠹼𮫠𢨢𮃀𧙹𩭌𩒠𭏫𦭧𪶴𪼧？𪅎𬾥𬻗𭊣𪏎𤝽𥮌𡸈𮾆𨲇𪶴𪌎𡐽𫉙𮈋，𦤳𤔭𡊧𪕫𨵮𬘭𡸈𪢔𦛭𠄗𦲐——𪥘𦈠𧟭𣝡𣰀𣏅𤒪𦒚𨲜𣝡𣏅𪺄𣏅。

🔲 ⭐

使用 JuiceFS 存储 Elasticsearch 数据

✇陈少文的博客
微信公众号
1. 存储方案 三种存储方案： 基于目录隔离公用一个 JuiceFS Elasticsearch 的节点共用一个 JuiceFS，通过子目录挂载不同的 Elasticsearch 节点。 /0/ 对应节点 Node-0 /1/ 对应节点 Node-1 /2/ 对应节点 Node-2 这种方式的好处主要是，易于扩展、配置方便。 基于 JuiceFS 隔离节点数据 Elasticsearch 每个节点都对接一个独立的 JuiceF
🔲 ⭐

一次Elasticsearch慢查询问题的排查

✇御坂研究所
Derobukal

最近对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 -versionopenjdk version "13.0.1" 2019-10-15OpenJDK 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 logging8:-XX:+PrintGCDetails8:-XX:+PrintGCDateStamps8:-XX:+PrintTenuringDistribution8:-XX:+PrintGCApplicationStoppedTime8:-Xloggc:logs/gc.log8:-XX:+UseGCLogFileRotation8:-XX:NumberOfGCLogFiles=328:-XX:GCLogFileSize=64m# JDK 9+ GC logging9-:-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.logGC日志所保存的文件名
（需要被打印的其它一些属性）
utctime打印GC的时间点
pidJVM的进程号
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状态了。

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

🔲 ☆

Elasticsearch 与 Hive 集成

✇TimeMachine Notes
时光机

前言

工作上存在将 Hive 上的数据刷到 ES 的场景，首先想到的是自己写程序读取 Hive 上的数据，经过业务逻辑处理在写回到 ES 上，不过请教了下，知道了 ES 本身已经可以和 Hive 集成。只需添加对应的 jar 包，在 hive 上建立与 ES 关联的外部表，即可使用 HQL 查询写入 ES 索引库。具体使用请见官方文档 ，本文只举个简单例子及介绍下主要的参数。

❌