ElasticsearchのSlowlog設定について

18186 ワード
Elasticsearch Elasticsearch テキストリンク

ElasticsearchのSlowlogについて

皆さん、ElasticsearchのSlowlog設定を利用されてますか？
クエリのパフォーマンスチューニングや、インデキシングに時間がかかっている時の原因究明に大いに役立つ設定だと思いますので、Elastic CloudとDocker上でのSlowlogの設定をご紹介します。

目次

  • Slowlogとは
  • Elastic CloudでのSlowlog設定
  • Docker上でのSlowlog設定
  • 最後に

Slowlogとは

まず公式ドキュメントはこちらです。
概要としては、インデックスに対してwarn, info, debug, traceのレベル毎に時間を設定することで、設定時間を上回ったクエリが出力されます。対象はSearchとIndexになりSearchのSlowlogではQueryとFetchで別々の時間が設定できます。

Search
PUT /item/_settings
{
  "index.search.slowlog.threshold.query.warn": "10s",
  "index.search.slowlog.threshold.query.info": "5s",
  "index.search.slowlog.threshold.query.debug": "2s",
  "index.search.slowlog.threshold.query.trace": "500ms",
  "index.search.slowlog.threshold.fetch.warn": "1s",
  "index.search.slowlog.threshold.fetch.info": "800ms",
  "index.search.slowlog.threshold.fetch.debug": "500ms",
  "index.search.slowlog.threshold.fetch.trace": "200ms",
  "index.search.slowlog.level": "info"
}
Index
PUT /item/_settings
{
  "index.indexing.slowlog.threshold.index.warn": "10s",
  "index.indexing.slowlog.threshold.index.info": "5s",
  "index.indexing.slowlog.threshold.index.debug": "2s",
  "index.indexing.slowlog.threshold.index.trace": "500ms",
  "index.indexing.slowlog.level": "info",
  "index.indexing.slowlog.source": "1000"
}

Elastic CloudでのSlowlog設定

ElasticのブログにElastic CloudのSlowlogの取得が簡単になった旨の記事がありましたので試してみました。この記事の設定が入る前は、Slowlog設定を行った後にElasticサポートに連絡してSlowlogをメールで送っていただくしか取得する方法がなく、とても手間だったと思います。

設定方法

ブログ記事と同様の内容ですが、非常に簡単です。

１．Slowlogの有効化
Ship to a deloyment を Enable をクリック

２．送り先を設定
Ship date to でSlowlogを保管する場所を指定し、Saveをクリック
※Slowlogだけの場合はLogsのみにチェックし、Metricsも設定する場合はMetricsにもチェックする。

３．Slowlog設定
Slowlogを設定したいインデックスに対して設定します。
下記設定の場合は、レベルをdebugに設定したので、2s以上かかるクエリがSlowlogとして出力されます。
※便宜上インデックス名はitemとしています。

PUT /item/_settings
{
  "index.search.slowlog.threshold.query.warn": "10s",
  "index.search.slowlog.threshold.query.info": "5s",
  "index.search.slowlog.threshold.query.debug": "2s",
  "index.search.slowlog.threshold.query.trace": "500ms",
  "index.search.slowlog.level": "debug"
}

４．Slowlog確認
itemインデックスに対してクエリが2s以上かかった場合に、Slowlogが出力されるため確認します。
Slowlogが出力されるインデックス名は下記になります。
elastic-cloud-logs-<beatversion>-<date>

クエリはこんな感じです。
非常に簡単な設定でSlowlogが取得できるようになりましたね！
内部ではFilebeatがログを保管場所へ送信しているようです。

GET /elastic-cloud-logs-7-2020.12.03-000001/_search
{
  "query": {
    "term": {
      "log.level": {
        "value": "DEBUG"
      }
    }
  }
}

Docker上でのSlowlog設定

次はDocker上で動かしているElasticsearchにSlowlog設定を行い、filebeat経由でindexに登録してみます。
こちらも非常に簡単で設定するだけです。

１．Dockerファイルの準備
Dockerファイルはこんな感じで、log4j2.propertiesの設定を変更したいのでCOPYしています。

Dockerfile
FROM docker.elastic.co/elasticsearch/elasticsearch:7.10.0
COPY ./log/log4j2.properties /usr/share/elasticsearch/config/log4j2.properties

２．log4j2.propertiesの準備
Slowlogのドキュメントに記載の通りlog4j2.propertiesの設定を行います。

