[Lightsail]徒労日記のサイトダウンの詳細調査

[Lightsail]徒労日記のサイトダウンの詳細調査

遭遇した方が居たら申し訳ない。
未だに徒労日記は定期的にハングします。
ただ、前に書いた定期処刑cronのおかげで30分以内には復旧している、という状況。

結論としては解決に至らなかったのだけど、調査の過程を記します。

発生状態をsysstatで観察

sysstatをインストールし、発生時の各ステータスを調べてみる事にしました。
/var/log/sysstatに溜まるsa**ログから、2回分の数字を拾っています。

10:55及び12:55がApacheの再起動直前=ハング中のステータス。
そして次が再起動して復帰した後の数値。
ベースラインとして1日平穏だった日のAverageログも追記してあります。

/var/log/sysstat$sar -A -f sa**

00:00:01     pgpgin/s pgpgout/s   fault/s  majflt/s  pgfree/s pgscank/s pgscand/s pgsteal/s    %vmeff
10:55:01         2.99      1.33      5.02      0.05     21.59      0.00      2.76      2.67     96.75
11:15:01         6.05     20.59    136.01      0.01    157.03      0.00      0.00      0.00      0.00

12:55:01         4.11      3.83     21.18      0.08    165.54      0.00      0.00      0.00      0.00
13:15:01         6.83     20.02    119.86      0.03    232.65     15.95      0.00     15.28     95.79
---
Average:         9.44     31.75    194.14      0.03    379.69      1.84      1.46      3.16     95.58


00:00:01          tps      rtps      wtps   bread/s   bwrtn/s
10:55:01         0.35      0.15      0.20      5.97      2.67
11:05:01        17.58     15.84      1.75    546.60     65.34
11:15:01         1.99      0.47      1.52     12.09     41.17

12:55:01         0.61      0.21      0.40      8.21      7.67
13:05:01        14.81     12.92      1.90    372.85     64.76
13:15:01         2.20      0.63      1.57     13.67     40.04
---
Average:         2.59      0.49      2.10     18.88     63.51


00:00:01    kbmemfree   kbavail kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit  kbactive   kbinact   kbdirty  kbanonpg    kbslab  kbkstack   kbpgtbl  kbvmused
10:55:01       307936    459856    330908     32.73     77516    222996   1027044     61.84    333452    274624        28    291880     71584      2080      5940         0
11:05:01       165108    448632    321600     31.81     94752    354936   4224100    254.32    568584    170544         8    288412     74544      8368      6376         0
11:15:01       100204    395796    379896     37.58     94868    361464   4290508    258.32    620788    180604         4    344044     74508      8360      6740         0

12:55:01       204196    420296    332372     32.88     78528    323324   1010648     60.85    489688    220796        56    293272     72520      2080      5904         0
13:05:01        82764    405492    357976     35.41     94400    396272   4273896    257.32    673812    141196        16    319392     79528      8384      6808         0
13:15:01        95824    387976    375216     37.12     91288    370164   4254916    256.18    567876    234232       112    337544     78448      8384      6732         0
---
Average:       171820    393277    371643     36.76     79021    310717   3962480    238.57    450747    273842       129    321412     77739      7905      7335         0



00:00:01    kbswpfree kbswpused  %swpused  kbswpcad   %swpcad
10:45:01       580108     69888     10.75     12968     18.56
10:55:01       580108     69888     10.75     12980     18.57
11:05:01       619276     30720      4.73      1792      5.83

12:55:01       571148     78848     12.13     14996     19.02
13:05:01       617996     32000      4.92      1680      5.25
13:15:01       617484     32512      5.00      1880      5.78
---
Average:       599583     50413      7.76      9801     19.44


00:00:01    dentunusd   file-nr  inode-nr    pty-nr
10:55:01         5635       768     14539         0
11:05:01        11125       736     18696         0
11:15:01        11203       768     18688         0

12:55:01         7508       768     15574         0
13:05:01        14484       736     21395         0
13:15:01        11919       768     20844         0
---
Average:         7703       770     16178         0


