AWS のALB (ロードバランサー)設定

GUI から設定がわかりやすいと思います。 ロードバランサーはリクエストをその特定のグループに分散させることができる機能. 名前とリクエストを分散させるグループなどを決める。 またリクエストの分散させるグループ内での個別でインスタンスの状況に応じてアラームを投げることを別途設定可能。 続きを読む

カテゴリー 未分類 | タグ

AWS CLIで構築するAWS WAF環境

こんにちは、坂巻です。 今回は、AWS WAFをAWS CLIで構築する方法をご紹介します。 前提. 本エントリの記載を実施するには、以下が必要となります。 ACL CLIでAWSに接続ができること; ALBとその配下にWebサーバが存在すること; Webサイトにアクセス可能な日本のリージョン以外で稼働するEC2. 要件. 構成図内の赤 … 続きを読む

「おや…ELBのようすが…?」という時に確認すること

私の経験上、「ELBがおかしいぞ!AWSしっかりしろや!」と思ったら、よくよく調べると実装がダメなだけだったというパターンがよくあるのでまとめたい。

あ、ELBと言いながら厳密にはALBの話をメインにします。

CASE 1. 「バックエンドは生きてるはずなのにヘルスチェックが失敗する!」

つまり以下のような症状が出る状況

  1. ヘルスチェックが失敗する
  2. バックエンドに直接アクセスしたら普通にうまくいく
  3. バックエンドのアクセスログ見たら、ヘルスチェックに200を返している

というパターン。
「バックエンドは生きてるしヘルスチェックにも200を返してる!それなのに失敗扱いなんてELBの不具合だ!」と思いたくなる気持ちはわかるが、まずは落ち着いてヘルスチエックの成否の基準を見直そう。

ターゲットグループのヘルスチェック – Elastic Load Balancing

ターゲットが応答タイムアウト期間内に応答するのを待ちます。

つまりバックエンドが200を返していようが、タイムアウトしていたらヘルスチェック的には失敗なのだ。
とりあえずバックエンドのアクセスログから処理時間を確認してみよう。まさか処理時間を出力するようにログフォーマットを設定してないなんて言わないよな?

ちなみにステータスコード200というのも注意が必要で、みんな大好きApacheのドキュメントにこんな記載がある

mod_log_config – Apache HTTP サーバ バージョン 2.4

%s ステータス。内部でリダイレクトされたリクエストは、元々の リクエストのステータス — 最後のステータスは %>s

すこぶる分かりにくい文章だが、要するに
・ %s -> リダイレクトが発生した際に3XXのコードを出力する
・ %>s -> リダイレクトが発生した際に3XXのコードを出力せず、リダイレクト後の処理の結果のコードを出力する

というわけだ。そのため、「200を返してるし、CPU使用率も上がってないから大丈夫なはず」と思ってたら実はリダイレクトしまくってタイムアウトしてた、というパターンもある。
そして、筆者の記憶が確かならApacheではデフォルトで%>sが設定されている。

というわけでこの症状の場合は、ELBの不具合とヘルスチェックのタイムアウト、どちらの方がありえそうか考えて調査をはじめてみよう。

CASE 2. 「HTTPCode_ELB_5XX_Countメトリクスが出てる!」

「5XXはサーバサイドのエラー…ELBが5XXエラーを出しているということは…ELBの不具合や!」と思いたくなる気持ちはわかるが、まあ落ち着いてほしい。
私も過去に502 Bad Gatewayに悩まされ、AWSにも問い合わせたりしたが、結局のところバックエンドの実装がクソだったのが原因だった。
だから落ち着いてまずはこれを見てほしい。

Application Load Balancer のトラブルシューティング – Elastic Load Balancing

うん、分かりにくいな。
5XX系のエラーに絞って、頑張って解説してみよう。

HTTP 502: Bad Gateway

そもそも502 Bad Gatewayというもの自体が分かりにくい。
Wikipediaによると

不正なゲートウェイ。ゲートウェイ・プロキシサーバは不正な要求を受け取り、これを拒否した。

これで理解できる人間はほぼいないだろう。
502 Bad Gatewayについてはこちらのページの解説が分かりやすい。