log4j2.properties
appender.index_search_slowlog_rolling.type = RollingFile
appender.index_search_slowlog_rolling.name = index_search_slowlog_rolling
appender.index_search_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_search_slowlog.log
appender.index_search_slowlog_rolling.layout.type = PatternLayout
appender.index_search_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] [%node_name]%marker %.-10000m%n
appender.index_search_slowlog_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_search_slowlog-%i.log.gz
appender.index_search_slowlog_rolling.policies.type = Policies
appender.index_search_slowlog_rolling.policies.size.type = SizeBasedTriggeringPolicy
appender.index_search_slowlog_rolling.policies.size.size = 1GB
appender.index_search_slowlog_rolling.strategy.type = DefaultRolloverStrategy
appender.index_search_slowlog_rolling.strategy.max = 4

logger.index_search_slowlog_rolling.name = index.search.slowlog
logger.index_search_slowlog_rolling.level = trace
logger.index_search_slowlog_rolling.appenderRef.index_search_slowlog_rolling.ref = index_search_slowlog_rolling
logger.index_search_slowlog_rolling.additivity = false

log4j2.propertiesの全体はこちらを参照
status = error

appender.rolling.type = Console
appender.rolling.name = rolling
appender.rolling.layout.type = ESJsonLayout
appender.rolling.layout.type_name = server

rootLogger.level = info
rootLogger.appenderRef.rolling.ref = rolling

appender.deprecation_rolling.type = Console
appender.deprecation_rolling.name = deprecation_rolling
appender.deprecation_rolling.layout.type = ESJsonLayout
appender.deprecation_rolling.layout.type_name = deprecation
appender.deprecation_rolling.layout.esmessagefields=x-opaque-id
appender.deprecation_rolling.filter.rate_limit.type = RateLimitingFilter

appender.header_warning.type = HeaderWarningAppender
appender.header_warning.name = header_warning

logger.deprecation.name = org.elasticsearch.deprecation
logger.deprecation.level = deprecation
logger.deprecation.appenderRef.deprecation_rolling.ref = deprecation_rolling
logger.deprecation.appenderRef.header_warning.ref = header_warning
logger.deprecation.additivity = false

appender.index_search_slowlog_rolling.type = RollingFile
appender.index_search_slowlog_rolling.name = index_search_slowlog_rolling
appender.index_search_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_search_slowlog.log
appender.index_search_slowlog_rolling.layout.type = PatternLayout
appender.index_search_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] [%node_name]%marker %.-10000m%n
appender.index_search_slowlog_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_search_slowlog-%i.log.gz
appender.index_search_slowlog_rolling.policies.type = Policies
appender.index_search_slowlog_rolling.policies.size.type = SizeBasedTriggeringPolicy
appender.index_search_slowlog_rolling.policies.size.size = 1GB
appender.index_search_slowlog_rolling.strategy.type = DefaultRolloverStrategy
appender.index_search_slowlog_rolling.strategy.max = 4

logger.index_search_slowlog_rolling.name = index.search.slowlog
logger.index_search_slowlog_rolling.level = trace
logger.index_search_slowlog_rolling.appenderRef.index_search_slowlog_rolling.ref = index_search_slowlog_rolling
logger.index_search_slowlog_rolling.additivity = false


appender.index_indexing_slowlog_rolling.type = Console
appender.index_indexing_slowlog_rolling.name = index_indexing_slowlog_rolling
appender.index_indexing_slowlog_rolling.layout.type = ESJsonLayout
appender.index_indexing_slowlog_rolling.layout.type_name = index_indexing_slowlog
appender.index_indexing_slowlog_rolling.layout.esmessagefields=message,took,took_millis,doc_type,id,routing,source

logger.index_indexing_slowlog.name = index.indexing.slowlog.index
logger.index_indexing_slowlog.level = trace
logger.index_indexing_slowlog.appenderRef.index_indexing_slowlog_rolling.ref = index_indexing_slowlog_rolling
logger.index_indexing_slowlog.additivity = false

