项目日志漫谈

项目日志漫谈

日志系统是任何系统都不可或缺的一部分,明白如何记录日志和应该记录什么是一个软件工程师必备的技能。但怎么样才能做好日志系统呢?

记录日志的若干建议

查阅了很多资料,再结合自己的项目经验,大概可以给出以下几点建议。

不应该自己写日志系统

现在有很多流行的logging库,在Java里面有比如Log4j(log4j2),slf4j,logback,Apache Commons Logging等,它们都经受住了时间的考验,是非常可靠的日志系统(库)。关于各个库的性能问题,我们稍后再详细讨论,但可以肯定的是,它们肯定比你自己写日志系统靠谱的多。

推荐使用slf4j +log4j(log4j2)/logback来记录日志。

使用slf4j的原因是,SLF4J与上述其它的日志库之间有一个主要的区别。SLF4J或者说是Java的简单记录日志设计没有真正地实现日志记录,相反它只是一个允许你使用任何处于后端的日志记录库的抽象层 。如果你正在编写内部或者外部使用的API或者应用库的话,那么你真的不需要让使用你所编写的库的客户端还去选择日志库。假设项目已经使用了log4j,而且你包含一个名为Apache Active MQ的库,这个库还依赖于另一个日志记录库logback的话,那么你还需要包含它们,然而,如果Apache Active MQ使用了SLF4J的话,你可以继续使用你的日志记录库,而不需要痛苦地添加和维护新的日志记录框架。简短的说,SLF4J让你的代码独立于任何特定的日志记录API,这个好的想法尤其适合于公共的API开发人员。虽然日志记录库的抽象理念不是新的,而且Apache的commons logging日志记录库也是用了这个理念,不过现在SLF4J是Java世界里标准的日志记录库。让我们看一些使用 SLF4J而不使用log4j,logback或者java.util.logging的理由。

1)在你的开源库或者私有库中使用SLF4J,可以使它独立于任何的日志实现,这就意味着不需要管理多个库和多个日志文件。你的客户端将会体会到这一点。

2)SLF4J提供了占位日志记录,通过移除对isDebugEnabled(), isInfoEnabled()等等的检查提高了代码的可读性。

3)通过使用日志记录方法,直到你使用到的时候,才会去构造日志信息(字符串),这就同时提高了内存和CPU的使用率。

4)做一个侧面的说明,越少的临时字符串,垃圾回收器就意味着越少的工作,这就意味着为你的应用程序提供更好的吞吐量和性能。

在适当级别上记录日志

尽管我们有多个日志库可供选择,但是在记录日志时都要遵循一个普遍的原则:在适当的级别傻姑娘记录日志。下面给出一个比较通用的建议。

  • TRACE level: 一般用在开发环境中,用于开发过程中追踪问题。
  • DEBUG level:可以把一切东西都记录在这里。这在调试过程中最常用到。在进入生产阶段前减少debug语句的数量,只留下最有意义的部分。
  • INFO level: 记录一些比较有价值的用户行为(user-driven)和系统的特定行为(例如计划任务…),但是这样的信息不宜太多。
  • NOTICE level:这是生产环境中使用的级别。把一切不认为是错误的,可以记录的事件都log起来
  • WARN level:记录在这个级别的事件都有可能成为一个error。例如,一次调用数据库使用的时间超过了预设时间,或者内存缓存即将到达容量上限。这可以让你适当地发出警报,或者在调试时更好地理解系统在failure之前做了些什么
  • ERROR level:把每一个错误条件都记录在这。例如API调用返回了错误,或是内部错误条件
  • FATAL level:极少被用到,在实际程序中也不应该出现多少。在这个级别上进行log意味着程序要结束了。例如一个网络守护进程无法bind到socket上,那么它唯一能做的就只有log到这里,然后退出运行。