502Bad Getewayの原因と意味について | ぷろめし|プログラミングよりも飯が好き

ELBに当てはめて考えるなら、「ELBからバックエンドにリクエストを投げたが、解せないレスポンスが帰ってきた」という状況である。
つまり、ELBがイかれている可能性もあるが、バックエンドがイかれたレスポンスを返したり途中でコネクションをブッチしている可能性もあるのだ。

つまり、502 Bad Gatewayが現れたらバックエンドからのレスポンスがどうなってるかを見直した方がいいだろう。

HTTP 503: Service Unavailable

一時的に使えないというやつ。
上記のドキュメントにはターゲットグループにインスタンスが無いという場合しか書いてないが、実は他にも503が発生する可能性はある。

ELBはトラフィック量に合わせて自動でスケールするが、あまりに急激にトラフィックが増加した場合にはスケールが間に合わなくなることがある。そういう場合にはELBの処理能力が足りなくなって503が発生することになる。
ほっといたらそのうちELBがスケールして解決するが、「一瞬たりとも落とせないんだ!」という時は予めPre-warmingを申し込んでおこう。

Elastic Load Balancing の暖気申請について | Developers.IO

見積もりがガバガバだと「ほんまにPre-warming必要か?」と突っ込まれることもあるので、真面目に見積もろう。

HTTP 504: Gateway Timeout

これは分かりやすい。
ELB -> バックエンドの通信がタイムアウトしたということである。
バックエンドの処理を見直すか、タイムアウト時間を伸ばすかの二択だが、基本的にはバックエンドの処理を見直す方が健全である。

色々調べたが、どう考えても実装に問題はない時は…

AWS側の問題という可能性もあるので、問い合わせよう。

続きを読む

コピペで使えるELBのアクセスログ解析による事象分析 (ShellScript, Athena)

アクセスログ解析

ELBのアクセスログの事象分析について、ShellScriptとAthenaを用いた実行例についてまとめます。

ShellScript

CLB

No.1 : レスポンスが正常に受け取れていないELBのレスポンスコード毎のカウント

$ awk '$10 == "-"' * | awk '{print $9}' | sort | uniq -c

No.2 : ELBのレスポンスコード毎の数集計

$ awk '{print $8}' *.log | sort | uniq -c

No.3 : 504のレコード一覧

$ awk '$8 == 504'

No.4 : 504がどのELBノードから多く出力されているか

$ grep ' 504 ' *.log | awk '{print $3}' | sed 's/:.*//' | sort | uniq -c

No.5 : バックエンドから正常に応答が受け取れていない時

$ awk '{if (! int($5) < 0) {print $0}}' * | egrep '2018-01-2[45]'

No.6 : target_processing_time の3つの統計値(最小値、最大値、平均)と -1 の値を取った回数を表示する

$ awk '{ print $4,$8,$9,$6 }' * | sort | sed -e 's/ /!!/' -e 's/ /!!/' | awk '{if(count[$1]==0) min[$1]=100; count[$1]+=1; if(max[$1]<$2&&$2!=-1) max[$1]=$2; if(min[$1]>$2&&$2!=-1) min[$1]=$2; if($2!=-1)sum[$1]+=$2; else minus[$1]+=1;} END{for(k in count)print k,", count:",count[k],", max:",max[k],", min:",min[k],", avg:",sum[k]/count[k],", -1:",minus[k];}' | sort -k4nr

No.7 : response_processing_time の3つの統計値(最小値、最大値、平均)と -1 の値を取った回数を表示する

$ awk '{ print $4,$8,$9,$7 }' * | sort | sed -e 's/ /!!/' -e 's/ /!!/' | awk '{if(count[$1]==0) min[$1]=100; count[$1]+=1; if(max[$1]<$2&&$2!=-1) max[$1]=$2; if(min[$1]>$2&&$2!=-1) min[$1]=$2; if($2!=-1)sum[$1]+=$2; else minus[$1]+=1;} END{for(k in count)print k,", count:",count[k],", max:",max[k],", min:",min[k],", avg:",sum[k]/count[k],", -1:",minus[k];}' | sort -k4nr

