Apache 2.2.3+MySQL 5.0.95+WordPressでCPU 100%となる

Apache 2.2.3+MySQL 5.0.95+WordPressでCPU 100%となるので、原因を調べてみました。

Apache 2.2.3でCPU100%
PHP Fatal error: Maximum execution time of 30 seconds exceeded
Out of memory: Killed process 32592, UID 27, (mysqld)
Apache Killer(CVE-2011-3192)が原因か？
2014.11.14 追記 nginxへ移行しました
さくらのVPSサーバー

Apache 2.2.3でCPU100%

当ブログはさくらインターネットのVPS(仮想専用サーバー)を使っていますが、時々ApacheのCPU負荷が100%になってサーバーのアクセスができなくなることがあるようです。

先日もアクセス不可に見舞われたのですが、以下の設定で

アクセス不可になった際に、通知メールが飛ぶようになり、すぐにCPU100%となっている状況を知ることができました。

さくらインターネットのVPS(仮想専用サーバー)のサーバー・ネットワークの監視(リソース情報、Uptime Robot)

当ブログはさくらインターネットのVPS(仮想専用サーバー)を使っているのですが、時々、CPU100%負荷になってアクセスが遅くなります。現在原因を調査しているところですが、まだ抜本的な対策が出来ておりません。そこでとりあえず、サーバー・...

後で、さくらインターネットのVPSコントロールパネルから「リソース情報」を見ると下記の状態になっていました。

この状態ではCPUが100%になっているのでユーザーからはアクセスできない状態になっていたようです。

PHP Fatal error: Maximum execution time of 30 seconds exceeded

該当時間のログを調べてみることにします。

Apacheのerror_logは以下の通りです。

