DiscourseはRAMをあまり使用しない

こんにちは!
昨日確認したときはサイトは正常でしたが、今朝起きたら502 Bad Gatewayエラーでダウンしていました。モニタログはこちらです monitor.txt (9.4 MB)

わあ…Java がこんなに多いなんて!私の Jitsi サーバーもかつては同じように混乱していました。
また、ホストをメールサーバーとして使用しているようですが、私は最終的にそれをアプリから分離しました。そうすれば、将来的に復元しやすくなり、標準的な本番環境のインストールにできるだけ近い状態で整理整頓を保つことができます。フローティング IP を備えた非常に小さなメールインスタンスの方が、評判の監視がしやすく、コストもわずかに抑えられるかもしれません。

OK、見てみましょう…まず「average」でgrepします:

 06:24:13 up 3 days,  8:13,  0 users,  load average: 0.01, 0.05, 0.08
 06:34:33 up 3 days,  8:23,  0 users,  load average: 12.89, 11.68, 6.35

つまり、06:34 の少し前に、実行可能なプロセスの数という点で何かが大爆発しました。

もう少し範囲を広げてgrepすると、メモリ使用量は実際にはほとんど変わっていないことがわかります:

 06:24:13 up 3 days,  8:13,  0 users,  load average: 0.01, 0.05, 0.08
              total        used        free      shared  buff/cache   available
Mem:        8167548     3513172     3241404      371940     1412972     4512016
Swap:      10485756           0    10485756
--
 06:34:33 up 3 days,  8:23,  0 users,  load average: 12.89, 11.68, 6.35
              total        used        free      shared  buff/cache   available
Mem:        8167548     3110612     1351844      373268     3705092     4812672
Swap:      10485756           0    10485756

むしろ、メモリ使用量は減少しています。何かのプロセスが終了したのかもしれません:

 06:13:53 up 3 days,  8:02,  0 users,  load average: 0.04, 0.16, 0.15
              total        used        free      shared  buff/cache   available
Mem:        8167548     3505540     3259744      371932     1402264     4519680
 06:24:13 up 3 days,  8:13,  0 users,  load average: 0.01, 0.05, 0.08
              total        used        free      shared  buff/cache   available
Mem:        8167548     3513172     3241404      371940     1412972     4512016
 06:34:33 up 3 days,  8:23,  0 users,  load average: 12.89, 11.68, 6.35
              total        used        free      shared  buff/cache   available
Mem:        8167548     3110612     1351844      373268     3705092     4812672
 06:44:53 up 3 days,  8:33,  0 users,  load average: 13.64, 13.25, 9.89
              total        used        free      shared  buff/cache   available
Mem:        8167548     3093212     3618984      373276     1455352     4840140
 06:55:13 up 3 days,  8:44,  0 users,  load average: 11.62, 12.70, 11.42
              total        used        free      shared  buff/cache   available
Mem:        8167548     3140580     3366628      373352     1660340     4792440

どうやらユニコーン(Unicorn)が再起動したようです:

Thu Aug  5 06:24:13 CEST 2021
 06:24:13 up 3 days,  8:13,  0 users,  load average: 0.01, 0.05, 0.08
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root     30389  0.0  0.0   2160  1148 ?        Ss   Aug03   0:00          \\_ runsv unicorn
x        13329  0.0  0.0  15132  3712 ?        S    Aug04   0:26              \\_ /bin/bash config/unicorn_launcher -E production -c config/unicorn.conf.rb
x        13365  0.0  3.0 542036 251584 ?       Sl   Aug04   0:23                  \\_ unicorn master -E production -c config/unicorn.conf.rb
x        13846  0.6  4.5 9129356 371852 ?      SNl  Aug04   4:19                  |   \\_ sidekiq 6.2.1 discourse [0 of 5 busy]
x        13858  0.0  3.9 8971616 323264 ?      Sl   Aug04   0:18                  |   \\_ unicorn worker[0] -E production -c config/unicorn.conf.rb
x        13870  0.0  4.0 8975712 330660 ?      Sl   Aug04   0:20                  |   \\_ unicorn worker[1] -E production -c config/unicorn.conf.rb
x        13889  0.0  4.1 8979808 337180 ?      Sl   Aug04   0:20                  |   \\_ unicorn worker[2] -E production -c config/unicorn.conf.rb
x        29760  0.0  0.0  13708  2220 ?        S    06:24   0:00                  \\_ sleep 1