No.8 : 最も多いリクエスト元のELBノードIPアドレスのリクエスト数

$ awk '{print $3}' * | awk -F ":" '{print $1}' | sort | uniq -c | sort -r| head -n 10 

No.9 : 時間毎のリクエスト数

grep中の二重引用符内は適宜日付等を入れて絞り込み

grep -r "" . | cut -d [ -f2 | cut -d] -f1 | awk -F: '{print $2":00"}' | sort -n | uniq -c

No.10 : 分単位でのリクエスト数

grep中の二重引用符内は適宜日付等を入れて絞り込み

$ grep "" * | cut -d [ -f2 | cut -d ] -f1 | awk -F: '{print $2":"$3}' | sort -nk1 -nk2 | uniq -c | awk '{ if ($1 > 10) print $0}'

No.11 : ユーザーエージェント毎のランキング

$ awk '{split($0, array, """); agent=array[4]; print agent}' * | sort | uniq -c | sort -nr | head

No.12 : TLSでクライアントが最も使った暗号スイートのランキング

$ awk '{split($0, array, """); afterUserAgent=array[5]; print afterUserAgent}' * | awk '{print $1}' | sort | uniq -c | sort -nr | head -5

No.13 : TLSでクライアントが最も使ったTLSバージョンのランキング

$ awk '{split($0, array, """); afterUserAgent=array[5]; print afterUserAgent}' * | awk '{print $2}' | sort | uniq -c | sort -nr | head

No.14 : TLSでクライアントが最も使ったプロトコルと暗号スイートのランキング

$ awk '{split($0, array, """); proto=array[1]; afterUserAgent=array[5]; print proto afterUserAgent}' * | awk '{print $1 " " $13}' | sort | uniq -c | sort -nr | head

ALB

No.1 : target_processing_time の3つの統計値(最小値、最大値、平均)と -1 の値を取った回数を表示する

 $ awk '{ print $5,$9,$10,$7 }' * | sort | sed -e 's/ /!!/' -e 's/ /!!/' | awk '{if(count[$1]==0) min[$1]=100; count[$1]+=1; if(max[$1]<$2&&$2!=-1) max[$1]=$2; if(min[$1]>$2&&$2!=-1) min[$1]=$2; if($2!=-1)sum[$1]+=$2; else minus[$1]+=1;} END{for(k in count)print k,", count:",count[k],", max:",max[k],", min:",min[k],", avg:",sum[k]/count[k],", -1:",minus[k];}' | sort -k4nr

No.2 : response_processing_time の3つの統計値(最小値、最大値、平均)と -1 の値を取った回数を表示する

$ awk '{ print $5,$9,$10,$8 }' * | sort | sed -e 's/ /!!/' -e 's/ /!!/' | awk '{if(count[$1]==0) min[$1]=100; count[$1]+=1; if(max[$1]<$2&&$2!=-1) max[$1]=$2; if(min[$1]>$2&&$2!=-1) min[$1]=$2; if($2!=-1)sum[$1]+=$2; else minus[$1]+=1;} END{for(k in count)print k,", count:",count[k],", max:",max[k],", min:",min[k],", avg:",sum[k]/count[k],", -1:",minus[k];}' | sort -k4nr

Athena

以下、全て CLB を前提とします。
また、以下のような、デフォルトで生成されている sampledb データベースの elb_logs テーブルを使用します。

CREATE EXTERNAL TABLE `elb_logs`(
  `request_timestamp` string COMMENT '', 
  `elb_name` string COMMENT '', 
  `request_ip` string COMMENT '', 
  `request_port` int COMMENT '', 
  `backend_ip` string COMMENT '', 
  `backend_port` int COMMENT '', 
  `request_processing_time` double COMMENT '', 
  `backend_processing_time` double COMMENT '', 
  `client_response_time` double COMMENT '', 
  `elb_response_code` string COMMENT '', 
  `backend_response_code` string COMMENT '', 
  `received_bytes` bigint COMMENT '', 
  `sent_bytes` bigint COMMENT '', 
  `request_verb` string COMMENT '', 
  `url` string COMMENT '', 
  `protocol` string COMMENT '', 
  `user_agent` string COMMENT '', 
  `ssl_cipher` string COMMENT '', 
  `ssl_protocol` string COMMENT '')