测试联调环境一般的都是用DEBUG level,因为可以获取到任何自己感兴趣的信息,正式的生产环境可以用INFO level,只记录一些重要的信息,当然也有的系统会用到WARN level。当然如果在生产环境出现了一个bug,仅靠INFO level或者WARN level,ERROR level无法定位问题的话,可能你会想看到debug级别的日志,帮助排查问题,这个就涉及到动态调整系统的日志级别了,我们稍后再说。

将日志信息分类

大部分的日志库允许指定一个日志类别以及将不同类别的日志记录到不同的文件中去。它可以分类log信息,并基于logging框架的配置,在最后以某一形式进行记录。比如将日志分为业务日志、错误日志和系统日志等,并将它们按照统一的格式进行输出,使得排查问题时可以一目了然的看出是哪个文件在什么时间点发生了什么,如果是错误日志的话,最好是打印出行号和错误原因。

1
2
3
4
5
6
7
8
9
10
11
<RollingRandomAccessFile name="smartrobotLog"
fileName="logs/biz.log"
filePattern="logs/$${date:yyyy-MM}/biz-%d{MM-dd-yyyy}-%i.log">
<Append>true</Append>
<PatternLayout
pattern="%d{yy-MM-dd.HH:mm:ss.SSS} [%-16t] %-5p %-22c{0} - [%X{traceId}] - %m%n" />
<Policies>
<TimeBasedTriggeringPolicy interval="1" modulate="true" />
<SizeBasedTriggeringPolicy size="500 MB"/>
</Policies>
</RollingRandomAccessFile>

上面的一段log4j的配置代码指定了日志输出的格式以及日志文件归档的策略。

如果对log4j的语法不熟悉的话,可以参考http://www.cnblogs.com/elaron/archive/2013/01/14/2860259.html 这篇博客。

写有意义的log

这可能是最重要的建议了。没有什么比你深刻理解程序内部,却写出含糊的日志更糟了。

在你写日志信息之前,总要提醒自己,有突发事件的时候,你唯一拥有的只有来自log文件,你必须从中明白发生了什么。一个很有用的日志内容是接口(无论是自己提供的接口还是调用其它系统的接口)的入参、返回值,如果是调用外部接口的话,最好把完整的请求url及返回的原始结果打印出来。

在写warn和error level时尤为重要的一个方法是,添加辅助信息到log信息中,如果做不到,那么改为把这个操作的作用写下。

还有,不要让一个log信息的内容基于上一个。这是因为前面的信息可能由于(与当前信息)处于不同的类别或者level而没被写入。更坏的情况是,它因多线程或异步操作,在另一个地方(或是以另一方式)出现。

为你的日志增加traceId

一个很有用的关于日志的纪录是traceId(基于线程,可追踪一条业务线),尤其是分布式系统中。如果使用的是log4j或者是logback的话,可以结合slf4j的MDC来为线程统一的添加traceId,可以添加到AOP或Filter或Interceptor中。如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
@Around(value = "execution(* com.xx.xx.facade.impl.*.*(..))", argNames="pjp")
public Object validator(ProceedingJoinPoint pjp) throws Throwable {
try {
String traceId = TraceUtils.begin();
MDC.put("traceId", traceId);
Object obj = pjp.proceed(args);
return obj;
} catch(Throwable e) {
//TODO 处理错误
} finally {
TraceUtils.endTrace();
}
}

代码通过AOP记录了每次请求的traceId并使用变量“mdc_trace_id”记录,在日志配置文件里需要设置变量才能将“traceId”输出到日志文件中。我以logback配置文件为例,看日志第6行%X{traceId}:

1
2
3
4
5
6
7
8
9
10
11
<RollingRandomAccessFile name="smartrobotLog"
fileName="logs/biz.log"
filePattern="logs/$${date:yyyy-MM}/biz-%d{MM-dd-yyyy}-%i.log">
<Append>true</Append>
<PatternLayout
pattern="%d{yy-MM-dd.HH:mm:ss.SSS} [%-16t] %-5p %-22c{0} - [%X{traceId}] - %m%n" />
<Policies>
<TimeBasedTriggeringPolicy interval="1" modulate="true" />
<SizeBasedTriggeringPolicy size="500 MB"/>
</Policies>
</RollingRandomAccessFile>

