服务器仅日志文件读写慢(log4j)

总述

服务器慢, jsp页面和服务都卡, 排查后发现
log4j在java org.apache.log4j.Category.callAppenderscall阻塞,
业务在java org.springframework.context.support.ResourceBundleMessageSource.getResourceBundle阻塞,
由于2台weblogic竞争写一个日志文件导致的, 可以尝试配置不同名的日志文件, 比如在log4j.xml中定义文件名的参数中加${weblogic.Name}(weblogic启动参数中应该有配置, 实际类似于java System.getProperty("weblogic.Name")).
(结论由调整前后的对比得出)

现象

• 服务器启动速度还行.
• 启动后可以短暂正常访问(加载速度正常), 随后就出现页面和服务卡顿, 日志未见异常, 会话和线程直接爆满.
• 共2台服务, 都很慢

排查

• 通过weblogic查看会话和线程, 发现直接爆满.
• 通过weblogic转储线程堆栈.
• 分析堆栈发现部分业务线程阻塞在java org.springframework.context.support.ResourceBundleMessageSource.getResourceBundle, 其中一个业务线程多走了几步后和其他一些业务线程一起阻塞在java org.apache.log4j.Category.callAppenders, 堆栈中只有一个线程在写日志;
• 形成了多个getResourceBundle在等一个getResourceBundle释放锁, 而这个持有锁的getResourceBundle调用了log4j且正在等待一个持有RootLogger的锁的callAppenders释放锁, 进而导致一堆业务线程卡住.
• 推测是磁盘写入慢, 但是其他服务正常, 且通过服务访问系统其他文件时正常, 排除此可能.
• 日志使用的rollingfileappender, 推测日志文件有问题, 下载该文件的时候很慢, 但是下载同目录的其他文件很快, 同时, 其他服务的相同位置的日志文件都很快, 所有非常怀疑是当前写入的日志文件有问题.
• 过了差不多9个小时, 服务变正常了
• 比对日志发现因超过单文件配置大小已经自动备份和新建, 2个服务现在在写2个不同的日志文件
• 下载历史日志文件, 发现其他日志都是一个服务输出的, 而服务卡顿的日志里有2个服务的输出
• 推测是双服务竞争日志文件导致的IO慢