[Thu Nov 13 00:33:46 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error:  Maximum execution time of 30 seconds exceeded in /var/www/wordpress/wp-includes/functions.php on line 286
[Thu Nov 13 00:34:34 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error:  Maximum execution time of 30 seconds exceeded in /var/www/wordpress/wp-content/plugins/db-cache-reloaded-fix/db-functions.php on line 107
[Thu Nov 13 00:43:49 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error:  Maximum execution time of 30 seconds exceeded in /var/www/wordpress/wp-content/plugins/crayon-syntax-highlighter/global.php on line 114
[Thu Nov 13 00:46:10 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error:  Maximum execution time of 30 seconds exceeded in /var/www/wordpress/wp-content/plugins/db-cache-reloaded-fix/db-module.php on line 396
[Thu Nov 13 00:48:30 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error:  Maximum execution time of 30 seconds exceeded in /var/www/wordpress/wp-content/plugins/db-cache-reloaded-fix/db-module.php on line 396
[Thu Nov 13 01:16:25 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error:  Maximum execution time of 30 seconds exceeded in /var/www/wordpress/wp-includes/pomo/translations.php on line 77
[Thu Nov 13 01:16:27 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error:  Maximum execution time of 30 seconds exceeded in /var/www/wordpress/wp-includes/pomo/entry.php on line 45
[Thu Nov 13 01:16:32 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error:  Maximum execution time of 30 seconds exceeded in /var/www/wordpress/wp-includes/pomo/mo.php on line 199
[Thu Nov 13 01:16:36 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error:  Maximum execution time of 30 seconds exceeded in Unknown on line 0
[Thu Nov 13 01:18:17 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error:  Maximum execution time of 30 seconds exceeded in Unknown on line 0
[Thu Nov 13 01:19:55 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error:  Maximum execution time of 30 seconds exceeded in Unknown on line 0
[Thu Nov 13 01:22:23 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error:  Maximum execution time of 30 seconds exceeded in Unknown on line 0

[Thu Nov 13 00:33:46 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error: Maximum execution time of 30 seconds exceeded in /var/www/wordpress/wp-includes/functions.php on line 286

[Thu Nov 13 00:34:34 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error: Maximum execution time of 30 seconds exceeded in /var/www/wordpress/wp-content/plugins/db-cache-reloaded-fix/db-functions.php on line 107

[Thu Nov 13 00:43:49 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error: Maximum execution time of 30 seconds exceeded in /var/www/wordpress/wp-content/plugins/crayon-syntax-highlighter/global.php on line 114

[Thu Nov 13 00:46:10 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error: Maximum execution time of 30 seconds exceeded in /var/www/wordpress/wp-content/plugins/db-cache-reloaded-fix/db-module.php on line 396

[Thu Nov 13 00:48:30 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error: Maximum execution time of 30 seconds exceeded in /var/www/wordpress/wp-content/plugins/db-cache-reloaded-fix/db-module.php on line 396

[Thu Nov 13 01:16:25 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error: Maximum execution time of 30 seconds exceeded in /var/www/wordpress/wp-includes/pomo/translations.php on line 77

[Thu Nov 13 01:16:27 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error: Maximum execution time of 30 seconds exceeded in /var/www/wordpress/wp-includes/pomo/entry.php on line 45

[Thu Nov 13 01:16:32 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error: Maximum execution time of 30 seconds exceeded in /var/www/wordpress/wp-includes/pomo/mo.php on line 199

[Thu Nov 13 01:16:36 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error: Maximum execution time of 30 seconds exceeded in Unknown on line 0

[Thu Nov 13 01:18:17 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error: Maximum execution time of 30 seconds exceeded in Unknown on line 0

[Thu Nov 13 01:19:55 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error: Maximum execution time of 30 seconds exceeded in Unknown on line 0

[Thu Nov 13 01:22:23 2014] [error] [client aaa.bbb.ccc.ddd] PHP Fatal error: Maximum execution time of 30 seconds exceeded in Unknown on line 0

パッとみたところ、PHP Fatal error: Maximum execution time of 30 seconds exceeded が怪しいように見えますが、これはシロだと思います。

PHPでは無限ループの対策のため、PHP実行処理のタイムアウトが設定されており、デフォルト値が30秒になっています。

30秒自体はおそらくほとんどの処理では適当なタイムアウト値だと思われます。

/etc/php.iniファイルの中の

max_execution_time = 30

を変更すれば伸ばすことは可能ですが、今回のCPU100%問題について説明がつく修正ではないので止めておくことにします。

今回の現象は、恐らく、CPU100%となってしまったために、PHPの応答がなかなか返ってこなくなって結果として30秒のタイムアウト値を超えてしまったのではないかと考えられます。

Out of memory: Killed process 32592, UID 27, (mysqld)

該当時間のシステムのログを調査してみます。

CentOSではシステムのログとしては、/var/log/messagesと/var/log/secureを参照します。

/var/log/secureには目立った障害は見られませんでした。

/var/log/messagesは以下の通りです。

Nov 13 00:17:11 xxxx kernel: init invoked oom-killer: gfp_mask=0x201d2, order=0, oomkilladj=0
Nov 13 00:17:17 xxxx kernel: 
Nov 13 00:17:17 xxxx kernel: Call Trace:
Nov 13 00:17:17 xxxx kernel:  [<ffffffff800cb679>] out_of_memory+0x8e/0x2f3
Nov 13 00:17:17 xxxx kernel:  [<ffffffff8002e4c4>] __wake_up+0x38/0x4f
Nov 13 00:17:17 xxxx kernel:  [<ffffffff8000f691>] __alloc_pages+0x27f/0x308
Nov 13 00:17:17 xxxx kernel:  [<ffffffff80013074>] __do_page_cache_readahead+0x96/0x17b
Nov 13 00:17:17 xxxx kernel:  [<ffffffff800139b5>] filemap_nopage+0x14c/0x360
Nov 13 00:17:17 xxxx kernel:  [<ffffffff80008972>] __handle_mm_fault+0x1fd/0x103b
Nov 13 00:17:17 xxxx kernel:  [<ffffffff800671ae>] do_page_fault+0x499/0x842
Nov 13 00:17:17 xxxx kernel:  [<ffffffff8005ddf9>] error_exit+0x0/0x84
Nov 13 00:17:17 xxxx kernel: 
Nov 13 00:18:14 xxxx kernel: Mem-info:
Nov 13 00:33:53 xxxx kernel: Node 0 DMA per-cpu:
Nov 13 00:33:57 xxxx kernel: cpu 0 hot: high 0, batch 1 used:0
Nov 13 00:33:58 xxxx kernel: cpu 0 cold: high 0, batch 1 used:0
Nov 13 00:34:01 xxxx kernel: cpu 1 hot: high 0, batch 1 used:0
Nov 13 00:34:04 xxxx kernel: cpu 1 cold: high 0, batch 1 used:0
Nov 13 00:34:13 xxxx kernel: Node 0 DMA32 per-cpu:
Nov 13 00:34:13 xxxx kernel: cpu 0 hot: high 186, batch 31 used:80
Nov 13 00:34:14 xxxx kernel: cpu 0 cold: high 62, batch 15 used:52
Nov 13 00:34:15 xxxx kernel: cpu 1 hot: high 186, batch 31 used:31
Nov 13 00:34:17 xxxx kernel: cpu 1 cold: high 62, batch 15 used:43
Nov 13 00:34:17 xxxx kernel: Node 0 Normal per-cpu: empty
Nov 13 00:34:18 xxxx kernel: Node 0 HighMem per-cpu: empty
Nov 13 00:34:20 xxxx kernel: Free pages:        6860kB (0kB HighMem)
Nov 13 00:34:21 xxxx kernel: Active:123746 inactive:108682 dirty:0 writeback:0 unstable:0 free:1715 slab:4075 mapped-file:1183 mapped-anon:233529 pagetables:11419
Nov 13 00:34:22 xxxx kernel: Node 0 DMA free:2948kB min:36kB low:44kB high:52kB active:0kB inactive:0kB present:9684kB pages_scanned:0 all_unreclaimable? yes
Nov 13 00:34:23 xxxx kernel: lowmem_reserve[]: 0 994 994 994
Nov 13 00:34:25 xxxx kernel: Node 0 DMA32 free:3912kB min:4012kB low:5012kB high:6016kB active:495304kB inactive:434416kB present:1018072kB pages_scanned:1717138 all_unreclaimable? yes
Nov 13 00:34:32 xxxx kernel: lowmem_reserve[]: 0 0 0 0
Nov 13 00:34:39 xxxx kernel: Node 0 Normal free:0kB min:0kB low:0kB high:0kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no
Nov 13 00:34:55 xxxx kernel: lowmem_reserve[]: 0 0 0 0
Nov 13 00:34:57 xxxx kernel: Node 0 HighMem free:0kB min:128kB low:128kB high:128kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no
Nov 13 00:34:57 xxxx kernel: lowmem_reserve[]: 0 0 0 0
Nov 13 00:34:57 xxxx kernel: Node 0 DMA: 5*4kB 4*8kB 5*16kB 4*32kB 2*64kB 2*128kB 1*256kB 0*512kB 2*1024kB 0*2048kB 0*4096kB = 2948kB
Nov 13 00:35:00 xxxx kernel: Node 0 DMA32: 0*4kB 1*8kB 18*16kB 3*32kB 5*64kB 3*128kB 1*256kB 1*512kB 0*1024kB 1*2048kB 0*4096kB = 3912kB
Nov 13 00:35:21 xxxx kernel: Node 0 Normal: empty
Nov 13 00:35:22 xxxx kernel: Node 0 HighMem: empty
Nov 13 00:35:24 xxxx kernel: 6954 pagecache pages
Nov 13 00:35:35 xxxx kernel: Swap cache: add 43771139, delete 43765391, find 25699158/40375651, race 6+103
Nov 13 00:39:59 xxxx kernel: Free swap  = 0kB
Nov 13 00:40:23 xxxx kernel: Total swap = 2048276kB
Nov 13 00:43:13 xxxx kernel: Free swap:            0kB
Nov 13 00:43:14 xxxx kernel: 262141 pages of RAM
Nov 13 00:43:14 xxxx kernel: 5628 reserved pages
Nov 13 00:43:14 xxxx kernel: 34467 pages shared
Nov 13 00:43:15 xxxx kernel: 5751 pages swap cached
Nov 13 00:43:15 xxxx kernel: Out of memory: Killed process 32592, UID 27, (mysqld).
Nov 13 00:43:16 xxxx kernel: httpd invoked oom-killer: gfp_mask=0x201d2, order=0, oomkilladj=0
Nov 13 00:43:18 xxxx kernel: 
Nov 13 00:43:18 xxxx kernel: Call Trace:
Nov 13 00:43:20 xxxx kernel:  [<ffffffff800cb679>] out_of_memory+0x8e/0x2f3
Nov 13 00:43:21 xxxx kernel:  [<ffffffff8002e4c4>] __wake_up+0x38/0x4f
Nov 13 00:43:22 xxxx kernel:  [<ffffffff8000f691>] __alloc_pages+0x27f/0x308
Nov 13 00:43:22 xxxx kernel:  [<ffffffff80013074>] __do_page_cache_readahead+0x96/0x17b
Nov 13 00:43:23 xxxx kernel:  [<ffffffff800139b5>] filemap_nopage+0x14c/0x360
Nov 13 00:43:23 xxxx kernel:  [<ffffffff80008972>] __handle_mm_fault+0x1fd/0x103b
Nov 13 00:43:24 xxxx kernel:  [<ffffffff800671ae>] do_page_fault+0x499/0x842
Nov 13 00:43:24 xxxx kernel:  [<ffffffff80063002>] thread_return+0x62/0xfe
Nov 13 00:43:26 xxxx kernel:  [<ffffffff8000e302>] do_mmap_pgoff+0x652/0x7bd
Nov 13 00:43:28 xxxx kernel:  [<ffffffff8005ddf9>] error_exit+0x0/0x84
Nov 13 00:43:30 xxxx kernel: 
Nov 13 00:43:37 xxxx kernel: Mem-info:
Nov 13 00:43:39 xxxx kernel: Node 0 DMA per-cpu:
Nov 13 00:43:42 xxxx kernel: cpu 0 hot: high 0, batch 1 used:0
Nov 13 00:44:01 xxxx kernel: cpu 0 cold: high 0, batch 1 used:0
Nov 13 00:44:03 xxxx kernel: cpu 1 hot: high 0, batch 1 used:0
Nov 13 00:44:14 xxxx kernel: cpu 1 cold: high 0, batch 1 used:0
Nov 13 00:44:17 xxxx kernel: Node 0 DMA32 per-cpu:
Nov 13 00:44:22 xxxx kernel: cpu 0 hot: high 186, batch 31 used:26
Nov 13 00:44:45 xxxx kernel: cpu 0 cold: high 62, batch 15 used:3
Nov 13 00:44:59 xxxx kernel: cpu 1 hot: high 186, batch 31 used:50
Nov 13 00:45:16 xxxx kernel: cpu 1 cold: high 62, batch 15 used:14
Nov 13 00:46:43 xxxx kernel: Node 0 Normal per-cpu: empty
Nov 13 00:46:49 xxxx kernel: Node 0 HighMem per-cpu: empty
Nov 13 00:47:54 xxxx kernel: Free pages:        6960kB (0kB HighMem)
Nov 13 00:48:35 xxxx kernel: Active:102045 inactive:130967 dirty:0 writeback:0 unstable:0 free:1740 slab:4063 mapped-file:1187 mapped-anon:233529 pagetables:11419
Nov 13 00:48:43 xxxx kernel: Node 0 DMA free:2948kB min:36kB low:44kB high:52kB active:0kB inactive:0kB present:9684kB pages_scanned:0 all_unreclaimable? yes
Nov 13 00:49:00 xxxx kernel: lowmem_reserve[]: 0 994 994 994
Nov 13 00:53:00 xxxx kernel: Node 0 DMA32 free:4012kB min:4012kB low:5012kB high:6016kB active:408192kB inactive:523856kB present:1018072kB pages_scanned:1799434 all_unreclaimable? yes
Nov 13 01:02:58 xxxx kernel: lowmem_reserve[]: 0 0 0 0
Nov 13 01:03:01 xxxx kernel: Node 0 Normal free:0kB min:0kB low:0kB high:0kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no
Nov 13 01:03:07 xxxx kernel: lowmem_reserve[]: 0 0 0 0
Nov 13 01:03:08 xxxx kernel: Node 0 HighMem free:0kB min:128kB low:128kB high:128kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no
Nov 13 01:03:08 xxxx kernel: lowmem_reserve[]: 0 0 0 0
Nov 13 01:03:08 xxxx kernel: Node 0 DMA: 5*4kB 4*8kB 5*16kB 4*32kB 2*64kB 2*128kB 1*256kB 0*512kB 2*1024kB 0*2048kB 0*4096kB = 2948kB
Nov 13 01:03:12 xxxx kernel: Node 0 DMA32: 1*4kB 9*8kB 20*16kB 3*32kB 5*64kB 3*128kB 1*256kB 1*512kB 0*1024kB 1*2048kB 0*4096kB = 4012kB
Nov 13 01:03:13 xxxx kernel: Node 0 Normal: empty
Nov 13 01:03:14 xxxx kernel: Node 0 HighMem: empty
Nov 13 01:03:15 xxxx kernel: 7158 pagecache pages
Nov 13 01:03:18 xxxx kernel: Swap cache: add 43771247, delete 43765491, find 25699159/40375673, race 6+103
Nov 13 01:03:20 xxxx kernel: Free swap  = 0kB
Nov 13 01:03:22 xxxx kernel: Total swap = 2048276kB
Nov 13 01:16:32 xxxx kernel: Free swap:            0kB
Nov 13 01:16:34 xxxx kernel: 262141 pages of RAM
Nov 13 01:16:34 xxxx kernel: 5628 reserved pages
Nov 13 01:16:35 xxxx kernel: 34117 pages shared
Nov 13 01:16:35 xxxx kernel: 5759 pages swap cached
Nov 13 01:16:36 xxxx kernel: httpd invoked oom-killer: gfp_mask=0x201d2, order=0, oomkilladj=0
Nov 13 01:16:36 xxxx kernel: 
Nov 13 01:16:38 xxxx kernel: Call Trace:
Nov 13 01:16:39 xxxx kernel:  [<ffffffff800cb679>] out_of_memory+0x8e/0x2f3
Nov 13 01:16:41 xxxx kernel:  [<ffffffff8000f691>] __alloc_pages+0x27f/0x308
Nov 13 01:16:45 xxxx kernel:  [<ffffffff80013074>] __do_page_cache_readahead+0x96/0x17b
Nov 13 01:17:03 xxxx kernel:  [<ffffffff800139b5>] filemap_nopage+0x14c/0x360
Nov 13 01:17:05 xxxx kernel:  [<ffffffff80008972>] __handle_mm_fault+0x1fd/0x103b
Nov 13 01:17:09 xxxx kernel:  [<ffffffff800671ae>] do_page_fault+0x499/0x842
Nov 13 01:17:34 xxxx kernel:  [<ffffffff80023cd5>] sys_newstat+0x28/0x31
Nov 13 01:18:39 xxxx kernel:  [<ffffffff8005ddf9>] error_exit+0x0/0x84
Nov 13 01:18:47 xxxx kernel: 
Nov 13 01:21:16 xxxx kernel: Mem-info:
Nov 13 01:22:01 xxxx kernel: Node 0 DMA per-cpu:
Nov 13 01:22:12 xxxx kernel: cpu 0 hot: high 0, batch 1 used:0
Nov 13 01:24:54 xxxx kernel: cpu 0 cold: high 0, batch 1 used:0
Nov 13 01:24:59 xxxx kernel: cpu 1 hot: high 0, batch 1 used:0
Nov 13 01:26:03 xxxx kernel: cpu 1 cold: high 0, batch 1 used:0
Nov 13 01:26:31 xxxx kernel: Node 0 DMA32 per-cpu:
Nov 13 01:31:25 xxxx kernel: cpu 0 hot: high 186, batch 31 used:9
Nov 13 01:38:10 xxxx kernel: cpu 0 cold: high 62, batch 15 used:14
Nov 13 01:38:13 xxxx kernel: cpu 1 hot: high 186, batch 31 used:26
Nov 13 01:38:15 xxxx kernel: cpu 1 cold: high 62, batch 15 used:25
Nov 13 01:38:18 xxxx kernel: Node 0 Normal per-cpu: empty
Nov 13 01:38:21 xxxx kernel: Node 0 HighMem per-cpu: empty
Nov 13 01:38:27 xxxx kernel: Free pages:        6956kB (0kB HighMem)
Nov 13 01:38:30 xxxx kernel: Active:121664 inactive:111417 dirty:0 writeback:0 unstable:0 free:1739 slab:4063 mapped-file:1183 mapped-anon:233693 pagetables:11432
Nov 13 01:38:56 xxxx kernel: Node 0 DMA free:2948kB min:36kB low:44kB high:52kB active:0kB inactive:0kB present:9684kB pages_scanned:0 all_unreclaimable? yes
Nov 13 01:39:03 xxxx kernel: lowmem_reserve[]: 0 994 994 994
Nov 13 01:40:01 xxxx kernel: Node 0 DMA32 free:4008kB min:4012kB low:5012kB high:6016kB active:486704kB inactive:445620kB present:1018072kB pages_scanned:1832016 all_unreclaimable? yes
Nov 13 01:40:30 xxxx kernel: lowmem_reserve[]: 0 0 0 0
Nov 13 01:41:31 xxxx kernel: Node 0 Normal free:0kB min:0kB low:0kB high:0kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no
Nov 13 01:42:48 xxxx kernel: lowmem_reserve[]: 0 0 0 0
Nov 13 01:42:56 xxxx kernel: Node 0 HighMem free:0kB min:128kB low:128kB high:128kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no
Nov 13 01:42:58 xxxx kernel: lowmem_reserve[]: 0 0 0 0
Nov 13 01:44:13 xxxx kernel: Node 0 DMA: 5*4kB 4*8kB 5*16kB 4*32kB 2*64kB 2*128kB 1*256kB 0*512kB 2*1024kB 0*2048kB 0*4096kB = 2948kB
Nov 13 01:45:00 xxxx kernel: Node 0 DMA32: 18*4kB 4*8kB 18*16kB 3*32kB 5*64kB 3*128kB 1*256kB 1*512kB 0*1024kB 1*2048kB 0*4096kB = 4008kB
Nov 13 01:45:19 xxxx kernel: Node 0 Normal: empty
Nov 13 01:45:20 xxxx kernel: Node 0 HighMem: empty
Nov 13 01:46:02 xxxx kernel: 7038 pagecache pages
Nov 13 01:46:22 xxxx kernel: Swap cache: add 43774566, delete 43768785, find 25699219/40376098, race 6+103
Nov 13 01:48:04 xxxx kernel: Free swap  = 0kB
Nov 13 01:49:03 xxxx kernel: Total swap = 2048276kB
Nov 13 01:49:27 xxxx kernel: Free swap:            0kB
Nov 13 01:49:28 xxxx kernel: 262141 pages of RAM
Nov 13 01:49:29 xxxx kernel: 5628 reserved pages
Nov 13 01:49:30 xxxx kernel: 34137 pages shared
Nov 13 01:49:37 xxxx kernel: 5784 pages swap cached

100

101

102

103

104

105

106

107

108

109

110

111

112

113

114

115

116

117

118

119

120

121

122

123

124

125

126

127

128

129

130

131

132

133

134

135

136

137

138

139

140

141

142

143

144

145

146

147

Nov 13 00:17:11 xxxx kernel: init invoked oom-killer: gfp_mask=0x201d2, order=0, oomkilladj=0

Nov 13 00:17:17 xxxx kernel:

Nov 13 00:17:17 xxxx kernel: Call Trace:

Nov 13 00:17:17 xxxx kernel: [<ffffffff800cb679>] out_of_memory+0x8e/0x2f3

Nov 13 00:17:17 xxxx kernel: [<ffffffff8002e4c4>] __wake_up+0x38/0x4f

Nov 13 00:17:17 xxxx kernel: [<ffffffff8000f691>] __alloc_pages+0x27f/0x308

Nov 13 00:17:17 xxxx kernel: [<ffffffff80013074>] __do_page_cache_readahead+0x96/0x17b

Nov 13 00:17:17 xxxx kernel: [<ffffffff800139b5>] filemap_nopage+0x14c/0x360

Nov 13 00:17:17 xxxx kernel: [<ffffffff80008972>] __handle_mm_fault+0x1fd/0x103b

Nov 13 00:17:17 xxxx kernel: [<ffffffff800671ae>] do_page_fault+0x499/0x842

Nov 13 00:17:17 xxxx kernel: [<ffffffff8005ddf9>] error_exit+0x0/0x84

Nov 13 00:17:17 xxxx kernel:

Nov 13 00:18:14 xxxx kernel: Mem-info:

Nov 13 00:33:53 xxxx kernel: Node 0 DMA per-cpu:

Nov 13 00:33:57 xxxx kernel: cpu 0 hot: high 0, batch 1 used:0

Nov 13 00:33:58 xxxx kernel: cpu 0 cold: high 0, batch 1 used:0

Nov 13 00:34:01 xxxx kernel: cpu 1 hot: high 0, batch 1 used:0

Nov 13 00:34:04 xxxx kernel: cpu 1 cold: high 0, batch 1 used:0

Nov 13 00:34:13 xxxx kernel: Node 0 DMA32 per-cpu:

Nov 13 00:34:13 xxxx kernel: cpu 0 hot: high 186, batch 31 used:80

Nov 13 00:34:14 xxxx kernel: cpu 0 cold: high 62, batch 15 used:52

Nov 13 00:34:15 xxxx kernel: cpu 1 hot: high 186, batch 31 used:31

Nov 13 00:34:17 xxxx kernel: cpu 1 cold: high 62, batch 15 used:43

Nov 13 00:34:17 xxxx kernel: Node 0 Normal per-cpu: empty

Nov 13 00:34:18 xxxx kernel: Node 0 HighMem per-cpu: empty

Nov 13 00:34:20 xxxx kernel: Free pages: 6860kB (0kB HighMem)

Nov 13 00:34:21 xxxx kernel: Active:123746 inactive:108682 dirty:0 writeback:0 unstable:0 free:1715 slab:4075 mapped-file:1183 mapped-anon:233529 pagetables:11419

Nov 13 00:34:22 xxxx kernel: Node 0 DMA free:2948kB min:36kB low:44kB high:52kB active:0kB inactive:0kB present:9684kB pages_scanned:0 all_unreclaimable? yes

Nov 13 00:34:23 xxxx kernel: lowmem_reserve[]: 0 994 994 994

Nov 13 00:34:25 xxxx kernel: Node 0 DMA32 free:3912kB min:4012kB low:5012kB high:6016kB active:495304kB inactive:434416kB present:1018072kB pages_scanned:1717138 all_unreclaimable? yes

Nov 13 00:34:32 xxxx kernel: lowmem_reserve[]: 0 0 0 0

Nov 13 00:34:39 xxxx kernel: Node 0 Normal free:0kB min:0kB low:0kB high:0kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no

Nov 13 00:34:55 xxxx kernel: lowmem_reserve[]: 0 0 0 0

Nov 13 00:34:57 xxxx kernel: Node 0 HighMem free:0kB min:128kB low:128kB high:128kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no

Nov 13 00:34:57 xxxx kernel: lowmem_reserve[]: 0 0 0 0

Nov 13 00:34:57 xxxx kernel: Node 0 DMA: 5*4kB 4*8kB 5*16kB 4*32kB 2*64kB 2*128kB 1*256kB 0*512kB 2*1024kB 0*2048kB 0*4096kB = 2948kB

Nov 13 00:35:00 xxxx kernel: Node 0 DMA32: 0*4kB 1*8kB 18*16kB 3*32kB 5*64kB 3*128kB 1*256kB 1*512kB 0*1024kB 1*2048kB 0*4096kB = 3912kB

Nov 13 00:35:21 xxxx kernel: Node 0 Normal: empty

Nov 13 00:35:22 xxxx kernel: Node 0 HighMem: empty

Nov 13 00:35:24 xxxx kernel: 6954 pagecache pages

Nov 13 00:35:35 xxxx kernel: Swap cache: add 43771139, delete 43765391, find 25699158/40375651, race 6+103

Nov 13 00:39:59 xxxx kernel: Free swap = 0kB

Nov 13 00:40:23 xxxx kernel: Total swap = 2048276kB

Nov 13 00:43:13 xxxx kernel: Free swap: 0kB

Nov 13 00:43:14 xxxx kernel: 262141 pages of RAM

Nov 13 00:43:14 xxxx kernel: 5628 reserved pages

Nov 13 00:43:14 xxxx kernel: 34467 pages shared

Nov 13 00:43:15 xxxx kernel: 5751 pages swap cached

Nov 13 00:43:15 xxxx kernel: Out of memory: Killed process 32592, UID 27, (mysqld).

Nov 13 00:43:16 xxxx kernel: httpd invoked oom-killer: gfp_mask=0x201d2, order=0, oomkilladj=0

Nov 13 00:43:18 xxxx kernel:

Nov 13 00:43:18 xxxx kernel: Call Trace:

Nov 13 00:43:20 xxxx kernel: [<ffffffff800cb679>] out_of_memory+0x8e/0x2f3

Nov 13 00:43:21 xxxx kernel: [<ffffffff8002e4c4>] __wake_up+0x38/0x4f

Nov 13 00:43:22 xxxx kernel: [<ffffffff8000f691>] __alloc_pages+0x27f/0x308

Nov 13 00:43:22 xxxx kernel: [<ffffffff80013074>] __do_page_cache_readahead+0x96/0x17b

Nov 13 00:43:23 xxxx kernel: [<ffffffff800139b5>] filemap_nopage+0x14c/0x360

Nov 13 00:43:23 xxxx kernel: [<ffffffff80008972>] __handle_mm_fault+0x1fd/0x103b

Nov 13 00:43:24 xxxx kernel: [<ffffffff800671ae>] do_page_fault+0x499/0x842

Nov 13 00:43:24 xxxx kernel: [<ffffffff80063002>] thread_return+0x62/0xfe

Nov 13 00:43:26 xxxx kernel: [<ffffffff8000e302>] do_mmap_pgoff+0x652/0x7bd

Nov 13 00:43:28 xxxx kernel: [<ffffffff8005ddf9>] error_exit+0x0/0x84

Nov 13 00:43:30 xxxx kernel:

Nov 13 00:43:37 xxxx kernel: Mem-info:

Nov 13 00:43:39 xxxx kernel: Node 0 DMA per-cpu:

Nov 13 00:43:42 xxxx kernel: cpu 0 hot: high 0, batch 1 used:0

Nov 13 00:44:01 xxxx kernel: cpu 0 cold: high 0, batch 1 used:0

Nov 13 00:44:03 xxxx kernel: cpu 1 hot: high 0, batch 1 used:0

Nov 13 00:44:14 xxxx kernel: cpu 1 cold: high 0, batch 1 used:0

Nov 13 00:44:17 xxxx kernel: Node 0 DMA32 per-cpu:

Nov 13 00:44:22 xxxx kernel: cpu 0 hot: high 186, batch 31 used:26

Nov 13 00:44:45 xxxx kernel: cpu 0 cold: high 62, batch 15 used:3

Nov 13 00:44:59 xxxx kernel: cpu 1 hot: high 186, batch 31 used:50

Nov 13 00:45:16 xxxx kernel: cpu 1 cold: high 62, batch 15 used:14

Nov 13 00:46:43 xxxx kernel: Node 0 Normal per-cpu: empty

Nov 13 00:46:49 xxxx kernel: Node 0 HighMem per-cpu: empty

Nov 13 00:47:54 xxxx kernel: Free pages: 6960kB (0kB HighMem)

Nov 13 00:48:35 xxxx kernel: Active:102045 inactive:130967 dirty:0 writeback:0 unstable:0 free:1740 slab:4063 mapped-file:1187 mapped-anon:233529 pagetables:11419

Nov 13 00:48:43 xxxx kernel: Node 0 DMA free:2948kB min:36kB low:44kB high:52kB active:0kB inactive:0kB present:9684kB pages_scanned:0 all_unreclaimable? yes

Nov 13 00:49:00 xxxx kernel: lowmem_reserve[]: 0 994 994 994

Nov 13 00:53:00 xxxx kernel: Node 0 DMA32 free:4012kB min:4012kB low:5012kB high:6016kB active:408192kB inactive:523856kB present:1018072kB pages_scanned:1799434 all_unreclaimable? yes

Nov 13 01:02:58 xxxx kernel: lowmem_reserve[]: 0 0 0 0

Nov 13 01:03:01 xxxx kernel: Node 0 Normal free:0kB min:0kB low:0kB high:0kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no

Nov 13 01:03:07 xxxx kernel: lowmem_reserve[]: 0 0 0 0

Nov 13 01:03:08 xxxx kernel: Node 0 HighMem free:0kB min:128kB low:128kB high:128kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no

Nov 13 01:03:08 xxxx kernel: lowmem_reserve[]: 0 0 0 0

Nov 13 01:03:08 xxxx kernel: Node 0 DMA: 5*4kB 4*8kB 5*16kB 4*32kB 2*64kB 2*128kB 1*256kB 0*512kB 2*1024kB 0*2048kB 0*4096kB = 2948kB

Nov 13 01:03:12 xxxx kernel: Node 0 DMA32: 1*4kB 9*8kB 20*16kB 3*32kB 5*64kB 3*128kB 1*256kB 1*512kB 0*1024kB 1*2048kB 0*4096kB = 4012kB

Nov 13 01:03:13 xxxx kernel: Node 0 Normal: empty

Nov 13 01:03:14 xxxx kernel: Node 0 HighMem: empty

Nov 13 01:03:15 xxxx kernel: 7158 pagecache pages

Nov 13 01:03:18 xxxx kernel: Swap cache: add 43771247, delete 43765491, find 25699159/40375673, race 6+103

Nov 13 01:03:20 xxxx kernel: Free swap = 0kB

Nov 13 01:03:22 xxxx kernel: Total swap = 2048276kB

Nov 13 01:16:32 xxxx kernel: Free swap: 0kB

Nov 13 01:16:34 xxxx kernel: 262141 pages of RAM

Nov 13 01:16:34 xxxx kernel: 5628 reserved pages

Nov 13 01:16:35 xxxx kernel: 34117 pages shared

Nov 13 01:16:35 xxxx kernel: 5759 pages swap cached

Nov 13 01:16:36 xxxx kernel: httpd invoked oom-killer: gfp_mask=0x201d2, order=0, oomkilladj=0

Nov 13 01:16:36 xxxx kernel:

Nov 13 01:16:38 xxxx kernel: Call Trace:

Nov 13 01:16:39 xxxx kernel: [<ffffffff800cb679>] out_of_memory+0x8e/0x2f3

Nov 13 01:16:41 xxxx kernel: [<ffffffff8000f691>] __alloc_pages+0x27f/0x308

Nov 13 01:16:45 xxxx kernel: [<ffffffff80013074>] __do_page_cache_readahead+0x96/0x17b

Nov 13 01:17:03 xxxx kernel: [<ffffffff800139b5>] filemap_nopage+0x14c/0x360

Nov 13 01:17:05 xxxx kernel: [<ffffffff80008972>] __handle_mm_fault+0x1fd/0x103b

Nov 13 01:17:09 xxxx kernel: [<ffffffff800671ae>] do_page_fault+0x499/0x842

Nov 13 01:17:34 xxxx kernel: [<ffffffff80023cd5>] sys_newstat+0x28/0x31

Nov 13 01:18:39 xxxx kernel: [<ffffffff8005ddf9>] error_exit+0x0/0x84

Nov 13 01:18:47 xxxx kernel:

Nov 13 01:21:16 xxxx kernel: Mem-info:

Nov 13 01:22:01 xxxx kernel: Node 0 DMA per-cpu:

Nov 13 01:22:12 xxxx kernel: cpu 0 hot: high 0, batch 1 used:0

Nov 13 01:24:54 xxxx kernel: cpu 0 cold: high 0, batch 1 used:0

Nov 13 01:24:59 xxxx kernel: cpu 1 hot: high 0, batch 1 used:0

Nov 13 01:26:03 xxxx kernel: cpu 1 cold: high 0, batch 1 used:0

Nov 13 01:26:31 xxxx kernel: Node 0 DMA32 per-cpu:

Nov 13 01:31:25 xxxx kernel: cpu 0 hot: high 186, batch 31 used:9

Nov 13 01:38:10 xxxx kernel: cpu 0 cold: high 62, batch 15 used:14

Nov 13 01:38:13 xxxx kernel: cpu 1 hot: high 186, batch 31 used:26

Nov 13 01:38:15 xxxx kernel: cpu 1 cold: high 62, batch 15 used:25

Nov 13 01:38:18 xxxx kernel: Node 0 Normal per-cpu: empty

Nov 13 01:38:21 xxxx kernel: Node 0 HighMem per-cpu: empty

Nov 13 01:38:27 xxxx kernel: Free pages: 6956kB (0kB HighMem)

Nov 13 01:38:30 xxxx kernel: Active:121664 inactive:111417 dirty:0 writeback:0 unstable:0 free:1739 slab:4063 mapped-file:1183 mapped-anon:233693 pagetables:11432

Nov 13 01:38:56 xxxx kernel: Node 0 DMA free:2948kB min:36kB low:44kB high:52kB active:0kB inactive:0kB present:9684kB pages_scanned:0 all_unreclaimable? yes

Nov 13 01:39:03 xxxx kernel: lowmem_reserve[]: 0 994 994 994

Nov 13 01:40:01 xxxx kernel: Node 0 DMA32 free:4008kB min:4012kB low:5012kB high:6016kB active:486704kB inactive:445620kB present:1018072kB pages_scanned:1832016 all_unreclaimable? yes

Nov 13 01:40:30 xxxx kernel: lowmem_reserve[]: 0 0 0 0

Nov 13 01:41:31 xxxx kernel: Node 0 Normal free:0kB min:0kB low:0kB high:0kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no

Nov 13 01:42:48 xxxx kernel: lowmem_reserve[]: 0 0 0 0

Nov 13 01:42:56 xxxx kernel: Node 0 HighMem free:0kB min:128kB low:128kB high:128kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no

Nov 13 01:42:58 xxxx kernel: lowmem_reserve[]: 0 0 0 0

Nov 13 01:44:13 xxxx kernel: Node 0 DMA: 5*4kB 4*8kB 5*16kB 4*32kB 2*64kB 2*128kB 1*256kB 0*512kB 2*1024kB 0*2048kB 0*4096kB = 2948kB

Nov 13 01:45:00 xxxx kernel: Node 0 DMA32: 18*4kB 4*8kB 18*16kB 3*32kB 5*64kB 3*128kB 1*256kB 1*512kB 0*1024kB 1*2048kB 0*4096kB = 4008kB

Nov 13 01:45:19 xxxx kernel: Node 0 Normal: empty

Nov 13 01:45:20 xxxx kernel: Node 0 HighMem: empty

Nov 13 01:46:02 xxxx kernel: 7038 pagecache pages

Nov 13 01:46:22 xxxx kernel: Swap cache: add 43774566, delete 43768785, find 25699219/40376098, race 6+103

Nov 13 01:48:04 xxxx kernel: Free swap = 0kB

Nov 13 01:49:03 xxxx kernel: Total swap = 2048276kB

Nov 13 01:49:27 xxxx kernel: Free swap: 0kB

Nov 13 01:49:28 xxxx kernel: 262141 pages of RAM

Nov 13 01:49:29 xxxx kernel: 5628 reserved pages

Nov 13 01:49:30 xxxx kernel: 34137 pages shared

Nov 13 01:49:37 xxxx kernel: 5784 pages swap cached

うーむ。

Out of memory: Killed process 32592, UID 27, (mysqld)　とか
httpd invoked oom-killer: gfp_mask=0x201d2, order=0, oomkilladj=0 あたりが怪しいところです。

推測すると、何らかの無限ループに入って、CPUやメモリを使い果たしてしまい、やむを得ずに、システムがApacheとMySQLを再起動しているように見えます。

LinuxカーネルにはOut Of Memory Killer(OOM Killer)という機能があって、メモリ浪費を行っているプロセスを自動的に止めるように動きます。

Apache Killer(CVE-2011-3192)が原因か？

2011年8月に当時、ほぼすべてのバージョンのApacheに存在する脆弱性が見つかりました(CVE-2011-3192)。

「Apache HTTP Server」には、サービス運用妨害 (DoS) の脆弱性（CVE-2011-3192）が存在します。

「Apache HTTP Server」は、Apache Software Foundation がオープンソースソフトウェアとして提供しているウェブサーバ用のプログラムです。「Apache HTTP Server」には、HTTP リクエストの取扱いに問題があるため、サービス運用妨害 (DoS) の脆弱性（CVE-2011-3192）が存在します。この脆弱性が悪用されると、運用中のウェブサービスを提供できなくなるなどの被害にあう可能性があります。

301 Moved Permanently

から引用しています。

私の使っているApacheは、2.2.3と古いので怪しいと思い、脆弱性を確認してみました。

検証するために、apachepartial.pl というスクリプトを使います。

http://pastebin.com/NCDv9eTh

からダウンロードしてクライアントに置きます。

サーバーをいつでも再起動できる状態にしてテストして見ました。

# perl apachepartial.pl urashita.com /  30 1 80

Testing http://urashita.com:80/

Request:
HEAD / HTTP/1.1
Host: urashita.com
User-Agent: Apache httpd Partial Content bug exploit
Range:bytes=0-100
Accept-Encoding: gzip
Connection: close

Response:
HTTP/1.1 200 OK
Date: Thu, 13 Nov 2014 09:43:43 GMT
Server: Apache/2.2.3 (CentOS)
X-Powered-By: PHP/5.4.34
Vary: Accept-Encoding,Cookie
Cache-Control: max-age=3, must-revalidate, max-age=2592000
WP-Super-Cache: Served supercache file from PHP
Content-Encoding: gzip
Content-Length: 8428
Expires: Sat, 13 Dec 2014 09:43:43 GMT
Connection: keep-alive, close
Content-Type: text/html; charset=UTF-8

Host does not seem vulnerable (maybe another path?).

# perl apachepartial.pl urashita.com / 30 1 80

Testing http://urashita.com:80/

Request:

HEAD / HTTP/1.1

Host: urashita.com

User-Agent: Apache httpd Partial Content bug exploit

Range:bytes=0-100

Accept-Encoding: gzip

Connection: close

Response:

HTTP/1.1 200 OK

Date: Thu, 13 Nov 2014 09:43:43 GMT

Server: Apache/2.2.3 (CentOS)

X-Powered-By: PHP/5.4.34

Vary: Accept-Encoding,Cookie

Cache-Control: max-age=3, must-revalidate, max-age=2592000

WP-Super-Cache: Served supercache file from PHP

Content-Encoding: gzip

Content-Length: 8428

Expires: Sat, 13 Dec 2014 09:43:43 GMT

Connection: keep-alive, close

Content-Type: text/html; charset=UTF-8

Host does not seem vulnerable (maybe another path?).

Host does not seem vulnerable ・・・シロでした。

この種の対策を何も行っていなかったので、いかにもこの問題かと思ったのですが違いました。

1日いろいろと対策を考えましたが、今回は本件の原因解明を諦めて、代わりにApacheをnginxへ移行して様子を見てみようと思います。

2014.11.14 追記 nginxへ移行しました

CentOS 5のWordPressでApache 2.2.3からnginx 1.6.2へ移行手順

当ブログはさくらインターネットのVPS(仮想専用サーバー)でCentOS 5を使っていますが、この度、Apache 2.2.3からnginx 1.6.2へ移行しました。以下、nginx 1.6.2への移行手順です。 ver...

さくらのVPSサーバー

↓月額685円からの低価格＆高パフォーマンスのVPS、さくらのVPSはコチラ

SSDプランが月々685円から使える！さくらのVPS