当然利用MDC我们还可以添加很多其它有用的信息。总结下MDC为我们带来的好处:

  1. 如果你的系统已经上线,突然有一天老板说我们增加一些用户数据到日志里分析一下。如果没有MDC我猜此时此刻你应该处于雪崩状态。MDC恰到好处的让你能够实现在日志上突如其来的一些需求
  2. 如果你是个代码洁癖,封装了公司LOG的操作,并且将处理线程跟踪日志号也封装了进去,但只有使用了你封装日志工具的部分才能打印跟踪日志号,其他部分(比如hibernate、mybatis、httpclient等等)日志都不会体现跟踪号。当然我们可以通过linux命令来绕过这些困扰。
  3. 使代码简洁、日志风格统一

应该用机器可解析的格式来打日志

日志是给人看的,但有时候当数量量很大的情况下,靠人肉去分析log就不太现实了,一定要自动化的去分析日志。如果我们想要顺利的实现日志分析的自动化,那么用机器容易解析的格式记录日志就很有必要了。

举个例子。

1
log.info("User {} plays {} in game {}",userId,card,gameId);

它会生成类似如下的输出:

1
2017-10-1217:49:37,656[T1]INFOc.d.g.UserRequestUser1334563plays4ofspadesingame23425656

如果我们想自动化解析它的话,就比较麻烦了/User(\d+)plays(.+)ingame(\d+)$/ 正则表达式是一个可行的方案,但是这并不轻松而且容易出错。一个更好的解决方案是把log记录成机器容易解析的格式,比如JSON。

1
2017-10-1217:49:37,656[T1]INFOc.d.g.UserRequestUserplays{'user':1334563,'card':'4ofspade','game':23425656}

现在你的log分析器可以更容易地写入,更直接地索引,而且你可以释放logstash(如果日志最终是放在logstash)所有的威力。

将日志收集到日志聚合系统

说到日志分析,就不得不提日志聚合系统。现在主流的日志分析系统有logstash和flume。关于它们具体的区别请自己百度,这样的文章很多。但是使用日志聚合系统总的目的是为了分析日志,还可以解决分布式环境下日志分散的问题。

应该考虑阅读者

为什么要对应用程序做日志?

唯一的答案是,在某一天会有人去读它(或是它的意义)。更重要的是,猜猜谁会读它,这是很有趣的事。对于不同的”谁”,你将要写下的log信息的内容,上下文,类别和level会大不同。

这些”谁”包括:

  • 一个尝试自己解决问题的终端用户(想象一个客户端或桌面程序)
  • 一个在调试产品问题的系统管理员或者运维工程师
  • 一个在开发中debug,或者在解决产品问题的开发者

开发者了解程序内部,所以给他的log信息可以比给终端用户的复杂得多。为你的目标阅读者调整你的表达方式,乃至为此加入额外的类别(dedicate separate catagories)。

当然,不管目标读者是谁,请记得给你的日志带上上下文。这一点可以配合前面提到的MDC来完成。、

给日志添加监控

可以给log4j日志添加邮件提醒,当出现ERROR级别的错误时发送邮件给相关技术人员。当然,如果你有专门的监控系统,这点可以忽略。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
## MAIL
log4j.appender.MAIL=org.apache.log4j.net.SMTPAppender
# 日志的错误级别
log4j.appender.MAIL.Threshold=ERROR 
#缓存文件大小,日志达到512K时发送Email
log4j.appender.MAIL.BufferSize=512
# 发送邮件的服务器
log4j.appender.MAIL.SMTPHost=smtp.163.com
# 邮件的标题
log4j.appender.MAIL.Subject=Log4J ErrorMessage
# 用户名
log4j.appender.MAIL.SMTPUsername=邮箱用户名
# 密码
log4j.appender.MAIL.SMTPPassword=邮箱密码
# 发件人地址
log4j.appender.MAIL.From=test@163.com 
# 日志邮件的接收者
log4j.appender.MAIL.To=test@163.com

