Aurora PostgreSQLのスロークエリログをAmazon ESに取り込んでみた

はじめに

SQLクエリごとの応答時間や時系列での推移を可視化できるとアプリケーションの性能改善に繋がりますよね^^

本投稿は、Aurora PostgreSQLのスロークエリログをAmazon Elasticsearch Serviceに取り込んでみたという内容です。

※ Aurora PostgreSQLの監査ログはAurora PostgreSQLの監査ログをAmazon ESに取り込んでみたを参考にしてみてください！

【参考】
・ Amazon Auroraの特徴 PostgreSQL互換エディション

利用環境

product	version
logstash (OSS版)	7.7.1
Java (Corretto)	11.0.8
OS(EC2)	Amazon Linux2 (t3.small)
AMI ID	ami-03657b56516ab7912
Elasticsearch	7.7 (latest)
PostgreSQL	11.6
Region	us-east-2

※投稿時点における最新版を採用しています。

【構成図】

• CloudWatch Logsに出力したAurora PostgreSQLのログをLogstashがInputしています。

前提条件

• Elasticsearchへのログ出力にはElastic社のETLツールであるLogstashを利用しています。
• Logstashのバージョンは、Amazon Elasticsearch Serviceの最新バージョンに合わせています。
• Amazon Elasticsearch ServiceはOSS版のため、LogstashもOSS版としています。
• Amazon Elasticsearch Service(以下、Amazon ES)は、パブリックアクセスとしています。
  (IPアドレスによるホワイトリスト制御でセキュリティを確保しています)
• Aurora PostgreSQLのDBクラスタは事前に構築された状態としています。

【参考】
・ Logstashとは

実施内容

1. IAM Role作成
2. ログ記録の設定
3. スロークエリログ出力設定
4. スロークエリログの確認
5. Amazon ESのドメイン作成
6. Logstashの構築
7. Kibanaでの各設定

1. IAM Role作成

• EC2として構築するLogstashに割り当てるIAM Roleを作成します。
• logatashのEC2に割り当てるIAM RoleとしてRoleForEC2というロールを作成し、
  CloudWatchLogsReadOnlyAccessというIAM Policyを割り当てます。

CloudWatchLogsReadOnlyAccess

{
    "Version": "2012-10-17",
    "Statement": [
        {
            "Action": [
                "logs:Describe*",
                "logs:Get*",
                "logs:List*",
                "logs:StartQuery",
                "logs:StopQuery",
                "logs:TestMetricFilter",
                "logs:FilterLogEvents"
            ],
            "Effect": "Allow",
            "Resource": "*"
        }
    ]
}

2. ログ記録の設定

• [RDS] > [データベース]をクリックし、ログを出力したいDBクラスタ名をチェックします。[変更]をクリックします。

• [追加設定] > [ログのエクスポート]でPostgresqlログにチェックを入れて保存します。

• [設定]タブで[CloudWatch Logs]が以下のようになっていれば、CloudWatch Logsのロググループが自動生成されてます。

• [CloudWatch] > [ロググループ]をクリックし、/aws/rds/cluster/<DBクラスタ名>/postgresqlというロググループであればOKです。

【参考】
・ Aurora PostgreSQLログの発行

3. スロークエリログ出力設定

• PostgreSQLのログ記録をオンにした状態では、エラーログのみが記録されます。
  ※ 全般、スロークエリ、監査のログは追加設定が必要です。
• パラメータグループで設定を追加しますが、DBインスタンスにアタッチされたデフォルトのパラメータグループは設定変更が出来ません。
• スロークエリログの出力設定のためのパラメータグループを以下の内容で作成します。

【パラメータグループの設定】

項目	値
パラメータグループファミリー	aurora-postgresql11
タイプ	DB Cluster Parameter Group
グループ名	testpostgresql11-paramatergroup (任意)
説明	testpostgresql11 (任意)

• 上記で作成したパラメータグループにて、log_min_duration_statementのパラメータを編集します。
  ※ 設定した数値(ミリ秒)を閾値とし、クエリの応答時間が指定値を超えるとログに記録されます。(デフォルト無効です。)

• 今回は、値に0を設定して、保存します。
  ※ この場合、全てのクエリにおいて、応答時間が記録されます。どんなログが出るか見てましょう。

• 作成したパラメータグループを適用するDBクラスタ名をチェックし、[変更]をクリックします。

• [追加設定] > [DBクラスターのパラメータグループ]で作成したパラメータグループを指定します。

• [変更のスケジューリング]を今すぐとして、[クラスターの変更]をクリックします。
  ※ 本番稼働中のDBクラスターで再起動を伴う変更を保留している場合は注意してください。

【参考】
・ RDSのデフォルトパラメータグループを変更する
・ postgresql on RDSでスロークエリを出力する

