サーバハングアップの原因について調査する
2016 年 9 月 19 日
Comments off
先日に引き続きまたサーバが応答不能に陥ったようです。
早速強制再起動を実施後ログを洗ってみます。
18日と19日それぞれ朝には、ハングアップしているのでまず初めに時間的な観点から調べてみました。
18日のmessagesログ
Sep 18 04:58:31 www16071ue kernel: httpd invoked oom-killer: gfp_mask=0x200da, order=0, oom_adj=0, oom_score_adj=0 Sep 18 04:58:31 www16071ue kernel: httpd cpuset=/ mems_allowed=0 Sep 18 04:58:31 www16071ue kernel: Pid: 11436, comm: httpd Not tainted 2.6.32-642.4.2.el6.x86_64 #1 Sep 18 04:58:31 www16071ue kernel: Call Trace: Sep 18 04:58:31 www16071ue kernel: [<ffffffff81131420>] ? dump_header+0x90/0x1b0 Sep 18 04:58:31 www16071ue kernel: [<ffffffff8123bfec>] ? security_real_capable_ noaudit+0x3c/0x70 Sep 18 04:58:31 www16071ue kernel: [<ffffffff811318a2>] ? oom_kill_process+0x82/0x2a0 Sep 18 04:58:31 www16071ue kernel: [<ffffffff811317e1>] ? select_bad_process+0xe 1/0x120 Sep 18 04:58:31 www16071ue kernel: [<ffffffff81131ce0>] ? out_of_memory+0x220/0x3c0 Sep 18 04:58:31 www16071ue kernel: [<ffffffff8113e6bc>] ? __alloc_pages_nodemask +0x93c/0x950 Sep 18 04:58:31 www16071ue kernel: [<ffffffff810fb479>] ? delayacct_end+0x89/0xa0
19日のmessagesログ
Sep 19 04:31:13 www16071ue kernel: INFO: task mysqld:1578 blocked for more than 120 seconds. Sep 19 04:31:13 www16071ue kernel: Not tainted 2.6.32-642.4.2.el6.x86_64 #1 Sep 19 04:31:13 www16071ue kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Sep 19 04:31:13 www16071ue kernel: mysqld D 0000000000000001 0 1578 1333 0x00000000 Sep 19 04:31:13 www16071ue kernel: ffff88003a6efdf8 0000000000000082 0000000000000000 ffff88003741c080 Sep 19 04:31:13 www16071ue kernel: ffff8800374b4040 0000000000000282 000036fe33a5ffd9 00000000038fa318
上記を見ると朝方の4時過ぎにハングアップ状態に陥っているのが確認できる。
ユーザからのアクセスは、この時間帯はほぼ無いのであまりアクセス数の増加などでのハングアップは、考えられないです。
なのでcrontabでの毎朝方のジョブの実行かな？と思いました。
とりあえこの時間帯に何のジョブが行われているかを調べてみます。
/var/log配下にあるCRONのログを見てみます。
そのままでcronファイルです。
18日のcron
Sep 18 03:15:03 www16071ue run-parts(/etc/cron.daily)[10174]: finished 10_logrotate Sep 18 03:15:03 www16071ue run-parts(/etc/cron.daily)[9666]: starting 20_chkrootkit Sep 18 03:15:25 www16071ue /usr/bin/crontab[10268]: (root) LIST (nobody) Sep 18 03:20:01 www16071ue CROND[10812]: (root) CMD (/usr/lib64/sa/sa1 1 1) Sep 18 03:30:01 www16071ue CROND[11247]: (root) CMD (/usr/lib64/sa/sa1 1 1) Sep 18 03:34:57 www16071ue run-parts(/etc/cron.daily)[11262]: finished 20_chkrootkit Sep 18 03:34:57 www16071ue run-parts(/etc/cron.daily)[9666]: starting 40_freshclam Sep 18 03:37:16 www16071ue run-parts(/etc/cron.daily)[11270]: finished 40_freshclam Sep 18 03:37:16 www16071ue run-parts(/etc/cron.daily)[9666]: starting 50_virusscan Sep 18 03:40:08 www16071ue CROND[11280]: (root) CMD (/usr/lib64/sa/sa1 1 1) Sep 18 03:50:36 www16071ue CROND[11323]: (root) CMD (/usr/lib64/sa/sa1 1 1) Sep 18 04:00:23 www16071ue CROND[11330]: (root) CMD (/usr/lib64/sa/sa1 1 1) Sep 18 04:01:14 www16071ue CROND[11334]: (root) CMD (run-parts /etc/cron.hourly) Sep 18 04:01:20 www16071ue run-parts(/etc/cron.hourly)[11334]: starting 00awstats Sep 18 04:02:40 www16071ue run-parts(/etc/cron.hourly)[11345]: finished 00awstats Sep 18 04:02:41 www16071ue run-parts(/etc/cron.hourly)[11334]: starting 0anacron Sep 18 04:02:56 www16071ue anacron[11355]: Anacron started on 2016-09-18 Sep 18 04:02:57 www16071ue run-parts(/etc/cron.hourly)[11357]: finished 0anacron Sep 18 04:02:57 www16071ue anacron[11355]: Job `cron.daily' locked by another anacron - skipping Sep 18 04:02:58 www16071ue anacron[11355]: Normal exit (0 jobs run) Sep 18 04:10:15 www16071ue CROND[11369]: (root) CMD (/usr/lib64/sa/sa1 1 1) Sep 18 04:24:08 www16071ue crond[11528]: (root) INFO (Job execution of per-minute job scheduled for 04:20 delayed into subsequent minute 04:23. Skipping job run.) Sep 18 04:53:47 www16071ue crond[11567]: (root) INFO (Job execution of per-minute job scheduled for 04:30 delayed into subsequent minute 04:52. Skipping job run.) Sep 18 05:03:26 www16071ue crond[11570]: (root) INFO (Job execution of per-minute job scheduled for 05:00 delayed into subsequent minute 05:03. Skipping job run.) Sep 18 05:04:02 www16071ue crond[11569]: (root) INFO (Job execution of per-minute job scheduled for 04:50 delayed into subsequent minute 05:04. Skipping job run.) Sep 18 05:04:51 www16071ue CROND[11572]: (root) CMD (run-parts /etc/cron.hourly) Sep 18 05:08:59 www16071ue run-parts(/etc/cron.hourly)[11572]: starting 00awstats Sep 18 05:09:41 www16071ue run-parts(/etc/cron.daily)[11582]: finished 50_virusscan Sep 18 05:09:43 www16071ue run-parts(/etc/cron.daily)[9666]: starting iplist_check.sh Sep 18 05:13:02 www16071ue crond[11587]: (root) INFO (Job execution of per-minute job scheduled for 05:11 delayed into subsequent minute 05:13. Skipping job run.) ・・・・・・・
19日のcron
Sep 19 03:06:53 www16071ue run-parts(/etc/cron.daily)[6809]: finished 0yum.cron Sep 19 03:06:53 www16071ue run-parts(/etc/cron.daily)[6277]: starting 10_logrotate Sep 19 03:06:59 www16071ue run-parts(/etc/cron.daily)[6820]: finished 10_logrotate Sep 19 03:06:59 www16071ue run-parts(/etc/cron.daily)[6277]: starting 20_chkrootkit Sep 19 03:07:22 www16071ue /usr/bin/crontab[6915]: (root) LIST (nobody) Sep 19 03:10:12 www16071ue CROND[7451]: (root) CMD (/usr/lib64/sa/sa1 1 1) Sep 19 03:20:05 www16071ue CROND[7477]: (root) CMD (/usr/lib64/sa/sa1 1 1) Sep 19 03:30:05 www16071ue CROND[7906]: (root) CMD (/usr/lib64/sa/sa1 1 1) Sep 19 03:33:09 www16071ue run-parts(/etc/cron.daily)[7915]: finished 20_chkrootkit Sep 19 03:33:09 www16071ue run-parts(/etc/cron.daily)[6277]: starting 40_freshclam Sep 19 03:35:11 www16071ue run-parts(/etc/cron.daily)[7953]: finished 40_freshclam Sep 19 03:35:12 www16071ue run-parts(/etc/cron.daily)[6277]: starting 50_virusscan Sep 19 03:40:08 www16071ue CROND[7966]: (root) CMD (/usr/lib64/sa/sa1 1 1) Sep 19 03:50:43 www16071ue CROND[8027]: (root) CMD (/usr/lib64/sa/sa1 1 1) Sep 19 04:04:20 www16071ue crond[8086]: (root) INFO (Job execution of per-minute job scheduled for 04:00 delayed into subsequent minute 04:03. Skipping job run.) Sep 19 04:04:20 www16071ue CROND[8107]: (root) CMD (run-parts /etc/cron.hourly) Sep 19 04:09:25 www16071ue run-parts(/etc/cron.hourly)[8107]: starting 00awstats Sep 19 04:13:32 www16071ue crond[8122]: (root) INFO (Job execution of per-minute job scheduled for 04:10 delayed into subsequent minute 04:13. Skipping job run.) Sep 19 04:47:36 www16071ue crond[8182]: (root) INFO (Job execution of per-minute job scheduled for 04:31 delayed into subsequent minute 04:47. Skipping job run.) Sep 19 04:47:36 www16071ue crond[8166]: (root) INFO (Job execution of per-minute job scheduled for 04:21 delayed into subsequent minute 04:47. Skipping job run.) Sep 19 04:48:00 www16071ue crond[8193]: (root) INFO (Job execution of per-minute job scheduled for 04:43 delayed into subsequent minute 04:48. Skipping job run.) Sep 19 04:55:37 www16071ue crond[8208]: (root) INFO (Job execution of per-minute job scheduled for 04:50 delayed into subsequent minute 04:55. Skipping job run.) Sep 19 05:20:27 www16071ue CROND[8222]: (root) CMD (run-parts /etc/cron.hourly)
上記二日分のログをみるとやはりここにも怪しいログが出ています。
Sep 19 04:13:32 www16071ue crond[8122]: (root) INFO (Job execution of per-minute job scheduled for 04:10 delayed into subsequent minute 04:13. Skipping job run.)
というようなログがどちらのログにも出てきています。
調べてみるとcronの処理が遅れているというメッセージです。これの原因は、サーバの負荷が重過ぎるか、プログラムが重過ぎが原因でジョブを実行できないということらしいです。
17日以前のCRONログを見比べても特に変化しているものは、ないのですがどちらもvirusscanがstartedしてからなので一応そちらも調べてみます。
messagesなどには、特にエラーは、吐かれていませんでした。
cronで動いているものにsarコマンドが10分後とに実行されているのでこのデータを確認しておきます。
[root@www16071ue log]# sar -f /var/log/sa/sa18|less
このコマンドで18日のサーバの状態が確認できます。
Linux 2.6.32-642.4.2.el6.x86_64 (www16071ue.sakura.ne.jp) 2016年09月18日 _x86_64_ (2 CPU) 00時00分01秒 CPU %user %nice %system %iowait %steal %idle 00時10分01秒 all 1.94 0.00 0.14 3.57 0.20 94.14 ～ 中略 ～ 01時20分01秒 all 0.60 0.00 0.06 2.61 0.12 96.61 01時30分01秒 all 1.30 0.00 0.09 1.58 0.18 96.84 01時40分05秒 all 1.93 0.00 0.22 25.66 0.21 71.98 01時50分04秒 all 1.30 0.00 0.23 50.36 0.19 47.91 02時00分03秒 all 1.99 0.00 0.26 50.91 0.22 46.62 02時10分01秒 all 0.86 0.00 0.22 50.63 0.19 48.10 02時20分04秒 all 2.54 0.00 0.28 51.17 0.20 45.80 02時30分02秒 all 0.61 0.00 0.18 50.61 0.15 48.45 02時40分06秒 all 0.81 0.74 0.27 55.51 0.17 42.50 02時50分03秒 all 1.48 0.00 0.21 51.47 0.17 46.68 03時00分13秒 all 1.31 0.00 0.17 50.57 0.15 47.80 03時10分05秒 all 0.98 0.00 0.13 51.57 0.13 47.19 03時20分01秒 all 0.72 0.38 0.24 62.60 0.14 35.91 03時30分01秒 all 1.46 0.09 0.30 60.74 0.19 37.22 03時40分10秒 all 1.40 0.47 0.23 58.78 0.14 38.99 03時50分51秒 all 0.27 2.03 0.23 67.23 0.14 30.10 04時00分37秒 all 0.30 1.50 0.20 78.60 0.15 19.24 04時10分32秒 all 1.30 0.78 0.25 84.40 0.19 13.08 06時13分18秒 all 0.34 0.01 0.15 99.32 0.12 0.07 07時37分26秒 all 0.06 0.00 0.10 99.73 0.10 0.00 11時06分34秒 all 0.04 0.01 0.12 99.72 0.11 0.00 12時00分01秒 all 1.96 0.00 0.23 15.66 0.21 81.93 12時10分01秒 all 3.02 0.00 0.28 4.87 0.15 91.68 12時20分01秒 all 2.15 0.79 0.30 10.46 0.17 86.13 12時30分01秒 all 1.26 0.31 0.25 28.37 0.17 69.63 12時40分22秒 all 1.12 2.77 0.44 58.59 0.17 36.91 12時50分17秒 all 1.22 1.90 0.24 58.87 0.20 37.56 13時00分13秒 all 2.47 1.82 0.30 57.19 0.25 37.96 13時10分09秒 all 1.25 1.93 0.22 54.18 0.19 42.24 13時20分08秒 all 0.93 2.33 0.26 56.19 0.22 40.08 13時30分07秒 all 1.10 2.41 0.29 51.31 0.19 44.70
17日（正常な日）
Linux 2.6.32-642.4.2.el6.x86_64 (www16071ue.sakura.ne.jp) 2016年09月17日 _x86_64_ (2 CPU) 00時00分01秒 CPU %user %nice %system %iowait %steal %idle 00時10分02秒 all 2.95 0.00 0.28 42.31 0.27 54.18 ～ 中略 ～ 02時30分03秒 all 0.31 0.69 0.33 52.83 0.18 45.68 02時40分06秒 all 1.16 0.00 0.25 52.59 0.18 45.82 02時50分05秒 all 1.48 0.00 0.25 51.19 0.17 46.91 03時00分10秒 all 1.39 0.41 0.39 65.05 0.21 32.55 03時10分11秒 all 0.97 0.65 0.35 66.48 0.17 31.38 03時20分42秒 all 0.87 2.35 0.42 69.31 0.23 26.83 03時30分19秒 all 0.87 1.74 0.35 81.41 0.22 15.42 03時40分17秒 all 1.03 1.22 0.28 74.43 0.24 22.81 03時50分14秒 all 0.59 2.08 0.33 70.85 0.26 25.90 04時00分12秒 all 0.47 2.68 0.37 70.59 0.28 25.62 04時10分08秒 all 1.49 2.22 0.45 73.34 0.25 22.26 04時20分09秒 all 2.49 6.38 0.79 74.19 0.41 15.74 04時30分13秒 all 0.98 2.42 0.37 72.29 0.27 23.67 04時40分09秒 all 0.93 1.90 0.25 67.16 0.21 29.55 04時50分15秒 all 0.85 2.49 0.26 71.33 0.19 24.88 05時00分12秒 all 0.72 1.56 0.22 67.87 0.17 29.46 05時10分08秒 all 1.16 1.86 0.27 69.37 0.19 27.16 05時20分23秒 all 0.96 4.29 0.40 68.05 0.17 26.14 05時30分14秒 all 0.77 0.41 0.21 63.04 0.14 35.43 05時40分15秒 all 0.62 0.09 0.19 65.19 0.13 33.77 05時50分16秒 all 1.20 0.08 0.22 62.17 0.15 36.17 06時00分15秒 all 0.93 0.09 0.22 64.64 0.14 33.98 06時10分07秒 all 0.61 0.07 0.19 62.86 0.13 36.13 06時20分07秒 all 0.79 1.55 0.23 63.07 0.16 34.20 06時30分13秒 all 0.74 0.05 0.17 61.09 0.13 37.83 06時40分08秒 all 0.56 0.07 0.15 61.26 0.13 37.83 06時50分07秒 all 1.27 0.23 0.25 66.18 0.17 31.90 07時00分07秒 all 1.30 0.19 0.23 66.30 0.16 31.83 07時10分07秒 all 0.81 1.12 0.19 66.72 0.16 31.00
上記を比較すると
その時間帯（多分4時10分以降）は、idleが０％に落ちていること当然、応答不能ですね。それとiowaitが非常に高い値になっていること。
これでわかることは、
%iowaitの値 高い
%systemの値 低い
これは、システムの物理メモリ量を超えてメモリを使用してしまい、swap領域を食いつぶしてハングアップしてしまったようです。
では、どのプロセスがメモリを食いつぶしてしまったかです。
これは、そのときに動いていたプロセスを調べないといけません。
また、物理メモリを増設すれば簡単？に解決できますがVPSサーバを借りているのでまず不可能です。
まずは、大食いメモリを調べることが先決なようです。
ロードアベレージも調べてみます。
[root@www16071ue sa]# sar -q Linux 2.6.32-642.4.2.el6.x86_64 (www16071ue.sakura.ne.jp) 2016年09月19日 _x86_64_ (2 CPU) 00時00分02秒 runq-sz plist-sz ldavg-1 ldavg-5 ldavg-15 00時10分02秒 0 130 0.21 0.20 0.16 00時20分07秒 0 130 0.74 0.67 0.39 00時30分01秒 0 130 0.14 0.16 0.25 00時40分01秒 0 130 0.15 0.22 0.23 00時50分01秒 0 130 0.10 0.12 0.17 01時00分01秒 0 130 0.09 0.20 0.18 01時10分01秒 0 130 0.12 0.20 0.21 01時20分01秒 0 130 0.05 0.10 0.15 01時30分01秒 0 130 0.10 0.12 0.12 01時40分04秒 1 134 1.20 0.75 0.37 01時50分04秒 0 134 1.49 1.14 0.73 02時00分05秒 0 134 1.28 1.18 0.92 02時10分04秒 0 135 1.10 1.09 0.99 02時20分01秒 0 139 1.55 1.24 1.08 02時30分03秒 1 140 1.13 1.17 1.15 02時40分03秒 0 139 1.60 1.52 1.32 02時50分01秒 0 139 1.14 1.19 1.23 03時00分06秒 0 139 1.15 1.13 1.16 03時10分16秒 3 142 2.67 2.09 1.58 03時20分07秒 0 142 2.27 2.16 1.85 03時30分06秒 0 141 2.10 2.14 1.99 03時40分14秒 0 139 2.71 2.51 2.21 03時51分09秒 0 146 9.87 5.34 3.40 06時43分31秒 1 218 111.06 112.19 111.70 07時34分50秒 0 222 111.03 112.30 112.59
3時50分以降に上昇しているのがわかります。こちらからもメモリ不足の可能性を示しています。
[root@www16071ue sa]# sar -W Linux 2.6.32-642.4.2.el6.x86_64 (www16071ue.sakura.ne.jp) 2016年09月19日 _x86_64_ (2 CPU) 00時00分02秒 pswpin/s pswpout/s 00時10分02秒 0.24 1.88 00時20分07秒 1.84 6.82 00時30分01秒 0.00 1.77 00時40分01秒 1.07 3.12 00時50分01秒 0.17 0.00 01時00分01秒 0.00 0.00 01時10分01秒 0.18 1.87 01時20分01秒 0.00 0.00 01時30分01秒 0.00 0.00 01時40分04秒 0.02 0.57 01時50分04秒 0.00 2.81 02時00分05秒 0.00 5.62 02時10分04秒 0.00 12.46 02時20分01秒 0.02 4.11 02時30分03秒 0.00 5.23 02時40分03秒 0.06 2.11 02時50分01秒 0.01 1.83 03時00分06秒 0.09 1.73 03時10分16秒 0.31 6.88 03時20分07秒 0.03 5.54 03時30分06秒 0.00 3.67 03時40分14秒 0.04 6.31 03時40分14秒 pswpin/s pswpout/s 03時51分09秒 11.63 67.37 06時43分31秒 44.10 66.15 07時34分50秒 37.84 14.63
ダメ押しのSWAPファイルのinとoutの利用率ですが、やはり3時40分以降に急激に増えています。
やはりこの時間以降に何かが動いてメモリを食いつぶしているようです。
ここまでやはり何か原因があってのハングアップですね。
まだ核心に迫れないのですが次に続く
*****************************************************************************
にほんブログ村