流行日志库的性能对比

关于性能对比,可以参考这篇博客 https://blog.souche.com/logback-log4j-log4j2shi-ce/ 。

这里只说下结果。

实验环境

  • OS: Mac OS X 10.12.1
  • CPU: 2.6 GHz Intel Core i5
  • 内存: 8 GB 1600 MHz DDR3

实验结果

logback log4j log4j2性能对比

logback log4j log4j2性能对比

  • 可见在同步日志模式下, Logback的性能是最糟糕的.
  • 而log4j2的性能无论在同步日志模式还是异步日志模式下都是最佳的.

其根本原因在于log4j2使用了LMAX,一个无锁的线程间通信库代替了, logback和log4j之前的队列. 并发性能大大提升。

关于log4j2的新特性

  1. 丢数据这种情况少,可以用来做审计功能。而且自身内部报的exception会被发现,但是logback和log4j不会。
  2. log4j2使用了disruptor技术,在多线程环境下,性能高于logback等10倍以上。
  3. (garbage free)之前的版本会产生非常多的临时对象,会造成GC频繁,log4j2则在这方面上做了优化,减少产生临时对象。尽可能少的GC
  4. 利用插件系统,使得扩展新的appender,filter,layout等变得容易,log4j不可以扩展 插件????
  5. 因为插件系统的简单性,所以在配置的时候,可以不用具体指定所要处理的类型。class
  6. 可以自定义level
  7. Java 8 lambda support for lazy logging
  8. Support for Message objects
  9. 对filter的功能支持的更强大
  10. 系统日志(Syslog)协议supports both TCP and UDP
  11. 利用jdk1.5并发的特性,减少了死锁的发生。
  12. Socket LogEvent SerializedLayout
  13. 支持kafka queue

动态更新log4j的日志级别

项目上线了后,我们生产环境一般设置的输出级别都是INFO,但是有些问题不一定能通过INFO信息找到。如何能做到 动态的修改日志的级别,而且不用重启服务,对线上环境的影响减少到最小呢?

首先POM中加上这些依赖:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
<properties>
<spring_version>3.2.2.RELEASE</spring_version>
</properties>
<dependencies>
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-api</artifactId>
<version>1.6.2</version>
</dependency>
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-log4j12</artifactId>
<version>1.6.2</version>
</dependency>
<dependency>
<groupId>javax.servlet</groupId>
<artifactId>servlet-api</artifactId>
<version>2.5</version>
</dependency>
<dependency>
<groupId>log4j</groupId>
<artifactId>log4j</artifactId>
<version>1.2.16</version>
</dependency>
<!-- spring -->
<dependency>
<groupId>org.springframework</groupId>
<artifactId>spring-web</artifactId>
<version>${spring_version}</version>
</dependency>
</dependencies>

然后在项目的web.xml中加上:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
<!--由Sprng载入的Log4j配置文件位置-->
<context-param>
<param-name>log4jConfigLocation</param-name>
<param-value>/WEB-INF/classes/log4j.properties</param-value>
</context-param>
<!--Spring默认刷新Log4j配置文件的间隔,单位为millisecond-->
<context-param>
<param-name>log4jRefreshInterval</param-name>
<param-value>6000</param-value>
</context-param>
<!--Spring log4j 监听器-->
<listener>
<listener-class>org.springframework.web.util.Log4jConfigListener</listener-class>
</listener>

如上配置的作用是每隔6000毫秒扫描一次log4j配置文件的变化。

最后,需要在log4j的配置文件里面加上日志级别控制。

1
2
3
<root level="${log_level}">
<appender-ref ref="${log_appender}" />
</root>

而这里的log_level可以配合disconf或者类似的配置系统实现实时的修改日志级别。

本文参考 http://blog.jobbole.com/52018/ , https://blog.souche.com/logback-log4j-log4j2shi-ce/

坚持原创技术分享,您的支持将鼓励我继续创作!