Simple Application Server が応答無し状態になった話

Alibaba Cloud の Simple Application Server のインスタンスで作業中、短時間で2回応答無し(調査の切り分け時も含めると4回)となりました。

応答無しの具体的な状況としては以下のとおり。 応答無しになった原因は CPU、ディスク、メモリのどこにあったのかの切り分け、そして最終的に行った対処内容を記録に残します。 結果として Alibaba Cloud 固有の話ではないので似たような事象に遭遇した場合の参考になればと。

  • dnf コマンド実行を起点に問題が発生
  • 接続中の SSH コンソールで応答が返ってこない、キー入力しても反応しない、Ctrl-Cとかでの中断も出来ない
  • 新しい SSH 接続も行えない
  • Apache も応答しない(Web ブラウザでアクセスしても応答無し)
  • Ping は応答はある

1回目の応答無しはたまたま発生したものかと思い Alibaba Cloud コンソールからインスタンスを強制再起動して復旧したのですが、30分もたたない間に再度応答無し状態が発生しました。 原因がわからないとこのサーバは使い物にならないのできちんと調べることにします。

Simple Application Server > Servers > MySimple > Metrics 画面からCPUの使用率を見ていきます。 Ping の応答はあるのでサーバが完全に停止している可能性はなく CPU リソースの枯渇が発生しているかどうか切り分けます。

以下スクリーンショットが問題発生時のチャートです。 17:37過ぎから17:52の前までが1回目の応答無しです。 この時の CPU 使用率は 60% 程度です。 CPU 使用率が 100% でも SSH 接続が出来ない、まったく応答がないということは普通はありえないですし、そもそも 60% 程度なので CPU リソースの枯渇が原因ということはないとわかります。 また 18:02 から 18:17 までは2回目の応答無しでこれを書いているときも応答無しは続いている(強制再起動はまだ行っていない)のですが CPU 使用率は 20%なので CPU リソースが原因の可能性はより低くなっています。

次に見るところはメモリかディスクなのですがディスクのチャートをみてこれが関わっている可能性が高いのではと考えました。  以下のチャートのとおり、1回目の17:37-17:52 と2回目の18:02 以降で System Disk の Read QPS が1500~2000で高い状態です。 これからマニュアルを調べるところですが Disk の IO 処理の上限に達してしまいシステムとして応答が出来ない状態となっていると仮説をたてます。

上記のチャートは Simple Application Server の管理画面で確認できるものですが Cloud Monitor の管理画面ではより詳細な情報を確認可能です。 まあ、詳細と言っても上のチャートと情報量はそこまで変わらないのですがAverage/Minimum/Maximumを選ぶことは可能です。

状況としては Read 処理に関する IOPS 上限に達している&この2,000 IOPS 以上の大量の要求を出し続けて結果システムとして応答が出来ない状態になっていると推測します。

とりいそぎ Simple Application Server のディスク性能の仕様を確認します。 Simple Application Server としての明確な記載は見つからなかったのですが、Simple Application Server の中身は Elastic Compute Service であること、コンソール画面から50 GB の ESSD であることはわかっているので Elastic Compute Service のマニュアルで参考となりそうな情報を見つけます。