ROW FORMAT SERDE 
  'org.apache.hadoop.hive.serde2.RegexSerDe' 
WITH SERDEPROPERTIES ( 
  'input.regex'='([^ ]*) ([^ ]*) ([^ ]*):([0-9]*) ([^ ]*):([0-9]*) ([.0-9]*) ([.0-9]*) ([.0-9]*) (-|[0-9]*) (-|[0-9]*) ([-0-9]*) ([-0-9]*) \"([^ ]*) ([^ ]*) (- |[^ ]*)\" ("[^"]*") ([A-Z0-9-]+) ([A-Za-z0-9.-]*)$') 
STORED AS INPUTFORMAT 
  'org.apache.hadoop.mapred.TextInputFormat' 
OUTPUTFORMAT 
  'org.apache.hadoop.hive.ql.io.HiveIgnoreKeyTextOutputFormat'
LOCATION
  's3://athena-examples-us-west-2/elb/plaintext'
TBLPROPERTIES (
  'transient_lastDdlTime'='1480278335');

HTTPステータスコードが200のレコード一覧

SELECT * 
FROM elb_logs
WHERE elb_response_code <> '200'
ORDER BY request_timestamp;

ELB毎のリクエスト数

SELECT elb_name,
         count(*) AS request_count
FROM elb_logs
GROUP BY elb_name
ORDER BY request_count DESC;

ELB毎のリクエスト数(期間指定)

SELECT elb_name,
         count(*) AS request_count
FROM elb_logs
WHERE request_timestamp >= '2014-01-01T00:00:00Z'
        AND request_timestamp < '2016-01-01T00:00:00Z'
GROUP BY elb_name
ORDER BY request_count DESC;

ELB毎のリクエスト数(期間+ELB 指定)

SELECT elb_name,
         count(*) AS request_count
FROM elb_logs
WHERE elb_name LIKE 'elb_demo_008'
        AND request_timestamp >= '2014-01-01T00:00:00Z'
        AND request_timestamp < '2016-01-01T00:00:00Z'
GROUP BY elb_name
ORDER BY request_count DESC;

ELB毎の5XXエラーのリクエスト数

SELECT elb_name,
         backend_response_code,
         count(*) AS request_count
FROM elb_logs
WHERE backend_response_code >= '500'
GROUP BY backend_response_code, elb_name
ORDER BY backend_response_code, elb_name;

ELB毎の5XXエラーのリクエスト数(ELB指定)

SELECT elb_name,
         backend_response_code,
         count(*) AS request_count
FROM elb_logs
WHERE elb_name LIKE 'elb_demo_008'
        AND backend_response_code >= '500'
GROUP BY backend_response_code, elb_name
ORDER BY backend_response_code, elb_name;

ELB毎の5XXエラーのリクエスト数(期間+ELB 指定)

SELECT elb_name,
         backend_response_code,
         count(*) AS request_count
FROM elb_logs
WHERE elb_name LIKE 'elb_demo_008'
        AND backend_response_code >= '500'
        AND request_timestamp >= '2014-01-01T00:00:00Z'
        AND request_timestamp < '2016-01-01T00:00:00Z'
GROUP BY backend_response_code, elb_name
ORDER BY backend_response_code, elb_name;

ELB毎の5XXエラーのリクエスト数(期間+ELB+URL 指定)

SELECT count(*) AS request_count,
         elb_name,
         url,
         elb_response_code,
         backend_response_code
FROM elb_logs
WHERE elb_name LIKE 'elb_demo_008'
        AND backend_response_code >= '500'
        AND url LIKE 'http://www.example.com/jobs/%'
        AND request_timestamp >= '2014-01-01T00:00:00Z'
        AND request_timestamp < '2016-01-01T00:00:00Z'
GROUP BY elb_name,url,elb_response_code,backend_response_code
ORDER BY request_count DESC limit 10;

ELB毎の5XXエラーのリクエスト数(期間+ELB+URL+UserAgent 指定)

