Log4J引起的程序“装死”

本文涉及的产品
日志服务 SLS,月写入数据量 50GB 1个月
简介:

问题起因

依然是在使用GemFire的集群中,我们发现偶尔会出现一些GemFire的Function执行特别慢,并且超过了两分钟(为了保证数据的一致性,我们在写之前需要先拿一个Lock,因为不能每个Key都对应一个Lock,因而我们使用了Guava的Stripe Lock(关于Stripe Lock可以参考 这里 ),而且这个Lock本身我们指定了2分钟的超时时间,因而如果写超过两分钟,我们就会收到Exception)。这个问题其实已经困扰了我们好几年了,刚前段时间,我们发现长时间的Stop-The-World GC会引起这个问题,而且这种时候很多时候会引起那个节点从集群中退出,并不是所有的这种错误都有GC的问题,我特地查了GC的日志,有些这种写超过两分钟的情况下,GC一直处于非常健康的状态,而且查了GemFire的日志和我们自己的日志,也没有发现任何异常。由于我们每个数据保留两分份拷贝,也就是说每次数据写都要写两个节点,两分钟对CPU来说可以做太多的事情,因而只有IO才能在某些时候产生这种问题,在问题发生的时候也没有任何overflow数据,而且本地操作,即使对IO来说2分钟也是一个非常长的时间了,因而我们只能怀疑这是写另一个节点引起的,对另一个节点,它是在同一个Data Center中,而且基本是在同一个Chasis内部,因而它们之间小于1M的数据量通信也不太可能花去2分钟的时间,所以剩下的我们就只能怀疑网络的问题了,比如数据丢包、网络抖动、网络流量太大一起传输变慢等,但是我们没有找到任何相关的问题。所以我们很长一段时间素手无策,只能怪GemFire闭源,我们不知道这两分钟是不是GemFire自己内部在做一些不为人知的事情,因而太忙了而每来得及处理我们的写请求。虽然我一直觉得不管在处理什么炒作,两分钟都没有响应根本无法解释的通,更何况GemFire节点之间并没有报告有任何异常,或者像以前发现的一个节点向Locator举报另一个节点没有响应的问题,Locator自己也能很正常的向那个节点发送新的成员信息(View),因而看起来向是这个节点虽然花了两分钟多来写一个数据,但是它还是有响应的,有点“假死”的赶脚。

问题发现

这个问题这么几年以来时不时的就会发生,而且因为以前花的时间太多了,而且也没有找到任何出错的地方,现在索性不去花太多时间在上面了,更何况这个它很长时间才发生一次,并且今年以来就一直没发生过,直到前几周出现一次,我有点不信邪的重新去看这个问题,依然没有找到任何可疑的地方,GC日志、应用程序日志、GemFire自己的日志、网络、CPU使用情况等所有的都是正常的,除了问题发生的那个时刻,应用程序没有任何日志,另外在问题发生之前出现过Log4J日志文件的Rolling(我们使用RollingFileAppender,并且只保留20个日志文件),但是Log4J日志文件Roll的日志出现了断结,在开始要Roll到真正完成Roll中间还有几行GemFire自身的日志,此时我并没有觉得这个是有很大问题的,因为我始终觉得Log4J除了它自己提到平均对性能有10%的影响以外,它就是一个简单的把日志写到文件的过程,不会影响的整个应用程序本身,因为它太简单了,直到今天这个问题再次出现,依然没有任何其他方面的收获,所有的地方都显示正常状态,甚至我们之前发现的网卡问题今天也没有发生,然而同样是出问题的两分钟没有出现应用程序日志,日志文件Roll的日志和上次类似,开始Roll到结束出现GemFire日志的交叉。
最近一次发生的日志
[info 2015/08/12 01:56:07.736 BST …] ClientHealthMonitor: Registering client with member id …
log4j: rolling over count=20971801
log4j: maxBackupIndex=20
[info 2015/08/12 01:56:12.265 BST …] ClientHealthMonitor: Unregistering client with member id …
……
[info 2015/08/12 01:56:23.773 BST …] ClientHealthMonitor: Registering client with member id …
log4j: Renaming file logs/….log.19 to logs/….log.20
一周前发生的日志
[info 2015/08/04 01:43:45.761 BST …] ClientHealthMonitor: Registering client with member id …
log4j: rolling over count=20971665
log4j: maxBackupIndex=20
……
[info 2015/08/04 01:45:25.506 BST …] ClientHealthMonitor: Registering client with member id …
log4j: Renaming file logs/….log.19 to logs/….log.20
看似这个是一个规律(套用同事的一句话:一次发生时偶然,两次发生就是科学了)。然而此时我其实依然不太相信Log4J是“凶手”,因为我一直觉得Log4J是一个简单的日志输出框架,它要是出问题也只是它自己的问题,是局部的,而这个问题的出现明显是全局的,直到我突然脑子一闪而过, 日志打印的操作是synchronized,也就是说在日志文件Roll的时候,所有其它需要打日志的线程都要等待直到Roll完成,如果这个Roll过程超过了2分钟,那么就会发生我们看到的Stripe Lock超时,也就是发生了程序“假死”的状态。重新查看Log4J打印日志的方法调用栈,它会在两个地方用synchronized,即同一个Category(Logger)类实例:
     public  void callAppenders(LoggingEvent event) {
         int writes = 0;
         for(Category c =  this; c !=  null; c=c.parent) {
             //  Protected against simultaneous call to addAppender, removeAppender,
             synchronized(c) {
                 if(c.aai !=  null) {
                    writes += c.aai.appendLoopOnAppenders(event);
                }
                 if(!c.additive) {
                     break;
                }
            }
        }
。。。
    }
