![[Lightsail]徒労日記のサイトダウンの詳細調査](https://i0.wp.com/dolls.tokyo/wp-content/uploads/2016/05/wordpress-logo-stacked-rgb.png?fit=499%2C310&ssl=1){kind=logo}
遭遇した方が居たら申し訳ない。
未だに徒労日記は定期的にハングします。
ただ、前に書いた定期処刑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
まず問題発生時に変化のあった項目をピックアップ。
そこからサービス停止による負荷低下と思われる項目を除外しました。
その結果残ったのは以下の３つ。
- メモリ: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だけ定期リスタしたほうがマシ」というのが現時点での考え。
毎日リブートすれば発生しない事は確認済みです。
そのうちイメージが更新されている頃を見計らい、インスタンスを作り直そうかと思います。