SELECT count(*) AS request_count,
         elb_name,
         url,
         elb_response_code,
         backend_response_code,
         user_agent
FROM elb_logs
WHERE elb_name LIKE 'elb_demo_008'
        AND backend_response_code >= '500'
        AND url LIKE 'http://www.example.com/jobs/%'
        AND user_agent LIKE '%Mozilla/5.0%'
        AND request_timestamp >= '2014-01-01T00:00:00Z'
        AND request_timestamp < '2016-01-01T00:00:00Z'
GROUP BY elb_name,url,elb_response_code,backend_response_code,user_agent
ORDER BY request_count DESC limit 10;

送信元IPのリクエスト数ランキング

SELECT request_ip,
         url,
         count(*) AS request_count
FROM elb_logs
WHERE elb_name LIKE 'elb_demo_008'
        AND request_timestamp >= '2014-01-01T00:00:00Z'
        AND request_timestamp < '2016-01-01T00:00:00Z'
GROUP BY request_ip,url
ORDER BY request_count DESC limit 5;

日付ごとのリクエスト数

SELECT date(from_iso8601_timestamp(request_timestamp)),
         count(*)
FROM elb_logs
WHERE url LIKE '%/jobs/%'
        AND date(from_iso8601_timestamp(request_timestamp)) >= date('2014-12-01')
GROUP BY  1
ORDER BY  1;

直近1年の500エラー発生のリクエスト数

SELECT elb_response_code,
         count(*)
FROM elb_logs
WHERE from_iso8601_timestamp(request_timestamp) >= date_add('day', -365 * 1, now())
        AND elb_response_code >= '500'
GROUP BY  1
ORDER BY  1;

レスポンスに1.0s以上時間がかかっているリクエスト

SELECT url,
         count(*) AS count,
         backend_processing_time
FROM elb_logs
WHERE backend_processing_time >= 1.0
GROUP BY  url, backend_processing_time
ORDER BY backend_processing_time DESC;

任意のエントリ取得(期間+リクエスト元IP 指定)

SELECT *
FROM elb_logs
WHERE request_ip = '245.85.197.169'
        AND request_timestamp >= '2014-01-01T00:00:00Z'
        AND request_timestamp <= '2016-01-01T00:00:00Z';

あるページからの遷移先ページ傾向

SELECT d.*
FROM 
    (SELECT b.request_ip,
         min(b.request_timestamp) AS request_timestamp
    FROM 
        (SELECT *
        FROM elb_logs
        WHERE url LIKE '%/jobs/%') a
        JOIN elb_logs b
            ON a.request_timestamp < b.request_timestamp
        GROUP BY  1 ) c
    JOIN elb_logs d
    ON c.request_ip = d.request_ip
        AND c.request_timestamp = d.request_timestamp
ORDER BY  d.request_timestamp;

参考

ELB アクセスログ

Classic Load Balancer のアクセスログ – Elastic Load Balancing
https://docs.aws.amazon.com/ja_jp/elasticloadbalancing/latest/classic/access-log-collection.html#access-log-entry-syntax
Application Load Balancer のアクセスログ – Elastic Load Balancing
https://docs.aws.amazon.com/ja_jp/elasticloadbalancing/latest/application/load-balancer-access-logs.html#access-log-entry-syntax

Athena

Querying Classic Load Balancer Logs – Amazon Athena
https://docs.aws.amazon.com/ja_jp/athena/latest/ug/elasticloadbalancer-classic-logs.html
Querying Application Load Balancer Logs – Amazon Athena
https://docs.aws.amazon.com/athena/latest/ug/application-load-balancer-logs.html

Amazon AthenaでELBのログを調査するときに使ったSQL
https://dev.classmethod.jp/cloud/amazon-athena-sql-for-elb/
Amazon AthenaでELBログをSQLで解析する #reinvent
https://dev.classmethod.jp/cloud/aws/amazon-athena-sql-elb-log-reinvent/
Amazon Athenaではじめるログ分析入門
https://qiita.com/miyasakura_/items/174dc73f706e8951dbdd

続きを読む