以及同一个Appender在doApppend时:
     public  synchronized  void doAppend(LoggingEvent event) {
      。。。
       this.append(event);
    }
而Roll的过程就是在append方法中,进一步分析,在下面两句话之间,他们分别花费了超过100s和超过11s的时间:
log4j: maxBackupIndex=20
。。。
log4j: Renaming file logs/….log.19 to logs/….log.20
而这两句之间只包含了两个File.exists(),一个File.delete(),一个File.rename()操作:
     public  void rollOver() {
      。。。
       if(maxBackupIndex > 0) {
         //  Delete the oldest file, to keep Windows happy.
        file =  new File(fileName + '.' + maxBackupIndex);
         if (file.exists())
            renameSucceeded = file.delete();
         for ( int i = maxBackupIndex - 1; i >= 1 && renameSucceeded; i--) {
            file =  new File(fileName + "." + i);
             if (file.exists()) {
                target =  new File(fileName + '.' + (i + 1));
                LogLog.debug("Renaming file " + file + " to " + target);
                renameSucceeded = file.renameTo(target);
            }
        }
      。。。
      }
    }

NFS简单性能测试和分析

因而我对NFS的性能作了一些简单测试:
只有一个线程时,在NFS下rename性能:
1 file:                    3ms
10 files:                48ms
20 files:                114ms
相比较,在本地磁盘rename的性能:
1 file:                    1ms
3 files:                  1ms
10 files:                3ms
对NFS和本地磁盘写的性能(模拟日志,每行都会flush):

 

NFS

LOCAL

1 writer, 11M

443ms

238ms

1 writer, 101M

2793ms

992ms

10 writers, 11M

~4400ms

~950ms

10 writers, 101M

~30157ms

~5500ms


一些其他的统计:
100同时写:
Create 20 files spend: 301ms
Renaming 20 files spends: 333ms
Delete 20 files spends: 329ms
1000同时写:
Create 20 files spend: 40145ms
Renaming 20 files spends: 39273ms
而在1000个同时写的过程中,重命名:
Rename file: LogTest1.50 take:  36434ms
Rename file: LogTest1.51 take:  39ms
Rename file: LogTest1.52 take:  34ms
也就是说在这个模拟过程中,一个文件的rename超过36s,而向我们有十几台机器同时使用相同的NFS,并且每台机器上都跑二三十个程序,如果那段时间同时有上万个的日志写,可以预计达到100s情况是可能发生的。
关于NFS性能的问题,在《构建高性能WEB站点》的书(330页)中也有涉及。简单的介绍,NFS由Sun在1984年开发,是主流异构平台实现文件共享的首选方案。它并没有自己的传输协议,而是使用RPC(Remote Procedure Call)协议(应用层),RPC协议默认底层基于UDP传输,但是自己实现在丢包时的重传机制,而且NFS服务器采用多进程模型,默认进程为4,但是一般都会调优增加服务进程数,然而“不管怎么对NFS进行性能优化,NFS注定不适合作为I/O密集型文件共享方案,但可以作为一般用途,比如提供站点内部的资源共享,它的优势在于容易搭建,而且可以减少不必要的数据冗余。”
可以使用命令:“nfsstat -c”获取对NFS服务器的操作的简单统计,具体可以参考《构建高性能WEB站点》的相关章节,里面还有更详细的对NFS服务器性能的测试。

总结

从这个事件我总结了两件事情:
1. 日志的影响可能是全局性的,因而要非常小心,一个耗时的操作可能引起程序的“假死”,因而要非常小心。
2. 虽然把日志打印在NFS上,对大量的日志文件查找会方便很多,但是这是一个很耗性能的设计,特别是当大量的程序共享这个NFS的时候,因而要尽量避免。

