我在 Debian 专用服务器上的 /var/log/apache2/vhosts 中有一个日志文件目录。每天我都会将主 access_log 拆分为 /var/log/apache2/vhosts 中的各个 vhostname.com_access_log 文件
在过去一周左右的时间里,我注意到服务器已经没有响应,并且每次发生这种情况时似乎都有多个日志轮换实例在运行。
经过一番调查,我决定检查 /var/log/apache2/vhosts 的内容,看看是否存在某种问题。我可以通过“cd”进入目录,但无法列出其内容。“ls”命令不会停止,只是不执行任何操作。
在尝试了各种列出文件内容的方法后,我决定删除它并创建一个新文件。但是,从父目录对目录运行 rm 似乎也不起作用:rm -rf vhosts。从“top”视图中我可以看到“rm”正在运行并使用少量 CPU... 它现在已经运行了大约一个小时。
知道发生了什么事以及如何摆脱该目录吗?
更多信息:
在 /var/log/messages 中看到很多这种类型的错误,不知道是否相关:
Oct 15 12:22:39 sp5059b kernel: [2257339.255530] apache2 D a9b86504 0 32217 9125
Oct 15 12:22:39 sp5059b kernel: [2257339.255533] dea15620 00000086 00000000 a9b86504 0007f05b dea157ac c1fdbfc0 00000001
Oct 15 12:22:39 sp5059b kernel: [2257339.255538] 00000000 00000000 00000001 00000000 00000000 00000000 00000000 00000000
Oct 15 12:22:39 sp5059b kernel: [2257339.255542] f7246ec0 f7246ec8 f7246ec4 dea15620 c02b95c6 c2483e80 d7085e80 dea15620
Oct 15 12:22:39 sp5059b kernel: [2257339.255547] Call Trace:
Oct 15 12:22:39 sp5059b kernel: [2257339.255553] [<c02b95c6>] __mutex_lock_slowpath+0x50/0x7b
Oct 15 12:22:39 sp5059b kernel: [2257339.255557] [<c02b945c>] mutex_lock+0xa/0xb
Oct 15 12:22:39 sp5059b kernel: [2257339.255561] [<c015810c>] generic_file_aio_write+0x41/0xa9
Oct 15 12:22:39 sp5059b kernel: [2257339.255565] [<f892ef99>] ext3_file_write+0x19/0x83 [ext3]
Oct 15 12:22:39 sp5059b kernel: [2257339.255575] [<c017460e>] do_sync_write+0xbf/0x100
Oct 15 12:22:39 sp5059b kernel: [2257339.255581] [<c0131a98>] autoremove_wake_function+0x0/0x2d
Oct 15 12:22:39 sp5059b kernel: [2257339.255585] [<c0132368>] set_process_cpu_timer+0x27/0xae
Oct 15 12:22:39 sp5059b kernel: [2257339.255590] [<c0125be2>] do_setitimer+0x2aa/0x31a
Oct 15 12:22:39 sp5059b kernel: [2257339.255594] [<c017e0a0>] fasync_helper+0x3c/0xb7
Oct 15 12:22:39 sp5059b kernel: [2257339.255597] [<c01bafe5>] security_file_permission+0xc/0xd
Oct 15 12:22:39 sp5059b kernel: [2257339.255601] [<c017454f>] do_sync_write+0x0/0x100
Oct 15 12:22:39 sp5059b kernel: [2257339.255605] [<c0174d80>] vfs_write+0x83/0x120
Oct 15 12:22:39 sp5059b kernel: [2257339.255608] [<c0175352>] sys_write+0x3c/0x63
Oct 15 12:22:39 sp5059b kernel: [2257339.255612] [<c01038d2>] syscall_call+0x7/0xb
Oct 15 12:22:39 sp5059b kernel: [2257339.255618] =======================
还有一些错误:
Oct 15 12:22:39 sp5059b kernel: [2257339.255618] =======================
Oct 15 13:52:55 sp5059b kernel: [2262820.703285] INFO: task kswapd0:173 blocked for more than 120 seconds.
Oct 15 13:52:55 sp5059b kernel: [2262820.703310] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Oct 15 13:52:55 sp5059b kernel: [2262820.703342] kswapd0 D 9527f7ea 0 173 2
Oct 15 13:52:55 sp5059b kernel: [2262820.703346] f747c4e0 00000046 c036f160 9527f7ea 0007f529 f747c66c c1fdbfc0 00000001
Oct 15 13:52:55 sp5059b kernel: [2262820.703352] 00000000 00000001 0051b47e 00000000 00000000 00000000 00000246 c0131ba7
Oct 15 13:52:55 sp5059b kernel: [2262820.703357] f77dc400 f7731dc4 f77dc450 00396fe5 f8899e28 f77dc414 00000000 f747c4e0
Oct 15 13:52:55 sp5059b kernel: [2262820.703362] Call Trace:
Oct 15 13:52:55 sp5059b kernel: [2262820.703374] [<c0131ba7>] prepare_to_wait+0x12/0x4d
Oct 15 13:52:55 sp5059b kernel: [2262820.703383] [<f8899e28>] log_wait_commit+0x8b/0xd1 [jbd]
Oct 15 13:52:55 sp5059b kernel: [2262820.703393] [<c0131a98>] autoremove_wake_function+0x0/0x2d
Oct 15 13:52:55 sp5059b kernel: [2262820.703398] [<f88975dd>] journal_try_to_free_buffers+0x123/0x13b [jbd]
Oct 15 13:52:55 sp5059b kernel: [2262820.703407] [<f89320f7>] ext3_releasepage+0x0/0x57 [ext3]
Oct 15 13:52:55 sp5059b kernel: [2262820.703420] [<c0156409>] try_to_release_page+0x33/0x45
Oct 15 13:52:55 sp5059b kernel: [2262820.703424] [<c015ee80>] shrink_page_list+0x3c7/0x4a8
Oct 15 13:52:55 sp5059b kernel: [2262820.703431] [<c015e349>] isolate_lru_pages+0x44/0x17f
Oct 15 13:52:55 sp5059b kernel: [2262820.703436] [<c015e349>] isolate_lru_pages+0x44/0x17f
Oct 15 13:52:55 sp5059b kernel: [2262820.703441] [<c015f04f>] shrink_inactive_list+0xee/0x2fd
Oct 15 13:52:55 sp5059b kernel: [2262820.703450] [<c015f30e>] shrink_zone+0xb0/0xcd
Oct 15 13:52:55 sp5059b kernel: [2262820.703454] [<c015fa64>] kswapd+0x27b/0x3ed
Oct 15 13:52:55 sp5059b kernel: [2262820.703459] [<c015e484>] isolate_pages_global+0x0/0x42
Oct 15 13:52:55 sp5059b kernel: [2262820.703463] [<c0131a98>] autoremove_wake_function+0x0/0x2d
Oct 15 13:52:55 sp5059b kernel: [2262820.703468] [<c015f7e9>] kswapd+0x0/0x3ed
Oct 15 13:52:55 sp5059b kernel: [2262820.703471] [<c01319d7>] kthread+0x38/0x5d
Oct 15 13:52:55 sp5059b kernel: [2262820.703474] [<c013199f>] kthread+0x0/0x5d
Oct 15 13:52:55 sp5059b kernel: [2262820.703477] [<c01044f7>] kernel_thread_helper+0x7/0x10
Oct 15 13:52:55 sp5059b kernel: [2262820.703482] =======================
Oct 17 16:39:21 sp5059b kernel: [2448749.835890] INFO: task exim4:15225 blocked for more than 120 seconds.
Oct 17 16:39:21 sp5059b kernel: [2448749.835915] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Oct 17 16:39:21 sp5059b kernel: [2448749.835947] exim4 D 0f35bdb1 0 15225 15223
Oct 17 16:39:21 sp5059b kernel: [2448749.835951] c24032c0 00000082 c1fdbfc0 0f35bdb1 00089b8e c240344c c1fdbfc0 00000001
Oct 17 16:39:21 sp5059b kernel: [2448749.835956] 00000000 00000001 000013fa 00000000 00000000 00000000 00000246 c0131ba7
Oct 17 16:39:21 sp5059b kernel: [2448749.835962] f77dc400 e6185f20 f77dc450 0039e41c f8899e28 f77dc414 00000000 c24032c0
Oct 17 16:39:21 sp5059b kernel: [2448749.835967] Call Trace:
Oct 17 16:39:21 sp5059b kernel: [2448749.835978] [<c0131ba7>] prepare_to_wait+0x12/0x4d
Oct 17 16:39:21 sp5059b kernel: [2448749.835986] [<f8899e28>] log_wait_commit+0x8b/0xd1 [jbd]
Oct 17 16:39:21 sp5059b kernel: [2448749.835996] [<c0131a98>] autoremove_wake_function+0x0/0x2d
Oct 17 16:39:21 sp5059b kernel: [2448749.836001] [<f8896451>] journal_stop+0x12f/0x151 [jbd]
Oct 17 16:39:21 sp5059b kernel: [2448749.836009] [<f892f0b7>] ext3_sync_file+0x57/0x9c [ext3]
Oct 17 16:39:21 sp5059b kernel: [2448749.836022] [<c015744c>] filemap_fdatawrite+0x12/0x16
Oct 17 16:39:21 sp5059b kernel: [2448749.836027] [<c018f5b5>] do_fsync+0x41/0x83
Oct 17 16:39:21 sp5059b kernel: [2448749.836031] [<c018f614>] __do_fsync+0x1d/0x2b
Oct 17 16:39:21 sp5059b kernel: [2448749.836034] [<c01038d2>] syscall_call+0x7/0xb
Oct 17 16:39:21 sp5059b kernel: [2448749.836041] =======================
答案1
在我看来,目录中可能有大量文件。我在非常大的目录中看到了与您描述的非常相似的症状。
可能存在某种问题(可能是 logrotate 的配置问题),导致您最终拥有数百万个文件。一旦达到数百万个文件,大多数文件系统都会开始出现问题。仅仅执行一个操作ls
就需要花费大量时间,如果您等待的时间足够长,甚至可能会死机。rm
由于文件数量庞大,类似命令也会出现问题。同样,像 logrotate 这样的命令似乎会挂起,因为对目录执行简单的操作需要很长时间才能完成。
验证这一点的一种方法是执行ls -l
上述目录(本例中为 /var/log/apache2/)并查看目录条目的大小(而不是内容)。例如(从我的服务器,其中有几个目录,其中包含许多文件):
$ ls -lh
rwxrwxr-x 2 ironport ironport 11M Apr 21 19:37 oma01syslog01/
drwxrwxr-x 2 ironport ironport 12M Apr 21 19:37 oma01syslog02/
drwxrwxr-x 2 ironport ironport 5.8M Mar 17 12:30 sat01syslog01/
drwxrwxr-x 2 ironport ironport 4.0K Jun 29 2011 swn01syslog01/
$ for DIR in * ; do echo -n "$DIR: " ; find $DIR -type f -print | wc -l ; done
oma01syslog01: 204332
oma01syslog02: 195500
sat01syslog01: 70960
swn01syslog01: 0
注意目录条目的大小与其中的文件数量相比。
最好的办法是尝试使用类似 的命令来查看文件find
。它不会在显示文件之前尝试拉取整个列表,并且可以让你查询和操作目录,而不会出现 和 中出现的问题ls
。rm
下面是一些有用的例子。
文件数量:
find ./directory/name/here -type f -print | wc -l
查看目录中的文件示例:
find ./directory/name/here -type f -print | head -20 | xargs ls -lh
从目录中删除所有匹配模式的文件:
find ./directory/name/here -type f -iname '*.log' -print | xargs rm -rf
笔记:我刚刚注意到您的评论,其中您展示了ls
从一个目录向上的内容:
drwxr-xr-x 2 root root 126406656 2011-10-17 18:51 vhosts
这证实了我的怀疑。126406656 字节等于 120MB。这是一个非常大的目录条目(从我上面的示例来看,我有一个 11MB 的目录条目,里面有 200k 个文件),这表明该目录中有数百万个文件。
答案2
这应该服务器故障, 但:
您的目录中的读取位似乎关闭:使用类似chmod a+r
目录名来改正它。
这很可能发生在创建目录时;日志轮换脚本会这样做吗?完全可以预料到,此脚本的多个并发实例会导致问题,但我很惊讶它会在目录上产生权限问题。无论如何,您需要一种更快的轮换方式,并且可能需要一种机制来阻止脚本在已经运行时启动。
答案3
挂起任务是一种非常严重的错误。它非常严重,因此有一个名为 /proc/sys/kernel/hung_task_panic 的 proc 文件可以自动导致崩溃/重启。这意味着某个进程在内核中挂起很长时间,正常使用情况下不应该发生这种情况。
- 检查你的内存使用情况/交换
- 检查你的文件系统/磁盘
答案4
问题似乎已经解决了?!?!
我注意到服务器的负载已经从峰值平均约 70 下降到徘徊在 1-3 左右(正常水平)。
我运行:screen rm -rf vhosts
大约半小时后回来并尝试恢复屏幕,但什么也没发生。耶!目录已被删除。
确实不知道发生了什么/正在发生什么,但至少部分问题已经消失。
不再有奇怪的内核错误。