AWS ALBのスティッキーセッションについて調べてみた(再接続のたびにセッションの寿命は延びる)

ALBのスティッキーセッションを使うことになったのだが、設定を見るとセッション保持時間しか設定できない。
これだと、例えば24hで設定したとして、24h後のちょっと前にアプリにログインしても、stikky sessionのcookie切れで再ばランシングされて、ログインしていないインスタンスに接続したらログインセッションが切れてしまうことになる。
なんだかなーと思ってマニュアルを読み直すと以下の記述を見つけた。

ターゲットグループレベルでスティッキーセッションを有効にします。
ロードバランサー生成のクッキーの維持期間を秒単位で設定することもできます。
期間はリクエストごとに設定されます。
そのため、各期間の有効期限が切れる前にクライアントがリクエストを送信すると、スティッキセッションが継続されます。
複数のターゲットグループのスティッキーセッションを有効にした場合、すべてのターゲットグループに同じ継続時間を設定することをお勧めします。

若干曖昧だた有効期限内にリクエストを送信するとセッションが延長されるって意味かな?
ということで実際に検証してみることにした。

検証環境

検証環境は以下のとおりとした。
nginxの/stikky.txtにアクセスするとそれぞれnginx01nginx02と返すようにしてある。
スティッキーセッションの期間は3秒とした(実環境ではこんな未時間に設定するわけないけどw)

Client --- ALB --- Nginx01
                └- Nginx02

検証結果

まずは5秒間隔でポーリングしてみる。
コマンド結果をみるとおりNginx01, Nginx02に交互に接続している。
スティッキーセッションが3秒で切れてしまうから、5秒後にアクセスしたときは新規接続とみなされ再振り分け、coocke再発行されるためだ。

[root@localhost ~]# yes "date '+%d-%m %H:%M:%S'|tr 'n ' ' ' ; curl -c ./cookie_elb.txt -b ./cookie_elb.txt http://nginx-1428263045.us-west-2.elb.amazonaws.com/stikky.txt;sleep 5;" | sh
27-01 05:45:03 nginx02
27-01 05:45:08 nginx01
27-01 05:45:14 nginx01
27-01 05:45:20 nginx02
27-01 05:45:25 nginx02
27-01 05:45:31 nginx01
27-01 05:45:36 nginx01

次に1秒間隔でポーリングしてみる。
30秒以上試したが今度はずっとNginx02に接続している。
心配していたセッションの途中切れだが、5秒以上たってもセッションは維持されるようだ。
つまりセッション期間内に再接続すればstikky sessyonの時間も延長される、ということだろう。

[root@localhost ~]# yes "date '+%d-%m %H:%M:%S'|tr 'n ' ' ' ; curl -c ./cookie_elb.txt -b ./cookie_elb.txt http://nginx-1428263045.us-west-2.elb.amazonaws.com/stikky.txt;sleep 1;" | sh
27-01 06:03:12 nginx01
27-01 06:03:14 nginx01
27-01 06:03:15 nginx01
27-01 06:03:17 nginx01
27-01 06:03:18 nginx01
27-01 06:03:20 nginx01
27-01 06:03:21 nginx01
27-01 06:03:23 nginx01
27-01 06:03:24 nginx01
27-01 06:03:26 nginx01
27-01 06:03:27 nginx01
27-01 06:03:29 nginx01
27-01 06:03:30 nginx01
27-01 06:03:32 nginx01
27-01 06:03:33 nginx01
27-01 06:03:35 nginx01
27-01 06:03:36 nginx01
27-01 06:03:38 nginx01
27-01 06:03:39 nginx01
27-01 06:03:41 nginx01
27-01 06:03:42 nginx01
27-01 06:03:44 nginx01
27-01 06:03:45 nginx01
27-01 06:03:47 nginx01
27-01 06:03:48 nginx01
27-01 06:03:50 nginx01

で、スティッキーセッション期間はどれくらいに設定すべきか?