Thu Aug  5 06:34:33 CEST 2021
 06:34:33 up 3 days,  8:23,  0 users,  load average: 12.89, 11.68, 6.35
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root     30389  0.0  0.0   2160  1148 ?        Ss   Aug03   0:00          \\_ runsv unicorn
x         4638  0.4  0.0  15132  3784 ?        S    06:32   0:00              \\_ /bin/bash config/unicorn_launcher -E production -c config/unicorn.conf.rb
x         4642 11.1  2.8 439636 233240 ?       Sl   06:32   0:11                  \\_ unicorn master -E production -c config/unicorn.conf.rb
x         4822 13.1  3.7 8877408 309844 ?      Sl   06:33   0:10                  |   \\_ unicorn worker[1] -E production -c config/unicorn.conf.rb
x         5025 15.6  3.7 8873312 310264 ?      Sl   06:33   0:10                  |   \\_ unicorn worker[0] -E production -c config/unicorn.conf.rb
x         5065 20.6  3.9 8922504 320740 ?      SNl  06:33   0:11                  |   \\_ sidekiq 6.2.1 discourse [0 of 5 busy]
x         5639  0.0  0.0  13708  2264 ?        S    06:34   0:00                  \\_ sleep 1

また、Apache が起動に苦労しているようにも見えます:

Thu Aug  5 06:24:13 CEST 2021
 06:24:13 up 3 days,  8:13,  0 users,  load average: 0.01, 0.05, 0.08
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root     13730  0.0  0.1 225016 15840 ?        Ss   Aug02   0:17 /usr/sbin/apache2 -k start
www-data 10232  0.0  0.1 1352372 10972 ?       Sl   Aug03   0:00  \\_ /usr/sbin/apache2 -k start
www-data 27998  0.0  0.1 228880  9608 ?        S    Aug04   0:01  \\_ /usr/sbin/apache2 -k start
www-data 28000  0.0  0.3 3036536 27796 ?       Sl   Aug04   0:53  \\_ /usr/sbin/apache2 -k start
www-data 28002  0.0  0.3 2904772 26524 ?       Sl   Aug04   0:50  \\_ /usr/sbin/apache2 -k start
www-data 28185  0.0  0.1 762472 10952 ?        Sl   Aug04   0:00  \\_ /usr/sbin/apache2 -k start

Thu Aug  5 06:34:33 CEST 2021
 06:34:33 up 3 days,  8:23,  0 users,  load average: 12.89, 11.68, 6.35
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root     13730  0.0  0.1 225024 15856 ?        Ss   Aug02   0:17 /usr/sbin/apache2 -k start
www-data 10232  0.0  0.1 1352372 10972 ?       Sl   Aug03   0:00  \\_ /usr/sbin/apache2 -k start
www-data 28185  0.0  0.1 762472 10952 ?        Sl   Aug04   0:00  \\_ /usr/sbin/apache2 -k start
www-data 30794  0.0  0.1 228888  9620 ?        S    06:25   0:00  \\_ /usr/sbin/apache2 -k start
www-data 31490  0.0  0.1 344564 10852 ?        Sl   06:25   0:00  \\_ /usr/sbin/apache2 -k start
www-data 32095  0.0  0.1 500228 10888 ?        Sl   06:25   0:00  \\_ /usr/sbin/apache2 -k start
www-data 32215 83.2  0.1 369152 10876 ?        Sl   06:25   7:26  \\_ /usr/sbin/apache2 -k start
www-data 32284  0.0  0.1 229400  9936 ?        S    06:25   0:00  \\_ /usr/sbin/apache2 -k start
www-data 32382  187  0.1 410136 10916 ?        Sl   06:25  16:31  \\_ /usr/sbin/apache2 -k start
www-data 32410  0.0  0.1 229400  9936 ?        S    06:25   0:00  \\_ /usr/sbin/apache2 -k start
www-data 32545  0.0  0.1 229400  9936 ?        S    06:25   0:00  \\_ /usr/sbin/apache2 -k start
www-data  2106  0.0  0.1 3032348 11396 ?       Sl   06:27   0:00  \\_ /usr/sbin/apache2 -k start
www-data  2240  0.0  0.1 2901012 11416 ?       Sl   06:27   0:00  \\_ /usr/sbin/apache2 -k start
www-data  2241  0.0  0.1 2901184 14220 ?       Sl   06:27   0:00  \\_ /usr/sbin/apache2 -k start