4. スロークエリログの確認

• [Systems Manager] > [Session Manager]からLogstash用のEC2に接続します。
• EC2から以下のコマンド操作でDBに接続し、testtableという名前のテーブルを作成します。
• 適当なデータ(name: guest01、text: test01)をINSERTし、その後SELECTでクエリします。
  ※ EC2からPostgreSQLにTCP5432で通信許可されている状態としています。

$ psql -h [Auroraのエンドポイント] -U [マスターユーザ名]
Password for user postgres: xxxxxxxxxxx(パスワード)
psql (9.2.24, server 11.6)
WARNING: psql version 9.2, server version 11.0.
         Some psql features might not work.
SSL connection (cipher: ECDHE-RSA-AES256-GCM-SHA384, bits: 256)
Type "help" for help.

postgres=> CREATE TABLE testtable (name VARCHAR(255), text VARCHAR(255));
postgres=> INSERT INTO testtable (name, text) values ('guest01', 'test01');
postgres=> SELECT * FROM testtable;

• [CloudWatch Logs]のロググループ配下のログストリームに以下のようなログが出力されます。(こちらがスロークエリログです。)

少し余談になりますが、デフォルトのログフォーマットはlog_line_prefixで%t:%r:%u@%d:[%p]:と定義されています。

【参考】
・ log_line_prefixの説明

5. Amazon ESのドメイン作成

• 下記内容でAmazon ESのドメインを作成します。

項目	値
リージョン	us-east-2
デプロイタイプ	開発およびテスト
Elasticsearchのバージョン	7.7 (latest)
Elasticsearchのドメイン	test-es
インスタンスタイプ	t3.small.elasticsearch
ノードの数	1
データノードのストレージタイプ	EBS
EBS ボリュームタイプ	汎用(SSD)
EBS ボリュームサイズ	10 GiB
自動スナップショットの開始時間	00:00 UTC (デフォルト)
ネットワークアクセス	パブリックアクセス
細かいアクセスコントロールを有効化	無効
Amazon Cognito認証を有効化	無効
ドメインアクセスポリシー	カスタムアクセスポリシー (IPv4アドレス)
ドメインへのすべてのトラフィックにHTTPSを要求	有効
ノード間の暗号化	無効
保管時のデータの暗号化の有効化	無効

※アクセスポリシーに追加するIPは、Amazon ESにアクセスする自宅IPとLogstashのIPになります。

ドメインアクセスポリシー

{
  "Version": "2012-10-17",
  "Statement": [
    {
      "Effect": "Allow",
      "Principal": {
        "AWS": "*"
      },
      "Action": "es:*",
      "Resource": "arn:aws:es:us-east-2:<AWSアカウント>:domain/test-es/*",
      "Condition": {
        "IpAddress": {
          "aws:SourceIp": [
            "<自宅IP>/32",
            "<LogstasのEIP>/32"
          ]
        }
      }
    }
  ]
}

6. Logstashの構築

• Logstashの構築手順は、Amazon Corretto 11で構築するLogstashになります。

• スロークエリログは、正規表現パターンを使って以下のようなフィールドと値にパースします。

フィールド	値(サンプル)	データ型
タイムスタンプ	2020-10-11 13:52:40	日付型
タイムゾーン	UTC	文字列型 (keyword)
IPアドレス	172.31.41.200	IP型
ポート番号	56984	文字列型 (keyword)
ユーザ名	postgres	文字列型 (keyword)
データベース名	postgres	文字列型 (keyword)
プロセスID	1622	文字列型 (keyword)
ログレベル	LOG	文字列型 (keyword)
クエリ応答時間	0.335	数値型 (float)
クエリ文	select * from testtable;	文字列型 (keyword)

• Grokパターン(/etc/logstash/grok_patterns/aurora-postgresql-slowlog)を保存するディレクトリを作成します。

$ sudo mkdir /etc/logstash/grok_patterns
$ sudo vi /etc/logstash/grok_patterns/aurora-postgresql-slowlog

• 下記の内容を上記のGrokパターンファイルに記述します。

aurora-postgresql-slowlog

### PosgreSQL slowLog
POSTGRESQL_SLOWLOG %{TIMESTAMP_ISO8601:timestamp}\s%{TZ:timezone}:%{IP:ipaddress}\(%{NUMBER:src_port}\):%{WORD:username}@%{WORD:database}:\[%{NUMBER:process_id}\]:%{WORD:log_level}:\s+duration:\s%{NUMBER:duration}\sms\s+%{WORD:action}(?:\s%{NOTSPACE:name})?:\s+%{GREEDYDATA:statement}