相关实践学习
日志服务之使用Nginx模式采集日志
本文介绍如何通过日志服务控制台创建Nginx模式的Logtail配置快速采集Nginx日志并进行多维度分析。
相关文章
|
Java Maven
Maven:程序包org.apache.log4j不存在问题处理
1 2 log4j 3 log4j 4 1.2.15 5 6 7 javax.
4486 0
|
Java C语言 数据格式
程序日志输出实现-Log4j
学习开发的过程中,我们都应该用过System.out.println();来做一些调试工作,有时候确实很有用有没有。但是这种简单粗暴的方式让程序中到处存在着sysout。这种方式难免会有性能的影响,维护时也要对其大量的修改工作,并且输出的信息错乱复杂。
|
22天前
|
XML 安全 Java
【日志框架整合】Slf4j、Log4j、Log4j2、Logback配置模板
本文介绍了Java日志框架的基本概念和使用方法,重点讨论了SLF4J、Log4j、Logback和Log4j2之间的关系及其性能对比。SLF4J作为一个日志抽象层,允许开发者使用统一的日志接口,而Log4j、Logback和Log4j2则是具体的日志实现框架。Log4j2在性能上优于Logback,推荐在新项目中使用。文章还详细说明了如何在Spring Boot项目中配置Log4j2和Logback,以及如何使用Lombok简化日志记录。最后,提供了一些日志配置的最佳实践,包括滚动日志、统一日志格式和提高日志性能的方法。
165 30
【日志框架整合】Slf4j、Log4j、Log4j2、Logback配置模板
|
2月前
|
XML JSON Java
Logback 与 log4j2 性能对比:谁才是日志框架的性能王者?
【10月更文挑战第5天】在Java开发中,日志框架是不可或缺的工具,它们帮助我们记录系统运行时的信息、警告和错误,对于开发人员来说至关重要。在众多日志框架中,Logback和log4j2以其卓越的性能和丰富的功能脱颖而出,成为开发者们的首选。本文将深入探讨Logback与log4j2在性能方面的对比,通过详细的分析和实例,帮助大家理解两者之间的性能差异,以便在实际项目中做出更明智的选择。
248 3
|
3月前
|
Java
日志框架log4j打印异常堆栈信息携带traceId,方便接口异常排查
日常项目运行日志,异常栈打印是不带traceId,导致排查问题查找异常栈很麻烦。
|
4月前
|
XML Java Maven
log4j 日志的简单使用
这篇文章介绍了Log4j日志框架的基本使用方法,包括在Maven项目中添加依赖、配置`log4j.properties`文件以及在代码中创建和使用Logger对象进行日志记录,但实际打印结果中日志级别没有颜色显示。
log4j 日志的简单使用
|
4月前
|
XML Java Maven
Spring5入门到实战------16、Spring5新功能 --整合日志框架(Log4j2)
这篇文章是Spring5框架的入门到实战教程,介绍了Spring5的新功能——整合日志框架Log4j2,包括Spring5对日志框架的通用封装、如何在项目中引入Log4j2、编写Log4j2的XML配置文件,并通过测试类展示了如何使用Log4j2进行日志记录。
Spring5入门到实战------16、Spring5新功能 --整合日志框架(Log4j2)
|
4月前
|
存储 消息中间件 监控
Java日志详解:日志级别,优先级、配置文件、常见日志管理系统ELK、日志收集分析
Java日志详解:日志级别,优先级、配置文件、常见日志管理系统、日志收集分析。日志级别从小到大的关系(优先级从低到高): ALL < TRACE < DEBUG < INFO < WARN < ERROR < FATAL < OFF 低级别的会输出高级别的信息,高级别的不会输出低级别的信息
|
5月前
|
Java 测试技术 Apache
《手把手教你》系列基础篇(八十六)-java+ selenium自动化测试-框架设计基础-Log4j实现日志输出(详解教程)
【7月更文挑战第4天】Apache Log4j 是一个广泛使用的 Java 日志框架,它允许开发者控制日志信息的输出目的地、格式和级别。Log4j 包含三个主要组件:Loggers(记录器)负责生成日志信息,Appenders(输出源)确定日志输出的位置(如控制台、文件、数据库等),而 Layouts(布局)则控制日志信息的格式。通过配置 Log4j,可以灵活地定制日志记录行为。
58 4
|
4月前
|
存储 运维 Java
SpringBoot使用log4j2将日志记录到文件及自定义数据库
通过上述步骤,你可以在Spring Boot应用中利用Log4j2将日志输出到文件和数据库中。这不仅促进了良好的日志管理实践,也为应用的监控和故障排查提供了强大的工具。强调一点,配置文件和代码的具体实现可能需要根据应用的实际需求和运行环境进行调优和修改,始终记住测试配置以确保一切运行正常。
650 0