Thu Aug  5 06:44:53 CEST 2021
 06:44:53 up 3 days,  8:33,  0 users,  load average: 13.64, 13.25, 9.89
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root     13730  0.0  0.1 225024 15856 ?        Ss   Aug02   0:17 /usr/sbin/apache2 -k start
www-data 10232  0.0  0.1 1352372 10972 ?       Sl   Aug03   0:00  \\_ /usr/sbin/apache2 -k start
www-data 28185  0.0  0.1 762472 10952 ?        Sl   Aug04   0:00  \\_ /usr/sbin/apache2 -k start
www-data 30794  0.0  0.1 228888  9620 ?        S    06:25   0:00  \\_ /usr/sbin/apache2 -k start
www-data 31490  0.0  0.1 344564 10852 ?        Sl   06:25   0:00  \\_ /usr/sbin/apache2 -k start
www-data 32095  0.0  0.1 500228 10888 ?        Sl   06:25   0:00  \\_ /usr/sbin/apache2 -k start
www-data 32215 82.1  0.1 369152 10876 ?        Sl   06:25  15:50  \\_ /usr/sbin/apache2 -k start
www-data 32284  0.0  0.1 229400  9936 ?        S    06:25   0:00  \\_ /usr/sbin/apache2 -k start
www-data 32382  188  0.1 410136 10916 ?        Sl   06:25  36:10  \\_ /usr/sbin/apache2 -k start
www-data 32410  0.0  0.1 229400  9936 ?        S    06:25   0:00  \\_ /usr/sbin/apache2 -k start
www-data 32545  0.0  0.1 229400  9936 ?        S    06:25   0:00  \\_ /usr/sbin/apache2 -k start
www-data  2106  0.0  0.1 3032348 11396 ?       Sl   06:27   0:00  \\_ /usr/sbin/apache2 -k start
www-data  2240  0.0  0.1 2901012 11416 ?       Sl   06:27   0:00  \\_ /usr/sbin/apache2 -k start
www-data  2241  0.0  0.1 2901184 14432 ?       Sl   06:27   0:00  \\_ /usr/sbin/apache2 -k start

多数のフォークされた Apache プロセスがあり、そのうちの一つが 83% の CPU を消費し、もう一つが 188% の CPU を消費している点に注目してください。何かおかしいことが起きています。

しかし、この発見に対して何をすべきか確信が持てません。

最近、カーネルが何かを殺す理由があったか確認してみる価値もあるかもしれません:
dmesg -T | egrep -i kille

そのコマンドを実行しても何も出力されません。

おそらく、友人が MPM prefork から MPM Event に切り替えたことが原因だと思います。それ以来 Apache の使用量が大幅に増えましたが、Discourse 以降はサイトがクラッシュしたり不具合が起きたりすることはありません。私は MPM prefork に戻しました。これで改善するかもしれません。

Java はどうやら Varnish キャッシュだったようです。プロセスのツリーを開いてみると、ベースが Varnish でした。Java よりもこちらの方がずっと納得がいきます :smiley:

「いいね!」 1

MPM Event は Apache をマルチスレッドで動作させ、より多くの訪問者を処理できるようにします。これには、現在一般的に PHP-FPM として知られる独立した PHP サービスとの組み合わせが必要です。サーバーが混雑している場合、Prefork は Apache と PHP のパフォーマンスを制限してしまいます。Event が過剰なリソースを消費している場合、その原因は Event に対して不適切に設定された FPM である可能性が最も高いですが、最適化されていない MPM Event 自体が問題となることもあります。

Prefork は、同時アクセスの少ないサーバーでは問題なく動作しますが、Apache の現在の標準は Event/FPM です。

それは良いことだと思います…

ありがとうございます、お手伝いできて嬉しいです :slight_smile:

MPM preforkに戻したところ、Apacheは3日間クラッシュしていません。これで問題が完全に解決することを願っています。皆様のご支援、ありがとうございました :slight_smile:

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.