アーカイブ

2016 年 9 月 19 日 のアーカイブ

サーバハングアップの原因について調査する

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が0%に落ちていること当然、応答不能ですね。それと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分以降に急激に増えています。

やはりこの時間以降に何かが動いてメモリを食いつぶしているようです。

ここまでやはり何か原因があってのハングアップですね。

まだ核心に迫れないのですが次に続く

*****************************************************************************

ブログランキング・にほんブログ村へ

にほんブログ村

PVアクセスランキング にほんブログ村

カテゴリー: Linux, Logwatch タグ: ,