00:00:01      runq-sz  plist-sz   ldavg-1   ldavg-5  ldavg-15   blocked
10:55:01            0       116      0.00      0.00      0.00         0
11:05:01            0       509      0.00      0.02      0.00         0
11:15:01            0       509      0.00      0.00      0.00         0

12:55:01            0       116      0.00      0.00      0.00         0
13:05:01            0       510      0.08      0.02      0.01         0
13:15:01            0       510      0.12      0.03      0.01         0
---
Average:            0       480      0.02      0.01      0.00         0


00:00:01          DEV       tps     rkB/s     wkB/s   areq-sz    aqu-sz     await     svctm     %util
10:55:01     dev202-0      0.35      2.99      1.33     12.23      0.98      1.04   2765.51     97.71
11:05:01     dev202-0     17.58    273.30     32.67     17.40      1.00      0.95     56.48     99.31
11:15:01     dev202-0      1.99      6.05     20.59     13.35      1.00      0.91    500.43     99.83

12:55:01     dev202-0      0.61      4.11      3.83     13.09      0.99      0.97   1631.01     98.95
13:05:01     dev202-0     14.81    186.43     32.38     14.77      0.99      0.86     66.67     98.74
13:15:01     dev202-0      2.20      6.83     20.02     12.21      1.00      0.98    454.55    100.00
---
Average:     dev202-0      2.59      9.44     31.75     15.91      0.99      0.98    383.24     99.26


00:00:01        IFACE   rxpck/s   txpck/s    rxkB/s    txkB/s   rxcmp/s   txcmp/s  rxmcst/s   %ifutil
10:55:01         eth0      0.56      0.51      0.07      0.16      0.00      0.00      0.00      0.00
11:05:01         eth0      2.77      2.45      1.05      2.86      0.00      0.00      0.00      0.00
11:15:01         eth0      2.97      2.36      1.11      3.48      0.00      0.00      0.00      0.00

12:55:01         eth0      0.88      1.43      0.10      0.52      0.00      0.00      0.00      0.00
13:05:01         eth0      4.46      4.52      1.64      4.72      0.00      0.00      0.00      0.00
13:15:01         eth0      2.91      2.94      1.11      2.52      0.00      0.00      0.00      0.00
---
Average:         eth0      4.11      3.93      1.09      4.84      0.00      0.00      0.00      0.00


00:00:01       totsck    tcpsck    udpsck    rawsck   ip-frag    tcp-tw
10:55:01          129         2         2         0         0         0
11:05:01           83         2         2         0         0         0
11:15:01           83         2         2         0         0         3

12:55:01          111         2         2         0         0         0
13:05:01           89         2         2         0         0         1
13:15:01           83         2         2         0         0         1
---
Average:           83         2         2         0         0         3


09:05:01        CPU   total/s   dropd/s squeezd/s  rx_rps/s flw_lim/s
10:55:01        all      0.56      0.00      0.00      0.00      0.00
10:55:01          0      0.56      0.00      0.00      0.00      0.00
11:05:01        all      2.32      0.00      0.00      0.00      0.00
11:05:01          0      2.32      0.00      0.00      0.00      0.00
11:15:01        all      2.50      0.00      0.00      0.00      0.00
11:15:01          0      2.50      0.00      0.00      0.00      0.00

12:55:01        all      0.88      0.00      0.00      0.00      0.00
12:55:01          0      0.88      0.00      0.00      0.00      0.00
13:05:01        all      3.82      0.00      0.00      0.00      0.00
13:05:01          0      3.82      0.00      0.00      0.00      0.00
13:15:01        all      2.44      0.00      0.00      0.00      0.00
13:15:01          0      2.44      0.00      0.00      0.00      0.00
---
Average:        all      3.77      0.00      0.00      0.00      0.00

まず問題発生時に変化のあった項目をピックアップ。
そこからサービス停止による負荷低下と思われる項目を除外しました。

その結果残ったのは以下の3つ。

  • メモリ:kbswapusedの増加
  • I/O:svctmの増加
  • ソケット数:totsckの増加