appender.audit_rolling.type = Console
appender.audit_rolling.name = audit_rolling
appender.audit_rolling.layout.type = PatternLayout
appender.audit_rolling.layout.pattern = {\
"type":"audit", \
"timestamp":"%d{yyyy-MM-dd'T'HH:mm:ss,SSSZ}"\
%varsNotEmpty{, "node.name":"%enc{%map{node.name}}{JSON}"}\
%varsNotEmpty{, "node.id":"%enc{%map{node.id}}{JSON}"}\
%varsNotEmpty{, "host.name":"%enc{%map{host.name}}{JSON}"}\
%varsNotEmpty{, "host.ip":"%enc{%map{host.ip}}{JSON}"}\
%varsNotEmpty{, "event.type":"%enc{%map{event.type}}{JSON}"}\
%varsNotEmpty{, "event.action":"%enc{%map{event.action}}{JSON}"}\
%varsNotEmpty{, "authentication.type":"%enc{%map{authentication.type}}{JSON}"}\
%varsNotEmpty{, "user.name":"%enc{%map{user.name}}{JSON}"}\
%varsNotEmpty{, "user.run_by.name":"%enc{%map{user.run_by.name}}{JSON}"}\
%varsNotEmpty{, "user.run_as.name":"%enc{%map{user.run_as.name}}{JSON}"}\
%varsNotEmpty{, "user.realm":"%enc{%map{user.realm}}{JSON}"}\
%varsNotEmpty{, "user.run_by.realm":"%enc{%map{user.run_by.realm}}{JSON}"}\
%varsNotEmpty{, "user.run_as.realm":"%enc{%map{user.run_as.realm}}{JSON}"}\
%varsNotEmpty{, "user.roles":%map{user.roles}}\
%varsNotEmpty{, "apikey.id":"%enc{%map{apikey.id}}{JSON}"}\
%varsNotEmpty{, "apikey.name":"%enc{%map{apikey.name}}{JSON}"}\
%varsNotEmpty{, "origin.type":"%enc{%map{origin.type}}{JSON}"}\
%varsNotEmpty{, "origin.address":"%enc{%map{origin.address}}{JSON}"}\
%varsNotEmpty{, "realm":"%enc{%map{realm}}{JSON}"}\
%varsNotEmpty{, "url.path":"%enc{%map{url.path}}{JSON}"}\
%varsNotEmpty{, "url.query":"%enc{%map{url.query}}{JSON}"}\
%varsNotEmpty{, "request.method":"%enc{%map{request.method}}{JSON}"}\
%varsNotEmpty{, "request.body":"%enc{%map{request.body}}{JSON}"}\
%varsNotEmpty{, "request.id":"%enc{%map{request.id}}{JSON}"}\
%varsNotEmpty{, "action":"%enc{%map{action}}{JSON}"}\
%varsNotEmpty{, "request.name":"%enc{%map{request.name}}{JSON}"}\
%varsNotEmpty{, "indices":%map{indices}}\
%varsNotEmpty{, "opaque_id":"%enc{%map{opaque_id}}{JSON}"}\
%varsNotEmpty{, "x_forwarded_for":"%enc{%map{x_forwarded_for}}{JSON}"}\
%varsNotEmpty{, "transport.profile":"%enc{%map{transport.profile}}{JSON}"}\
%varsNotEmpty{, "rule":"%enc{%map{rule}}{JSON}"}\
%varsNotEmpty{, "event.category":"%enc{%map{event.category}}{JSON}"}\
}%n

logger.xpack_security_audit_logfile.name = org.elasticsearch.xpack.security.audit.logfile.LoggingAuditTrail
logger.xpack_security_audit_logfile.level = info
logger.xpack_security_audit_logfile.appenderRef.audit_rolling.ref = audit_rolling
logger.xpack_security_audit_logfile.additivity = false

logger.xmlsig.name = org.apache.xml.security.signature.XMLSignature
logger.xmlsig.level = error
logger.samlxml_decrypt.name = org.opensaml.xmlsec.encryption.support.Decrypter
logger.samlxml_decrypt.level = fatal
logger.saml2_decrypt.name = org.opensaml.saml.saml2.encryption.Decrypter
logger.saml2_decrypt.level = fatal

３．docker-compose.ymlファイルの準備
docker-compose.ymlはこんな感じで、ElasticsearchとKibanaとfilebeatを動かしています。

docker-compose.yml
version: "3"

services:
  elasticsearch:
    build: .
    environment:
      - discovery.type=single-node
      - cluster.name=docker-cluster
      - bootstrap.memory_lock=true
      - "ES_JAVA_OPTS=-Xms512m -Xmx512m"
    ulimits:
      memlock:
        soft: -1
        hard: -1
    ports:
      - 9200:9200
    volumes:
      - data01:/usr/share/elasticsearch/logs
  kibana:
    image: docker.elastic.co/kibana/kibana:7.10.0
    ports:
      - 5601:5601
  filebeat:
    build:
      context: .
      dockerfile: ./filebeat/Dockerfile
    volumes:
      - data01:/usr/share/elasticsearch/logs

volumes:
  data01:
    driver: "local"

4．Filebeat
logをFilebeat経由でindexに登録する設定をします。

filebeat/Dockerfile