• 下記のパイプライン構成ファイル(/etc/logstash/conf.d/logstash.conf)を作成します。
  (このタイミングではLogstashのプロセスは起動しません)

$ sudo vi /etc/logstash/conf.d/logstash.conf

• 下記の内容を上記のパイプライン構成ファイルに記述します。

logstash.conf

input {
  cloudwatch_logs {
    log_group => [ "/aws/rds/cluster/database-1/postgresql" ]
    region => "us-east-2"
    interval => 5
  }
}

filter {
  if "duration:" in [message] {
    ### 読み込むGrok Patternファイルを"patterns_dir"で指定
    grok {
      patterns_dir => [ "/etc/logstash/grok_patterns" ]
      match => { "message" => "%{POSTGRESQL_SLOWLOG}" }
    }
    ### dateフィールドから@timestampを抽出
    date {
      match => [ "timestamp", "yyyy-MM-dd HH:mm:ss" ]
      timezone => "UTC"
      target => "@timestamp"
    }
    ### @timstampから日本時間を抽出
    ruby {
      code => "event.set('[@metadata][local_time]',event.get('[@timestamp]').time.localtime.strftime('%Y-%m-%d'))"
    }
    ### document_idに利用する一意のIDを作成
    fingerprint {
      source => "message"
      target => "[@metadata][fingerprint]"
      method => "MURMUR3"
    }
    ### デフォルトの型がstringのため、フィールド定義で定義した型に変換
    mutate {
      ### typeフィールドを追加
      add_field => { "type" => "aurora-postgre-slowlog-cwl" }    
      ### 不要なフィールドを削除
      remove_field => [ "timestamp", "timezone" ]
    }
  }
}

output {
  if "duration:" in [message] {
    ### 出力先のAmazonESのIndexを指定
    elasticsearch {
      hosts => [ "https://search-test-es-xxxxxxxxxxxxxxxxxxxxxx.us-east-2.es.amazonaws.com:443" ]
      index => "%{type}-%{[@metadata][local_time]}"
      document_id => "%{[@metadata][fingerprint]}"
      ilm_enabled => false
    }
  }
}

【参考】
・ Logstashの実践的な説明
・ cloudwatch-logs input
・ grok filter
・ date filter
・ ruby filter
・ fingerprint filter
・ mutate filter
・ elasticsearch output

7. Kibanaでの各設定

• Amazon ESのKibanaのURLをクリックします。
  

• [Dev Tools]のConsoleからAurora PostgreSQLのスロークエリログのIndex Templateを追加します。
  

• 上記で張り付けたIndex Templateは以下の通りです。

index_templete_aurora-postgre-slowlog-cwl

PUT _template/aurora-postgre-slowlog-cwl
{
  "index_patterns": ["aurora-postgre-slowlog-cwl-*"],
  "settings": {
    "number_of_shards": 1,
    "number_of_replicas" : 1
  },
  "mappings": {
    "properties": {
      "@timestamp": {
        "type": "date"
      },
      "@version" : {
        "type" : "keyword"
      },
      "ipaddress" : {
        "type" : "ip"
      },
      "src_port" : {
        "type" : "keyword"
      },
      "username" : {
        "type" : "keyword"
      },
      "database" : {
        "type" : "keyword"
      },
      "process_id" : {
        "type" : "keyword"
      },
      "log_level" : {
        "type" : "keyword"
      },
      "duration" : {
        "type" : "float"
      },
      "action" : {
        "type" : "keyword"
      },
      "name" : {
        "type" : "keyword"
      },
      "statement" : {
        "type": "text",
        "fields": {
          "keyword": {
            "type": "keyword",
            "ignore_above": 8191
          }
        }
      },
      "type" : {
        "type" : "keyword"
      },
      "tags" : {
        "type" : "keyword"
      },
      "message" : {
        "type" : "text"
      },
      "cloudwatch_logs" : {
        "properties" : {
          "event_id" : {
            "type" : "keyword"
          },
          "ingestion_time" : {
            "type" : "date"
          },
          "log_group" : {
            "type" : "keyword"
          },
          "log_stream" : {
            "type" : "keyword"
          }
        }
      }
    }
  }
}

※クエリ文が含まれるフィールド(statement)は、全文検索ができるようtext型で格納しつつ、グラフ化できるようkeyword型でも格納しています。
※Luceneのトークンの上限値である32,766バイトを超えて破棄されないよう、推奨値8,191で制限しています。
※ durationは応答時間(ミリ秒)が入るフィールドなので、float型とします。

• Logstashを起動します。

logstash_start