当初はメモリを疑ってsarを調べ始めました。
ですがよくよく調べるとほぼ負荷低下による数値であり、リークなど分かりやすいメモリの増加などは見つかりませんでした。

増えているbkswapused(%swpused)は再起動後から微増し、概ね12%の時に問題が起きています。ただkbswapfree 571k:kbswapused 79kという数字が果たして悪なのか?何が増加させているのか?が分かっていません。
また、svctm=I/Oリクエストが実際に処理される平均時間(ms)も注目しました。数日間のログと比較すると、発生のタイミングだけ瞬間的に増加しています。ただしこれもhttpdのハングが先で悪化しているのか、別原因によるストレージロックが先なのかが分からない。

この調査をまとめると

  • ”%swpused”が11%近くまで上がってきたら危険サイン。
  • sysstatだけで問題を言い当てる事は難しい。

という結論に至りました・・・。

WordPressのリソースを変えて切り分け

Lightsailは世界的に実績アリのWordpress環境と信じます。
なので、後から入れたデータに問題がある方が高確率。
という事で時間をかけて以下を確認しました。

  • テーマはどれに変えても発生する
  • プラグインをJetpackとWPアソシエイトポストR2だけにしても発生する。
  • データベースのチェックは正常

プラグインをオール0にして試さないのは、ブログの生命線だから。
怪しいとは思っているけれど「これを無くしたら動く」では意味を成さないため実施していません。

MaxRequestsPerChildを設定する

プラグインを疑いながらも解決方法を模索。
問題を相談したら、いい記事を教えてもらいました。

定期的に再起動が必要なほど不安定なApacheをチューニングする

HTTPサーバーが不安定だからといってcrontabへ

# 毎朝3時にapacheを再起動
0 3 * * * /etc/init.d/httpd graceful 

のように書き込んでしまう前に、チューニングで何とかしようという話。

やば。やってた。
自分の置かれる状態もこの方がすべて文章化されています。

Apache自身は歴史も実績もあり非常に安定しています。
(中略)
なので疑うべきはCGIやmod_XXXで走るスクリプトです。プログラムのどこかでメモリリークを起こしていたり、解放すべきリソースが解放されず残っていたり…。

これらのバグは原因が特定できれば当然直すべきですが、リークした箇所を特定して改修するというのは相応のスキルと時間が要求されます。明示的なバグとは違ってリークしていても正常に動いてしまうので原因特定が難しいのです。

ということで、記事に従いApacheへMaxRequestsPerChildを設定してみました。

bitnamiのhttpd.confからincludeされる全ての.confを調べ、下記のファイルに記述しました。
AWSのガイドに従い当初は4,500でテスト、改善しなかったため2,500まで落としました。

EC2 Linux インスタンスで Apache サーバーのメモリを調整する

潜在的なメモリリークの影響を軽減するには、変数 MaxRequestsPerChild のデフォルト値を 4500 に設定します。

$ sudo vi /opt/bitnami/apache/conf/bitnami/httpd.conf

<IfModule mpm_prefork_module>
....
MaxRequestsPerChild 2500
</IfModule>

<IfModule mpm_event_module>
....
MaxRequestsPerChild 2500
</IfModule>

$ sudo vi /opt/bitnami/apache/conf/extra/httpd-default.conf
MaxRequestsPerChild 2500

結局リブート対処療法

しかし残念ながらこれでもハングは改善していません。
ほぼ決まったように48時間ほどで発生するので、何かが蓄積しているのは間違いそうなんですが・・・わからない。

結論として「2日おきに十数分間ハングするなら、毎日深夜にhttpdだけ定期リスタしたほうがマシ」というのが現時点での考え。
毎日リブートすれば発生しない事は確認済みです。

そのうちイメージが更新されている頃を見計らい、インスタンスを作り直そうかと思います。

参考

Manpage of SAR

【学習メモ】 sysstatパッケージのコマンドを知ってトラブルに備える – Qiita

iostat await svctm の 見かた、考え方

コメントを残す