上記検証を踏まえると、バックグランドで頻繁に通信しているようなシステムならスティッキーもそのたびに更新され、ログアウトしない限り維持され続けると思われる。ユーザー操作がないと通信しないシステムの場合、無操作状態が続くとスティッキーセッションの有効期限を迎えてしまうから、システムのセッションタイムアウトと同じに設定するのが良いだろう。そうすれば、システムのセッションが切れて、再ログインが必要になるタイミングでスティッキーセッション有効期限が切れるのでユーザーが意図せず突然セッションが切れてしまう、という事態が防げる。

続きを読む

オンプレMySQLからAuroraへの移行で躓いたポイント(その3・移行後)

この記事は以下の記事の続きです。

一部、内容がその2と被りますが、移行後に生じた問題…というよりは、移行段階から移行後までずっと引きずっていた問題について触れていきます。

【注意】

  • ここで示した対策をそのままプロダクト環境に適用しているとは限りません。大抵はもう少し手を加えて適用しています。
  • 一部「これからプロダクト環境に適用する予定」のものもあります。

移行後まで引きずった問題点

ずばり、その2で記した「複数スレッドでのパフォーマンス問題」です。

移行前と移行後を比較すると、Webサーバの台数は1.5倍に増やしました。1台当たりの搭載メモリも1.5倍に増やしましたが、一方で仮想CPUのコア数は1台当たりで半分にしました。

「あれ?G1GC使ってるDBCP2のEvictionも走ってるのにコア減らしていいの?」となりそうですが、実際、r4.largeとm4.xlargeで結果の差が全くといっていいほど出ませんでした(同じような負荷レベルで処理が詰まる)。r4.largeでもCPU使用率が30~35%程度までしか行かず…腑に落ちないまま移行リリース。

移行当日は土曜日だったので負荷はあまりなく(でもリリース直後は普通の土曜日よりアクセスが多かった)特に問題は出ませんでしたが、最初の営業日、やはりWebサーバが1台、処理が詰まって落ち、再起動しました。
※50xエラーが一定期間に閾値以上発生したら再起動するように仕込んでありました。

しばらく様子見していましたが、頻繁ではないものの週に1回から数回、Webサーバが落ちます。アクセスログを見ると、不正なアクセスではなく正規のユーザが、

「以前より反応が遅くなったので、画面を何度かリロード」

しているようだったので(一部「イラついて連打」している人もいたりいなかったり?)、最初は画面で「処理中」表示を行い操作を抑制するとともに、WAFで過剰なアクセスを遮断する対応を行いました。

時間稼ぎ(?)の対策を開始

しかし、WAFでは「閾値を低くしすぎると正常なアクセスを遮断してしまう」こともあり、あまり効果的にリロードを抑制できず。画面表示での(心理的な)抑制も、処理の進行状況を表示しないとかえって逆効果になることも(ケースバイケースですが)。

この時点ではまだ「オンプレ時代より遅い」ことの正確な原因(Web~DB間のネットワークレイテンシが影響していることはまず間違いはなかったのですが)は把握できておらず、解決が長引きそうだったので、

  • Webサーバをさらに増やしてオンプレ時の2倍に
  • Aurora DBクラスタのWriterがあるゾーンとは別のAZにレプリカ(Reader)を設置し、SELECT負荷が高いアプリケーションを一部修正してReaderにアクセスするように

するとともに、

  • 「処理が詰まる」とはいっても「特定のWebサーバ」の「負荷が高くなったアプリケーション単体」でDBアクセスが詰まっており、ほかのWebサーバはそのまま動き続け、同じWebサーバでも別のアプリケーションはしばらく動作を続けていた(DBへのコネクションプーリングはWebアプリケーション個々で分けて張っていたため)

ことから、閾値以上の50xエラーが出たときにWebサーバを単純に再起動するのではなく、ALBのDrainingを使って再起動し「巻き込み被害」を極力減らす対応を行いました。

※タイトルがわかりにくくてごめんなさい(どう表現したらよいかわからず…)。

また、

  • 「負荷が高い画面」の処理であっても、利用ユーザによって処理するデータ量に差があり、結果として処理時間に大きな開きがある。一律に「単位時間当たりのリクエスト数」を制限しても(WAFによる遮断と同様に)うまくいかない