公式マニュアル(https://www.alibabacloud.com/help/en/ecs/user-guide/block-storage-performance)からのスクリーンショットは以下ですが、ESSD でもっとも低い性能 PL0 タイプだとベースラインの IOPS は 1,800 で、あとは追加されたディスク容量ごとに 12 IOPS/GB が性能アップする仕様です。容量の追加は行っていないのでこの 1,800 IOPS が性能上限となると言えます。(ESSD PL0の下に ESSD Entry Disk というより低い性能のものもありますがこちらもベースラインは 1,800 IOPS )。

先ほどのチャートを再掲すると以下の通りで 1,800 IOPS で張り付いていますのでやはりディスクの性能上限に達してしまっていることがわかりました。

では、このような大量のIOPSの原因は何かを考えていきます。 1回目の操作を行っていた時は以下のコマンドを実行しているところで応答無しとなりました。 詳しく説明すると php-mysqlのところで tab キーを押下し候補をリストアップしてもらおうとしたところで応答無しになりました。

# dnf install php php-mysql(この状態でtab キーを押下しphp-mysqlの候補を検索)

2回目の応答無しですが、パッケージのインストール中に起きました。

# dnf install https://rpms.remirepo.net/enterprise/remi-release-9.rpm
Last metadata expiration check: 1:09:58 ago on Sat 20 Apr 2024 03:53:04 PM CST.
remi-release-9.rpm                               29 kB/s |  30 kB     00:01
Dependencies resolved.
================================================================================
 Package               Arch       Version               Repository         Size
================================================================================
Installing:
 remi-release          noarch     9.3-3.el9.remi        @commandline       30 k
Installing dependencies:
 epel-release          noarch     9-7.el9               extras-common      19 k
Installing weak dependencies:
 epel-next-release     noarch     9-7.el9               extras-common     8.1 k

Transaction Summary
================================================================================
Install  3 Packages

Total size: 57 k
Total download size: 27 k
Installed size: 60 k
Is this ok [y/N]: y
Downloading Packages:
(1/2): epel-next-release-9-7.el9.noarch.rpm      32 kB/s | 8.1 kB     00:00
(2/2): epel-release-9-7.el9.noarch.rpm           70 kB/s |  19 kB     00:00
--------------------------------------------------------------------------------
Total                                            96 kB/s |  27 kB     00:00
CentOS Stream 9 - Extras packages               2.1 MB/s | 2.1 kB     00:00
Importing GPG key 0x1D997668:
 Userid     : "CentOS Extras SIG (https://wiki.centos.org/SpecialInterestGroup) <security@centos.org>"
 Fingerprint: 363F C097 2F64 B699 AED3 968E 1FF6 A217 1D99 7668
 From       : /etc/pki/rpm-gpg/RPM-GPG-KEY-CentOS-SIG-Extras-SHA512
Is this ok [y/N]: y
Key imported successfully
Running transaction check
Transaction check succeeded.
Running transaction test
Transaction test succeeded.
Running transaction
  Preparing        :                                                        1/1
  Installing       : epel-release-9-7.el9.noarch                            1/3
  Running scriptlet: epel-release-9-7.el9.noarch                            1/3
Many EPEL packages require the CodeReady Builder (CRB) repository.
It is recommended that you run /usr/bin/crb enable to enable the CRB repository.

  Installing       : epel-next-release-9-7.el9.noarch                       2/3
  Installing       : remi-release-9.3-3.el9.remi.noarch                     3/3
  Running scriptlet: remi-release-9.3-3.el9.remi.noarch                     3/3
⇒ここで応答が無くなる!

1回目と2回目の共通点はdnfコマンドの利用中であることです。 Read IOPS が大量に発生していることから何かしらパッケージ情報の検索なのか読み取りが大量に発生し今回の事象に至っていると思われます。

ここまで来るとどのファイルを Read しにいっているのか知りたくなります。 Windows であればリソースモニターなどでどのプロセスがどのファイルやディレクトリに Read / Write しているのか簡単にわかるのですが Linux の場合はどうするか。そもそも SSH コンソールは応答無しですし、新たに接続することも出来ない状況です。 ログイン出来てコマンドが打てれば lsof コマンドなどでもうちょっと情報がとれたのですが・・・。

あとは処理が終わるまで待つしかありません。 ただ、18:00過ぎから 1,800 IOPS の上限に達して約2時間経過(現在 20:10)してもまったく IO 要求は上限に張り付いたままです。 2時間待っても NG ということでいったんインスタンスを強制再起動し、同じ処理を実行して再現するかどうかを見ていきます。

Force Restart で強制再起動します。

無事再起動し SSH ログイン出来たので再度同じコマンドを実行します。 今度はコマンド実行直後に応答無し事象が再現しました(3回目の応答無し)。

#  dnf install https://rpms.remirepo.net/enterprise/remi-release-9.rpm
Extra Packages for Enterprise Linux 9 - x86_64  3.6 MB/s |  21 MB     00:05
⇒ここで応答が無くなる!(3回目)

ここから取りうる選択肢を考えます。 1つは、CentOS Stream に何かしら原因があると考えOSを変えてしまうこと。 2つ目は Simple Application Server に何か原因があると考え Elastic Compute Service に移行すること、3つ目はディスクの IOPS 性能をあげてどうなるか。 4つ目はここまで着目していなかった他に問題の原因が無いか探ることです。4つ目についてはメモリ観点では現状の1GBを増やしてみてどうなるか、など。

OS を変えるのは作業のやり直しの範囲が広いので避けようとおもいます(とはいっても1時間もかからないやり直しですが)。 3つ目は今あるシステムディスクの容量を増やして性能を増やす考え方ですがシステムディスクを単純に増やしてもディスク性能が向上するかは怪しいです。 この手の容量と性能が比例関係のストレージは分散ストレージの技術を使っているわけで容量だけ増やしても実際のデータを再配置しない限りは性能は変わらない可能性が高いです。 4つ目のメモリについては以下のチャートでわかるように応答無しの発生のタイミングでも特に消費の増減もないことからメモリ起因の可能性は低いと考えました。

上記はメモリの使用量で、下のはディスクへのIOです。 問題発生中と発生していないときでメモリの使用量はほぼ変わらずなことがわかります。

ということで Simple Application Server のインスタンスを Elastic Compute Service のインスタンスに移行してみます。

移行は一度 SAS インスタンスで snapshot を作成し、その snaphost をもとに Custom Image を作成します。 次に Custom Image から ECS インスタンスを作成します。 とりあえず検証用途なので従量課金タイプで 2vCPU、8GBメモリ、システムディスクは 200G で 3400 IOPS まで性能がでるインスタンスとして展開します。

SAS インスタンスで失敗していた dnf による remi リポジトリのインストールに再挑戦します。 今回はあっという間に終わってしまいました。 already installed ということで SAS インスタンスでの実行時にすでにインストールは成功していた模様。 こうなってくるとインスタンスを ECS に切り替えたことで問題が解消できたのかどうよくわからなくなりました。

#  dnf install https://rpms.remirepo.net/enterprise/remi-release-9.rpm


Extra Packages for Enterprise Linux 9 openh264  1.7 kB/s | 2.5 kB     00:01
Extra Packages for Enterprise Linux 9 - Next -  1.8 MB/s | 1.8 MB     00:01
Remi's Modular repository for Enterprise Linux  223 kB/s | 673 kB     00:03
Safe Remi's RPM repository for Enterprise Linux 313 kB/s | 994 kB     00:03
remi-release-9.rpm                               30 kB/s |  30 kB     00:00
Package remi-release-9.3-3.el9.remi.noarch is already installed.
Dependencies resolved.
Nothing to do.
Complete!

もう一度 SAS インスタンスで上記コマンドを実行してみます。 SAS インスタンスは3度目の応答無し後にシステムを強制再起動しているので ECS インスタンスと同様にすでに remi リポジトリのインストールは終わっており、dnfコマンドも already installed で終了してくることが予想されます。しかし、4回目の応答無しが再現しました。 

状況からは一番可能性が低いと考えていたメモリが原因の可能性が出てきました。 もともとの SAS インスタンスは 1GB メモリ、今回の ECS は8GBメモリです。 

4回目の応答無しが発生した SAS インスタンスを強制再起動しSSHログインします。まず確認するのは swap の構成の有無です。 パブリッククラウドの仮想マシンは大体 swap が off になっています。 free コマンドの結果は以下ですが、Alibaba Cloud も swap はありません。

そして以下の free コマンドの結果は OS の起動直後なのですが free は約48MBしかありません。 cache は約147MBですが available は約83MBなのでメモリに全然余裕がない状態でした。。。 原因はメモリの可能性が高まります。

最初の切り分け時、応答無しが発生している場合もしていない場合もメモリ使用量に変動がないことからメモリ枯渇が原因の可能性を低いと切り分けしていました。また、パブリッククラウドはスワップが未構成であることからメモリ不足の結果として大量の IO 処理が発生することはないと考えました。仮に Swapが構成されいた場合はRead だけではなく Write の処理も発生するはずなのに実際には Read の IO しかなかったため。 しかしこれが大きな判断間違いだったようです。 結果として単純にメモリが1GB では余裕がほぼなくOS起動直後から上限に張り付いている状況。そこに dnf コマンドでメモリを使おうとしてメモリ枯渇で応答無しになったという推測が最有力となります。

# free
               total        used        free      shared  buff/cache   available
Mem:          736992      654368       47872        2440      146528       82624
Swap:              0           0           0

先ほど検証用に作成した 2vCPU、8GBメモリの ECS インスタンスをリリースし、もともとあった SAS インスタンスを1GBメモリから2GBメモリのタイプにアップグレードし応答無しが再発するか確認します。

SAS のコンソール管理画面から Upgrade を実行します。

注意事項を確認し、Go to the Upgrade page をクリックします。

Instance Plan について現在の 4.5ドル/月のものから 9ドル/月に変更します。

SAS インスタンスのステータスが Upgrading となるので完了するまで待ちます。3分もかからずに完了します。

Upgrade した SAS インスタンスに SSH ログインし、free コマンドでメモリの状態を確認します。 total は約 1735 MB と変更前の約737MBから1GB相当増えています。

# free
               total        used        free      shared  buff/cache   available
Mem:         1734876      711368      812296        2440      359148     1023508
Swap:              0           0           0

応答無しのトリガーとなっている dnf コマンドを実行してみます。 今度は問題なく正常終了しました。

# dnf install https://rpms.remirepo.net/enterprise/remi-release-9.rpm
Extra Packages for Enterprise Linux 9 openh264  2.4 kB/s | 2.5 kB     00:01
Extra Packages for Enterprise Linux 9 - Next -  3.6 MB/s | 1.8 MB     00:00
Remi's Modular repository for Enterprise Linux  254 kB/s | 673 kB     00:02
Safe Remi's RPM repository for Enterprise Linux 361 kB/s | 994 kB     00:02
Last metadata expiration check: 0:00:01 ago on Sat 20 Apr 2024 08:14:49 PM CST.
remi-release-9.rpm                               29 kB/s |  30 kB     00:01
Package remi-release-9.3-3.el9.remi.noarch is already installed.
Dependencies resolved.
Nothing to do.
Complete!

このとき、もう1つ別に接続していた SSH コネクションで free コマンドを実行した結果は以下です。実行中は 約 860MB ほどメモリを消費し、dnf コマンド終了後は 約700MBの消費量です。 この結果から dnf コマンド実行時に大体150-160MBほどメモリ消費が必要なことがわかります。

◆ dnf コマンド実行中
# free
               total        used        free      shared  buff/cache   available
Mem:         1734876      861932      586852        2448      434280      872944
Swap:              0           0           0

# free
               total        used        free      shared  buff/cache   available
Mem:         1734876      862408      584864        2448      435872      872468
Swap:              0           0           0

# free
               total        used        free      shared  buff/cache   available
Mem:         1734876      861668      584360        2448      437044      873208
Swap:              0           0           0

◆ dnf コマンド完了後
# free
               total        used        free      shared  buff/cache   available
Mem:         1734876      704140      730800        2448      448164     1030736
Swap:              0           0           0

以下は応答無しが発生していた1GBメモリのSAS インスタンスのfreeコマンドの結果の再掲ですがavailable が約83MB、buff/cacheが約147MBありますが150-160MBのメモリ消費が発生するとメモリ枯渇がちょうどおきそうな環境だったことがわかりました。

# free
               total        used        free      shared  buff/cache   available
Mem:          736992      654368       47872        2440      146528       82624
Swap:              0           0           0

結論として、 CentOS Stream 9 環境で Apache や MySQL を起動している状態で dnf コマンドを利用すると 1GB メモリではメモリ枯渇し応答が無くなるという結果でした。 Apache や MySQL をインストールし起動する前は dnf コマンドは問題なく使えていたので(OSパッチの更新や Apache や MySQLは問題なく行えていた)ちょうどギリギリ枯渇しそうなところだったと思われます。 逆に言えば 1GBメモリでもシステム用途によっては十分な可能性もあります。 

今回は実施しませんが不要なサービスやプロセスを落としていくようなチューニングを行うことで 1GB メモリでも大丈夫な可能性はあったかもしれません。 ちなみに run-level は 3(GUI無)なので GUI有だと 1GB メモリはきつそうですね・・。

あとは Swap が未構成なのにどうしてメモリ不足になると大量の Read の IO が発生したのかは謎のままです。。 その状態の時に何かしらコマンド(lsofとか)打てればわかりそうですが全く操作出来ずのため。 あとはメモリダンプ取って調べるというやり方もありますがそこまで手間かけるものでもなく(仕事ならやりますが個人の環境)。

以上