AWSハングアップ調査
サイト管理者EC2がたまにハングするようになる。 2022/03/31
wordpress環境を構築してから。インストールする際にストレージ容量とか気をつけてて、問題なさそうだったのに。その調査の備忘録。
目次
調査1
頻度は１～２日に1回。症状は夜中のどこか。AWSのモニタリングからわかるのはCPUの利用率が100%に張り付きその後、ステータスチェックの失敗が１になり、30分ごとにバックアップのためのネットワークアクセスがなくなる。sshでもログインできない。(※最初に起きたときはギリギリ生きていてsshは激重だった。)
EC2のモニタリングのログ調査
CPU利用率が100%に張り付き、その後CPUクレジットを使い切ってCPU利用率が0になり、そのままハングしている。CPUクレジットを使い切ってない間はsshできて辛うじて動いていたのであろう。
AWSのEC2のモニタリングからは、3/31 3:35からCPU利用率が上がり始め、3:40～4:00まで100%の期間
4:10 CPUクレジット0に CPU利用率も0に。
Linuxのシステムログ調査
システムのログにそれらしい記録あり
システムのログ/var/log/syslogを見てみた。OSがハングしてダンプしているログがある。
Linuxのハングの分析は初めてだが、面白い。
—-カーネル悲鳴はここからか？——
Mar 31 04:06:49 ip-172-31-45-138 systemd-networkd[402]: eth0: Could not set DHCPv4 address: Connection timed out
Mar 31 04:08:24 ip-172-31-45-138 systemd-networkd[402]: eth0: Failed
イーサーが死んでいるだと！？
–ここからカーネルが悲鳴上げてダンプしだしている—–
Mar 31 04:09:30 ip-172-31-45-138 kernel: [101314.179745] systemd invoked oom-killer: gfp_mask=0x100cca(GFP_HIGHUSER_MOVABLE), order=0, oom_score_adj=0
Mar 31 04:09:31 ip-172-31-45-138 kernel: [101314.179754] CPU: 0 PID: 1 Comm: systemd Not tainted 5.13.0-1019-aws #21~20.04.1-UbuntuMar 31 04:09:31 ip-172-31-45-138 kernel: [101314.179757] Hardware name: Xen HVM domU, BIOS 4.11.amazon 08/24/2006systemd invoked oom-killer:
oom-killerってなんだ？！調べてみると、oom=Out Of Memory、[systemd]がメモリ不足を回避するためにキルするプロセスを選んでキルしたというログらしい。何かが暴走して、CPUとメモリを無限に確保した後、システムが復旧しようとしたログなのであろう。キルされたのはマイクラサーバー、確かにoom-killerのプロセスのログから一番メモリをくってそう。その直前当たりを見てみる。
定期的に動いているのはほとんどcronで動いているログのよう。
・マイクラバックアップ →あえてやっている
Mar 31 03:30:01 ip-172-31-45-138 CRON[15399]: (ubuntu) CMD (/home/ubuntu/MinecraftServerBedrock/worlds/mc_backup_hourly_YuikaAndB.sh)
Mar 31 03:30:31 ip-172-31-45-138 CRON[15398]: (CRON) info (No MTA installed, discarding output)
・(CRON) info (No MTA installed, discarding output)
→メールの設定ができていときに出るログ。設定できていればエラー内容をメールするらしい。
バックアップスクリプトのどこかがエラーになっているのだろうか？ハングする前も出ているのでハングとは無関係そう。
・phpのphpsessionclean.service: Succeeded. →こちらはwordpressのためにインストールしたphpの掃除？phpのインストール時に止まったのでPHP関連は怪しいが、ログからは成功していそう。
・次はaptの更新、毎日アップデートか？
Mar 31 03:39:23 ip-172-31-45-138 systemd[1]: Starting Daily apt download activities…
：
Mar 31 03:39:28 ip-172-31-45-138 systemd[1]: Started PackageKit Daemon.
Mar 31 03:44:56 ip-172-31-45-138 PackageKit: daemon quit
Mar 31 03:49:18 ip-172-31-45-138 packagekitd[15843]: Error releasing name org.freedesktop.PackageKit: Timeout was reached
↑派手にエラーが出ている。このエラーがきっかけでハングしたのか？ネットワークのタイムアウトっぽいが、他事が原因である可能性もある。が、おそらくそのままapt系が死んでいるのだろうと推定する。確かに、aptでPHPをインストールするときに途中で止まった。これが原因か？
ダンプの最後の方で
—メモリ不足でマイクラサーバーがキルされている。—
Mar 31 04:09:31 ip-172-31-45-138 kernel: [101314.180132] Out of memory: Killed process 10850 (bedrock_server) total-vm:1026932kB, anon-rss:376956kB, file-rss:0kB, shmem-rss:0kB, UID:1000 pgtables:1016kB oom_score_adj:0
その後いろいろ停止させられているログ
その後、cronのマイクラバックアップとPHP掃除のログが定期的に出る。完全には死んでなさそう。
aptの日々更新も成功している。
cronのログを記録するように変更
■rsyslogの設定cronのログを記録するように変更
cronのマイクラバックアップがスクリプトがエラーを出しているような感じなのでcronのログを探したが、ない。ubuntuではデフォルトでcronのログがオフになっているらしく、設定を変えて記録してみる。
$ cd /etc/rsyslog.d
$ sudo cp -p 50-default.conf 50-default.conf_$(date “+%Y%m%d_%H%M%S”)
$ sudo emacs 50-default.conf
cron.* /var/log/cron.log # 編集前
↓
cron.* /var/log/cron.log # 編集後
$ sudo systemctl restart rsyslog
ログは/var/log/cron
ログが出るようになったがsyslogと同じ内容のログしかでてない。意味ない。
原因はメモリ不足
■systemd invoked oom-killer:
OOM Killerとは
「Linux上で重要なアプリケーションのプロセスが突然死んだけど、アプリケーションのログを見ても何もエラーが出力されていない、という経験はありませんか？そのような場合、システムのメモリ枯渇によりOOM Killerがそのプロセスを停止させた可能性があります。」
何らかの要因でメモリ不足になってイッちゃっているってのは間違いなさそう。
■topコマンドでメモリ順
メモリ不足ということで、とりあえずメモリを使ってそうなプロセスを確認したい。topコマンドで見れる。topコマンドはリアルタイムで更新してプロセスの情報を表示してくれる。下記ショートカットでソートできるみたい。これはメモっておく価値大。
・shift+m メモリ使用率順にソート
・shift+p CPU使用率順にソート（デフォルト）
■psコマンドでメモリ順
オーソドックスなpsコマンドでもソートできるらしい。
ps aux –sort -%mem |head -n30
-%menのところはpsコマンドの最初の行の項目名を入れればそれでソートしてくれるみたい。
出力結果をエクセルにコピペ。
ダンプ時のrssの単位が良くわからないので、dumpのところのrssとtopコマンドのRSSとの比率を出してみて考察。
dump-rss topRSS 比率 プロセス名94239 139876 1.484268721 bedrock_server
34864 120444 3.454681046 s3fs
17076 70996 4.157648161 mysqld
12044 apt-check
9675 43672 3.626037861 apache2
9178 42488 4.391524548 apache2
8926 41216 4.490738723 apache2
8903 39672 4.444544029 apache2
8758 39436 4.42951814 apache2
8517 39400 4.498744005 apache2
4500 18000 2.113420218 multipathd
結果、普段からマイクラサーバーがメモリを140M、これは1番食っている。異常時は更に他のと相対的にみると異常に食っている気がする。次に多いのがs3fs、AWSのS3をマウントするコマンド。120Mも食っている。外そう。
■マイクラサーバーはログインするとメモリ33％くらいになる。
起動時の空きメモリ69M=7%
$ free -m
total used free shared buff/cache available
Mem: 967 743 69 21 154 60
■実際にメモリ不足？
ログからは最後にoom起動＝メモリ不足となっていることから
もしかしたら、夜中に色々なのが同時に動いた際に実際にメモリ不足になっているかも
ubuntuのデフォルトはスワップが0らしい。確認すると確かに0なので手っ取り早くメモリ不足かを確認するにはスワップを用意すればよいかも?
——スワップ等、メモリの確認
$ freetotal used free shared buff/cache available
Mem: 991160 591828 130884 3344 268448 240460
Swap: 0 0 0
…スワップしていない
対策1:スワップするようにしてみる。
■スワップするようにしてみる。
暫定になるかもしれないが、これで死ななくなればメモリが足りてない。もし、これでも死ぬなら暴走していてメモリがいくらあっても無駄。このときサーバー再構築しよう。
スワップサイズは？
Redhat の資料によると
物理メモリ量 とスワップサイズ
物理メモリ2GB 以下 :メモリの２倍程度から3倍程度
2-8GB: メモリと同程度から２倍程度
8-64GB: メモリの1.5倍程度
sleepするときに全メモリをハイバネーションして退避するための量らしい。今時、メモリの量が莫大なものがあるので、例えば64Gのメモリのために６４Gのストレージで退避させるのは時間がかかりすぎてアホらしいみたい。メモリが潤沢になった今は、今はスワップしない、sleepしないのが普通なのか。
サーバーなので今までどおりはいハイバネーションしなくてよいが、それは別の設定かな？
私のEC2のスワップサイズ
メモリサイズは１G
ストレージの残容量は3G/8G
ストレージの容量も最小で行きたいので、スワップサイズは１Gとする。
作業
方法はAmazonの説明で十分わかる。
https://aws.amazon.com/jp/premiumsupport/knowledge-center/ec2-memory-swap-file/
1.スワップファイルを１G作成する。
1G=128Mx8。なぜブロックのサイズが128Mなのかはわからないが例にしたがう。
$ sudo dd if=/dev/zero of=/swapfile bs=128M count=8
8+0 records in
8+0 records out
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 15.2512 s, 70.4 MB/s
ちょっと時間がかかる。
2.スワップファイルの読み書きのアクセス許可を更新する。
$ sudo chmod 600 /swapfile
3.Linux スワップ領域のセットアップ
$ sudo mkswap /swapfile
Setting up swapspace version 1, size = 1024 MiB (1073737728 bytes)
no label, UUID=6c93a3d7-008d-49be-b566-926ac00bc892
スワップ領域にスワップファイルを追加して、スワップファイルを即座に使用できるようにする。
$ sudo swapon /swapfile
手順が正常に完了したことを確認します。
$ sudo swapon -s
Filename Type Size Used Priority
/swapfile file 1048572 2304 -2
早速、swapしている。
ubuntu@ip-172-31-45-138:~$ free
total used free shared buff/cache available
Mem: 991160 609344 80148 21352 301668 202472
Swap: 1048572 2304 1046268
/etc/fstab ファイルを編集して、起動時にスワップファイルを起動します。
エディタでファイルを開きます。
$ sudo emacs /etc/fstab
ファイルの末尾に次の新しい行を追加し、ファイルを保存して終了。
/swapfile swap swap defaults 0 0
ストレージ容量は？
$ df /
Filesystem 1K-blocks Used Available Use% Mounted on
/dev/root 8065444 6516508 1532552 81% /
81%使っていて残り、1.5G。
wordpress運用しだしたら1年持つかくらいのギリだな。
調査2
■他の日のハングのログを見てみる
3/31 3:35 ↑の記述のもの。Daily aptをトリガーにet0が死んでoom-killerが発動、bedrock_serverがkillされている。snapdはその後SIGABRTしている。
3/31 19:00付近 snapdがSIGABRTしている。Daily aptをトリガーにet0が死んでoom-killerが発動、bedrock_serverがkillされている
4/2 5:40 snapdがSIGABRTしている。Daily aptをトリガーにet0が死んでoom-killerは動いていない。
大体、同じだ。
■snapdが怪しい。止めていい？止める方法は？
snapdとは？
aptとかと同じようなパッケージ管理ツール
–snapd経由でインストールできるアプリ
利用頻度が高さそうなアプリを列挙
certbot
mysql
postgresql
aws-cli
Google Cloud SDK
heroku
VSCode
おそらく、mariaDBを入れたときに入った?→違うっぽい。
$ snap list
Name Version Rev Tracking Publisher Notes
amazon-ssm-agent 3.1.715.0 5163 latest/stable/… aws✓ classic
core18 20220309 2344 latest/stable canonical✓ base
core20 20220318 1405 latest/stable canonical✓ base
lxd 4.0.9-8e2046b 22753 4.0/stable/… canonical✓ –
snapd 2.54.4 15177 latest/stable canonical✓ snapd
amazonの何かを入れるときにはいったか？
デフォルトで入っているのか？
■対策2:s3のマウントをやめる。
s3のマウントが思いの外、メモリを食っている。
1.S3をCLIでmvとかで操作するためのaws cliのインストール
ここを参考にした。S3とそのアクセス設定やらは以前やっているので、インストールと認証の設定のみ。https://qiita.com/uhooi/items/e915873ddabdf6e27fd7
2.マイクラバックアップスクリプトの変更
S3をマウントして通常のディレクトリとしてマイクラのバックアップを普通にmvとかしていたのを
aws-cliのコマンドに置き換える。
—–シェルスクリプトはこんな感じ-
S3にaws s3 コマンドで直接アップするための設定
BK_TIME=date +%Y%m%d-%H%M00 #aws s3でもこれを使う
S3_PATH=”s3://minecraft-xxxx/worlds_backup”
S3_PATH_NAME=”$S3_PATH/mc_backup_hourly_${BK_TIME}.tar.gz”
:
:
#ファイル名をテンポラリから日付付きの名前にして所定の場所に移動する
aws s3 mv $TMP_BK_NAME $S3_PATH_NAME #S3をマウントするとメモリを食うので、やめて、aws cliでS3に移す。
#古いのを消す
aws s3 rm $S3_PATH/mc_backup_hourly_date +%Y%m%d-%H%M00 -d ‘1 days ago’.tar.gz
———-
確認１.まず直接実行してバックアップファイルがS3にできることを確認。ただし対応する１日前のファイルが無いので古いのを消す確認はできない。
move: ./backup_worls_tmp.tar.gz to s3://minecraft-nyanpu/worlds_backup/mc_backup_hourly_20220402-174300.tar.gz
delete: s3://minecraft-nyanpu/worlds_backup/mc_backup_hourly_20220401-174300*.tar.gz
ブロックを追加
メッセージからはうまく言ってそう。
確認2.cronの時間が来たので動いたか確認。
$ aws s3 ls s3://minecraft-xxxx/worlds_backup/
2022-02-03 19:18:16 0
2022-04-01 17:00:17 96091068 mc_backup_hourly_20220401-170000.tar.gz
2022-04-01 18:00:17 96092421 mc_backup_hourly_20220401-180000.tar.gz
2022-04-01 18:30:18 96093334 mc_backup_hourly_20220401-183000.tar.gz
2022-04-01 19:00:17 96091126 mc_backup_hourly_20220401-190000.tar.gz
2022-04-01 19:30:18 96093343 mc_backup_hourly_20220401-193000.tar.gz
2022-04-01 20:00:17 96092129 mc_backup_hourly_20220401-200000.tar.gz
2022-04-01 20:30:18 96093290 mc_backup_hourly_20220401-203000.tar.gz
2022-04-01 21:00:18 96092316 mc_backup_hourly_20220401-210000.tar.gz
2022-04-01 21:30:18 96093032 mc_backup_hourly_20220401-213000.tar.gz
2022-04-01 22:00:17 96085400 mc_backup_hourly_20220401-220000.tar.gz
2022-04-01 22:30:18 96058526 mc_backup_hourly_20220401-223000.tar.gz
2022-04-01 23:00:18 96032978 mc_backup_hourly_20220401-230000.tar.gz
2022-04-01 23:30:17 96033248 mc_backup_hourly_20220401-233000.tar.gz
2022-04-02 00:00:18 96032998 mc_backup_hourly_20220402-000000.tar.gz
2022-04-02 00:30:18 96033463 mc_backup_hourly_20220402-003000.tar.gz
2022-04-02 01:00:18 96033570 mc_backup_hourly_20220402-010000.tar.gz
2022-04-02 01:30:17 96033759 mc_backup_hourly_20220402-013000.tar.gz
2022-04-02 02:00:18 96033309 mc_backup_hourly_20220402-020000.tar.gz
2022-04-02 02:30:17 96034411 mc_backup_hourly_20220402-023000.tar.gz
2022-04-02 03:00:18 96034247 mc_backup_hourly_20220402-030000.tar.gz
2022-04-02 03:30:17 96034380 mc_backup_hourly_20220402-033000.tar.gz
2022-04-02 04:00:18 96033521 mc_backup_hourly_20220402-040000.tar.gz
2022-04-02 04:30:18 96035310 mc_backup_hourly_20220402-043000.tar.gz
2022-04-02 05:00:17 96034982 mc_backup_hourly_20220402-050000.tar.gz
2022-04-02 05:30:18 96033875 mc_backup_hourly_20220402-053000.tar.gz
2022-04-02 10:30:18 96272026 mc_backup_hourly_20220402-103000.tar.gz
2022-04-02 11:00:19 96242165 mc_backup_hourly_20220402-110000.tar.gz
2022-04-02 11:30:18 96179239 mc_backup_hourly_20220402-113000.tar.gz
2022-04-02 12:00:18 96173663 mc_backup_hourly_20220402-120000.tar.gz
2022-04-02 12:30:17 96133847 mc_backup_hourly_20220402-123000.tar.gz
2022-04-02 13:00:17 96085045 mc_backup_hourly_20220402-130000.tar.gz
2022-04-02 13:30:17 95996627 mc_backup_hourly_20220402-133000.tar.gz
2022-04-02 14:00:17 95997197 mc_backup_hourly_20220402-140000.tar.gz
2022-04-02 14:30:17 95997985 mc_backup_hourly_20220402-143000.tar.gz
2022-04-02 15:00:18 95997064 mc_backup_hourly_20220402-150000.tar.gz
2022-04-02 15:30:17 95997585 mc_backup_hourly_20220402-153000.tar.gz
2022-04-02 16:00:18 96556800 mc_backup_hourly_20220402-160000.tar.gz
2022-04-02 16:30:18 97773735 mc_backup_hourly_20220402-163000.tar.gz
2022-04-02 17:02:16 113338868 mc_backup_hourly_20220402-170000.tar.gz
2022-04-02 17:30:18 100512558 mc_backup_hourly_20220402-173000.tar.gz
2022-04-02 17:43:30 100518902 mc_backup_hourly_20220402-174300.tar.gz
2022-04-02 18:00:27 100497901 mc_backup_hourly_20220402-180000.tar.gz
新しいバックアップはできた。〜20220402-180000.tar.gz
ただし、1日前のを消しているつもりが消えてない。〜20220401-180000.tar.gzが残っている。
・もう１回、シェル上で直接実行したときのログを見る。
delete: s3://minecraft-nyanpu/worlds_backup/mc_backup_hourly_20220401-174300.tar.gz あぁ！s3のファイルにワイルドカードは使えないのか！ワイルドカードにしないとタイムラグが怖かったんだよね。 でも、保存するときに”%H%M00″と必ず00秒としたからよい。あれ？そうしてて、ワイルドカードが残りっぱなしなだけじゃん。
*を消したら良いでしょう。
結果、OKでした。
3.s3のマウントを外す
マウント名確認
$mount
:
s3fs on /mnt/s3 type fuse.s3fs (rw,relatime,user_id=0,group_id=0,allow_other)
$ ps aux –sort -%mem |head -n 5
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
ubuntu 1114 11.6 22.6 1013588 224108 pts/1 Sl+ 10:10 54:15 ./bedrock_server
root 314 0.1 11.8 708240 117356 ? Ssl 10:09 0:48 s3fs minecraft-nyanpu /mnt/s3 -o rw,allow_other,use_cache=/tmp,uid=1000,gid=1000,passwd_file=/etc/passwd-s3fs,dev,suid
www-data 663 0.0 2.5 201804 25672 ? S 10:09 0:02 /usr/sbin/apache2 -k start
www-data 643 0.0 2.5 202664 25412 ? S 10:09 0:02 /usr/sbin/apache2 -k start
11%=110Mbyteくらいメモリを使っていた。
-実際にマウントを外す
$ sudo umount /mnt/s3
$ ps aux –sort -%mem |head -n 5
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
ubuntu 1114 11.6 22.6 1013588 224108 pts/1 Sl+ 10:10 54:16 ./bedrock_server
www-data 663 0.0 2.5 201804 25672 ? S 10:09 0:02 /usr/sbin/apache2 -k start
www-data 643 0.0 2.5 202664 25412 ? S 10:09 0:02 /usr/sbin/apache2 -k start
www-data 641 0.0 2.4 202588 24656 ? S 10:09 0:02 /usr/sbin/apache2 -k start
–s3fsがいなくなった
—beforeのメモリ—
$ free
total used free shared buff/cache available
Mem: 991160 515600 168544 10520 307016 304732
Swap: 1048572 407296 641276
—afterのメモリ—-
$ free
total used free shared buff/cache available
Mem: 991160 402604 227372 10604 361184 417644
Swap: 1048572 391680 656892
110M=11%くらい空いた!
■結果 OK。結局メモリ不足
スワップ領域を１G追加して、メモリを食ってた必須ではないs3のマウントをやめることで１〜２回/日発生していたハングはすっかりなくなった。結論はwordpress環境構築でのメモリ不足である。実際のトリガーはsnapdの日々更新。これで多分、普段、40％くらいしか食ってないメモリを食い尽くしたのであろう。他の対策としてこのメモリ大食いのsnapdを止めるか？止めるとセキュリティバージョンアップが働かないから危ういか？これからの運用でまた判断していこう。今回は勉強になったし、楽しかった。