FROM docker.elastic.co/beats/filebeat:7.10.0

COPY ./filebeat/config/filebeat.yml /usr/share/filebeat/filebeat.yml
USER root
RUN chown root:filebeat /usr/share/filebeat/filebeat.yml
USER filebeat

COPY ./filebeat/config/elasticsearch.yml /usr/share/filebeat/modules.d/elasticsearch.yml
USER root
RUN chown root:filebeat /usr/share/filebeat/modules.d/elasticsearch.yml
USER filebeat

設定ファイルはこんな感じです。

filebeat/config/elasticsearc.yml
#https://www.elastic.co/guide/en/beats/filebeat/master/filebeat-module-elasticsearch.html
  server:
    enabled: true
    var.paths:
      - /usr/share/elasticsearch/logs/*.log          # Plain text logs
      - /usr/share/elasticsearch/logs/*_server.json  # JSON logs

  gc:
    var.paths:
      - /usr/share/elasticsearch/logs/gc.log.[0-9]*
      - /usr/share/elasticsearch/logs/gc.log

  slowlog:
    var.paths:
      - /usr/share/elasticsearch/logs/*_index_search_slowlog.log     # Plain text logs
      - /usr/share/elasticsearch/logs/*_index_indexing_slowlog.log   # Plain text logs
      - /usr/share/elasticsearch/logs/*_index_search_slowlog.json    # JSON logs
      - /usr/share/elasticsearch/logs/*_index_indexing_slowlog.json  # JSON logs
filebeat/config/filebeat.yml
#https://www.elastic.co/guide/en/beats/filebeat/current/filebeat-reference-yml.html
filebeat.modules:
- module: elasticsearch

filebeat.inputs:
- type: log
  enabled: true
  paths:
    - /usr/share/elasticsearch/logs/docker-cluster_index_search_slowlog.log

# FilebeatのConfig設定
filebeat.config.modules:
  enabled: true
  path: ${path.config}/modules.d/*.yml

# Output先の設定
output.elasticsearch:
  hosts: ["elasticsearch:9200"]
  index: "slowlog-%{[agent.version]}-%{+yyyy.MM.dd}"

setup.template.name: "slowlog"
setup.template.pattern: "slowlog-*"

setup.kibana:
  host: "kibana:5601"

5．ビルド＆起動

bash
$ docker-compose build
$ docker-compose up -d

6．filebeatのセットアップ
dockerコンテナが起動後に、filebeatのセットアップを行います。

bash
# filebeatのコンテナ名を確認する
$ docker ps

# dockerの中に入る
$ docker exec -it {NAME}_filebeat_1 bash

#filebeatのセットアップ
$ filebeat setup -e

７．Slowlog設定
kibanaから行います。
http://localhost:5601/app/dev_tools#/console

すべてのクエリが出力されるように0msに設定します。
※itemインデックスの作成は省略しています。

PUT /item/_settings
{
  "index.search.slowlog.threshold.query.warn": "10s",
  "index.search.slowlog.threshold.query.info": "5s",
  "index.search.slowlog.threshold.query.debug": "0ms",
  "index.search.slowlog.threshold.query.trace": "500ms",
  "index.search.slowlog.level": "debug"
}

何度かクエリを発行しログをためます。

GET /item/_search
{
  "query": {
    "match_all": {}
  }
}

８．Slowlog確認
まずは直接ログを確認します。

bash
# Elasticsearchのコンテナ名を確認する
$ docker ps

# dockerの中に入る
$ docker exec -it {NAME}_elasticsearch_1 bash

# logsを確認
$ ls -l ./logs

docker-cluster_index_search_slowlog.logファイルがありますので、Slowlogが出力されていることをご確認ください。

9．Slowlogのindex確認
自動的に作成されたSlowlogのindexを確認します。

GET /_cat/indices

filebeat-7.10.0-YYYY.MM.DD-000001のindexが作成されているので情報を確認します。

GET /filebeat-7.10.0-YYYY.MM.DD-000001/_search
{
  "sort": [
    {
      "@timestamp": {
        "order": "desc"
      }
    }
  ]
}

Slowlogが確認できると思います。

最後に

Slowlogを見始めたのはつい先日のElasticsearch初心者ではありますが、何とかSlowlogを出力できるようになりました。重要なのはここからでSlowlogに出てきたクエリの分析とチューニングですよね。そしてチューニングして速度改善ができたときの達成感が嬉しいと思えるのは皆さん同じだと思います。
皆さんのパフォーマンス改善に少しでもお役にたてれば嬉しいです。