ので、「負荷が高い画面のリクエストを受け付けた時点からレスポンスを返しきるまで」を「1」とカウントし、(ユーザ毎に)並行処理(カウント)数が閾値以上になっているかどうかを見て遮断するように、JavaのローカルキャッシュとTomcatのサーブレットフィルタを使って対応しました。

※こちらも上に同じ。タイトルを付けるのは難しい。

なお、この対応を行っている最中、正規のユーザが「遅さに慣れた」(リロードしまくるとかえって遅くなることに気づいた)ことで、処理が詰まってWebサーバが再起動することはほぼなくなりました。但し、遅い状態が解消されたわけではないので、対応が不要になったわけではありません。

Meltdownパッチで動揺、そして問題解決

2018年1月になり、Meltdown&Specterの騒ぎが発生、AWSもEC2やAuroraなど関係するクラウド基盤サーバにパッチを当てたようです。その結果、「サーバ性能低下」という事案が発生しました。

ベンチマークを取りつつ急いで利用中AuroraインスタンスのバージョンアップとR4への移行を行いましたが、作業直前にほぼ元の性能に戻っていました(振り回された…)。

ただ、ここでベンチマークを取りながら別の対応策を検討。移行リリース前、コネクションプールをDBCP2からTomcat JDBC Poolに移行しようとして失敗して時間切れになっていましたが、今度はHikariCPへの移行にトライ。
※「ステージング環境での負荷テスト結果はともかく、プロダクト環境で処理が詰まるのはDB(Aurora)側が原因ではなさそうだけど、DBへの問い合わせで詰まっていることは間違いない」というところまでは絞り込んでいましたので、行き当たりばったりの対応ではありません(多分。おそらく。きっと)。

結果、これがうまくハマってオンプレ時と同等(一部はそれ以上)の性能を取り戻すことができました。

Auroraフェイルオーバー時の処理の詰まりもなくなりました。

また、これで(現状の負荷なら)Webサーバの台数も元に戻すことができます。

AWSのネットワーク環境は、同一AZであってもインスタンス間のレイテンシ(遅延)が往復平均で200マイクロ秒(μs)程度あるようです(OS上で計測した場合)。これは、同じ室内に1ラック~数ラック立てて運用しているオンプレ環境(特にSDNを使っていない環境)とは1桁以上の差があります(オンプレが速い)。

通常のSQLクエリ/コマンドの実行では大した影響がなくても、コネクションプールでは接続のValidationやEviction等の際に確認クエリを発行する上、MySQL Connector/Jも色々と管理・確認用のクエリを流しがちな傾向があるので、わずかな処理時間の増加でもリソースの取得・開放がスムーズにいかない原因になります。

そこを、HikariCPにしたことで処理が軽減されて(クエリ発行数も減ったはず)、AWS環境でもうまく回るようになったようです。

なお、途中では触れませんでしたが、負荷を軽くするには「遅いSQLの改善」も重要です(当然、その対応も進めていました)。

HikariCPでWebサーバの動作が軽くなったことで、今度は「遅いSQLを処理するときのDB負荷」のほうにボトルネックが移りました。これまで以上にSQLの改善、INDEXやテーブル設計の調整などに力を入れる必要がありそうです。

まとめ

  • ユーザは「遅くなった」ことには割と敏感に気づき、そして(気軽に?)画面をリロードする
  • 一方で、「遅くなった」ことにはしばらくすると慣れる(限度はあるし、ユーザの時間を無駄に奪ってはいけない)
  • ちょっとしたレイテンシの変化が処理のサイクル・バランスを大きく崩すことがある(オンプレで実績がある構成でも、そのままで行けるとは限らない)
  • ボトルネックを1つ解消すると、別のところにボトルネックが移る(ので、移った先の対応を進める必要がある)

続きを読む

AWS CodeDeploy logs that you should watch.

We have a web service with AWS, located in like below environment. (This time in case of using AmazonLinux) WebServer: – Production: – ALB * 1 – EC2 * 2 – Dev: – EC2 * 1 DB: – Production: Aurora * 1 – Dev: Aurora * 1. Our source code is managed by github organization account. And we’re going to … 続きを読む