$ sudo systemctl start logstash
$ sudo systemctl status logstash
● logstash.service - logstash
   Loaded: loaded (/etc/systemd/system/logstash.service; disabled; vendor preset: disabled)
   Active: active (running) since Sun 2020-02-23 17:11:21 UTC; 4min 42s ago
 Main PID: 32168 (java)
   CGroup: /system.slice/logstash.service
           └─32168 /bin/java -Xms1g -Xmx1g -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -Djava.awt.h...

Feb 23 17:12:00 ip-172-31-37-204.ec2.internal logstash[32168]: [2020-02-23T17:12:00,242][INFO ][logstash.outputs.elasticsearch][main] New Elastic...:443"]}
Feb 23 17:12:00 ip-172-31-37-204.ec2.internal logstash[32168]: [2020-02-23T17:12:00,282][INFO ][logstash.filters.geoip   ][main] Using geoip data....mmdb"}
Feb 23 17:12:00 ip-172-31-37-204.ec2.internal logstash[32168]: [2020-02-23T17:12:00,332][INFO ][logstash.outputs.elasticsearch][main] Using defau...emplate
Feb 23 17:12:00 ip-172-31-37-204.ec2.internal logstash[32168]: [2020-02-23T17:12:00,396][INFO ][logstash.outputs.elasticsearch][main] Attempting ...field"=
Feb 23 17:12:00 ip-172-31-37-204.ec2.internal logstash[32168]: [2020-02-23T17:12:00,460][WARN ][org.logstash.instrument.metrics.gauge.LazyDelegatingGaug...
Feb 23 17:12:00 ip-172-31-37-204.ec2.internal logstash[32168]: [2020-02-23T17:12:00,467][INFO ][logstash.javapipeline    ][main] Starting pipeline {:pip...
Feb 23 17:12:01 ip-172-31-37-204.ec2.internal logstash[32168]: [2020-02-23T17:12:01,418][INFO ][logstash.javapipeline    ][main] Pipeline started..."main"}
Feb 23 17:12:01 ip-172-31-37-204.ec2.internal logstash[32168]: [2020-02-23T17:12:01,497][INFO ][logstash.agent           ] Pipelines running {:co...es=>[]}
Feb 23 17:12:01 ip-172-31-37-204.ec2.internal logstash[32168]: [2020-02-23T17:12:01,736][INFO ][logstash.agent           ] Successfully started L...=>9600}
Feb 23 17:12:14 ip-172-31-37-204.ec2.internal logstash[32168]: /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/logstash-filter-fingerprint-3.2...recated
Hint: Some lines were ellipsized, use -l to show in full.

• Kibanaの [Management] > [Index Patterns]でCreate index patternをクリックします。

• aurora-postgre-slowlog-cwl-*という名前でIndex Patternを作成します。
  

• @timestampを指定します。
  

• [Discover]を開き、Index Patternにaurora-postgre-slowlog-cwl-*を指定します。

• デフォルトでは直近15分間のログが表示されます。表示されていればOKです。
  

• 取り込んだログは以下のような感じです。

aurora-postgre-slowlog_sample

{
  "_index": "aurora-postgre-slowlog-cwl-2020-10-11",
  "_type": "_doc",
  "_id": "711173058",
  "_version": 2,
  "_score": null,
  "_source": {
    "src_port": "56984",
    "ipaddress": "172.31.41.200",
    "database": "postgres",
    "cloudwatch_logs": {
      "event_id": "35735257352278506729913774955467933061520202697351233536",
      "log_group": "/aws/rds/cluster/database-1/postgresql",
      "ingestion_time": "2020-10-11T13:52:42.064Z",
      "log_stream": "database-1-instance-1.0"
    },
    "@timestamp": "2020-10-11T13:52:40.000Z",
    "process_id": "1622",
    "duration": "0.335",
    "@version": "1",
    "log_level": "LOG",
    "username": "postgres",
    "type": "aurora-postgre-slowlog-cwl",
    "message": "2020-10-11 13:52:40 UTC:172.31.41.200(56984):postgres@postgres:[1622]:LOG:  duration: 0.335 ms  statement: select * from testtable;",
    "statement": "select * from testtable;"
  },
  "fields": {
    "cloudwatch_logs.ingestion_time": [
      "2020-10-11T13:52:42.064Z"
    ],
    "@timestamp": [
      "2020-10-11T13:52:40.000Z"
    ]
  },
  "sort": [
    1602424360000
  ]
}

まとめ

いかがでしたでしょうか？
冒頭のダッシュボードの作り方が全然出てこないじゃないか！？
というコメントがありそうですが、Kibanaでのダッシュボードは創意工夫溢れるものなので
取り込んだログをアドホックに分析し、それぞれの環境に合わせて素敵なダッシュボードを
作って頂けると幸いです^-^

以下のようなサンプルデータを取り込んでみて色々と試してみるのも良いかと思います!

【参考】
・ PostgreSQLサンプルデータ