Log日志框架的学习五.正确使用日志的10个技巧

做一个苦逼的Java攻城师, 我们除了关心系统的架构这种high level的问题, 还需要了解一些语言的陷阱, 异常的处理, 以及日志的输出, 这些"鸡毛蒜皮"的细节. 这篇文章是JCP成员, Tomasz Nurkiewicz(http://nurkiewicz.blogspot.com/ )总结的10条如何正确使用日志的技巧(参见原文). 跟那篇"java编程最差实践"一样, 也是针对一些细节的, 因为日志是我们排查问题, 了解系统状况的重要线索. 我觉得对我们平常coding非常有借鉴意义. 所以转换成中文, 加深一下印象, 也作为自己工作的一个参考.

1)选择正确的Log开源框架
在代码中为了知道程序的行为的状态, 我们一般会打印一条日志:

log.info("Happy and carefree logging");

在所有的日志框架中, 我认为最好的是SLF4J. 比如在Log4J中我们会这样写:

log.debug("Found " + records + " records matching filter: '" + filter + "'");

而在SLF4J中我们会这样写:

log.debug("Found {} records matching filter: '{}'", records, filter);

从可读性和系统效率来说, SLF4J( http://logback.qos.ch/ )比Log4J都要优秀(Log4J涉及到字符串连接和toString()方法的调用). 这里的{}带来的另一个好处, 我们在尽量不损失性能的情况, 不必为了不同的日志输出级别, 而加上类似isDebugEnabled()判断.

SLF4J只是各种日志实现的一个接口抽象(facade), 而最佳的实现是Logback, 相对于Log4J的同门兄弟(皆出自Ceki Gülcü之手), 它在开源社区的活跃度更高.

最后要推荐的是Perf4J( http://perf4j.codehaus.org/ ). 用一句话来概括就是:
如果把log4j看做System.out.println()的话, 那么Perf4J就是System.currentTimeMillis()

Perf4J可以帮助我们更方便的输出系统性能的日志信息. 然后借助其他报表工具将日志以图表的形式加以展现, 从而方便我们分析系统的性能瓶颈. 关于Perf4J的使用可以参考它的开发者指南(http://perf4j.codehaus.org/devguide.html).

下面是一份关于日志jar包依赖的pom.xml参考模板:

<repositories>
    <repository>
        <id>Version99</id>
        <name>Version 99 Does Not Exist Maven repository</name>
        <layout>default</layout>
        <url>http://no-commons-logging.zapto.org/mvn2</url>
    </repository>
</repositories>


<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.5.11</version>
</dependency>
<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>0.9.20</version>
</dependency>
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>jul-to-slf4j</artifactId>
    <version>1.5.11</version>
</dependency>
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>log4j-over-slf4j</artifactId>
    <version>1.5.11</version>
</dependency>
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>jcl-over-slf4j</artifactId>
    <version>1.5.11</version>
</dependency>
<dependency>
    <groupId>commons-logging</groupId>
    <artifactId>commons-logging</artifactId>
    <version>99.0-does-not-exist</version>
</dependency>

下面是测试代码:

SLF4JBridgeHandler.install();

org.apache.log4j.Logger.getLogger("A").info("Log4J");
java.util.logging.Logger.getLogger("B").info("java.util.logging");
org.apache.commons.logging.LogFactory.getLog("C").info("commons-logging");
org.slf4j.LoggerFactory.getLogger("D").info("Logback via SLF4J");

上面的代码, 无论你采用哪个log框架输出日志, 底层采用的都是logback, 至于为什么, 可以看这里(http://www.slf4j.org/legacy.html), 另外这里为了在classpath里面不引入common-logging, 用了一个小技巧, 就是将依赖版本设置为99.0-does-not-exist, 关于这种用法的说明可以看这里(http://day-to-day-stuff.blogspot.com/2007/10/announcement-version-99-does-not-exist.html), 不过log4j的作者认为最简单的做法就是直接去掉对common-logging的依赖, 相关内容可以看这里的说明(http://www.slf4j.org/faq.html#excludingJCL)

2) 理解正确的日志输出级别
很多程序员都忽略了日志输出级别, 甚至不知道如何指定日志的输出级别. 相对于System.out来说, 日志框架有两个最大的优点就是可以指定输出类别(category)和级别(level). 对于日志输出级别来说, 下面是我们应该记住的一些原则:
ERROR:系统发生了严重的错误, 必须马上进行处理, 否则系统将无法继续运行. 比如, NPE, 数据库不可用等.

WARN:系统能继续运行, 但是必须引起关注. 对于存在的问题一般可以分为两类: 一种系统存在明显的问题(比如, 数据不可用), 另一种就是系统存在潜在的问题, 需要引起注意或者给出一些建议(比如, 系统运行在安全模式或者访问当前系统的账号存在安全隐患). 总之就是系统仍然可用, 但是最好进行检查和调整.

INFO:重要的业务逻辑处理完成. 在理想情况下, INFO的日志信息要能让高级用户和系统管理员理解, 并从日志信息中能知道系统当前的运行状态. 比如对于一个机票预订系统来说, 当一个用户完成一个机票预订操作之后, 提醒应该给出"谁预订了从A到B的机票". 另一个需要输出INFO信息的地方就是一个系统操作引起系统的状态发生了重大变化(比如数据库更新, 过多的系统请求).

DEBUG:主要给开发人员看, 下面会进一步谈到.

TRACE: 系统详细信息, 主要给开发人员用, 一般来说, 如果是线上系统的话, 可以认为是临时输出, 而且随时可以通过开关将其关闭. 有时候我们很难将DEBUG和TRACE区分开, 一般情况下, 如果是一个已经开发测试完成的系统, 再往系统中添加日志输出, 那么应该设为TRACE级别.

以上只是建议, 你也可以建立一套属于你自己的规则. 但是一套良好的日志系统, 应该首先是能根据情况快速灵活的调整日志内容的输出.

最后要提到的就是"臭名昭著"的is*Enabled()条件, 比如下面的写法:

if(log.isDebugEnabled())
    log.debug("Place for your commercial");

这种做法对性能的提高几乎微乎其微(前面在提到SLF4J的时候已经说明), 而且是一种过度优化的表现. 极少情况下需要这样写, 除非构造日志信息非常耗性能. 最后必须记住一点: 程序员应该专注于日志内容, 而将日志的输出的决定权交给日志框架去非处理.

3) 你真的知道log输出的内容吗?
对于你输出的每一条log信息, 请仔细检查最终输出的内容是否存在问题, 其中最重要的就是避免NPE, 比如想下面这样:

log.debug("Processing request with id: {}", request.getId());

这里我们能否保证request不为null? 除了NPE之外, 有时候我们可能还需要考虑, 是否会导致OOM? 越界访问? 线程饥饿(log是同步的)? 延迟初始化异常? 日志打爆磁盘等等. 另外一个问题就是在日志中输出集合(collection), 有时候我们输出的集合内容可能是由Hibernate从数据库中取出来的, 比如下面这条日志信息:

log.debug("Returning users: {}", users);

这里最佳的处理方式是仅仅输出domain对象的id或者集合的大小(size), 而对Java来说, 不得不要吐槽几句, 要遍历访问集合中每一个元素的getId方法非常繁琐. 这一点Groovy就做的非常简单(users*.id), 不过我们可以借助Commons Beanutils工具包来帮我们简化:

log.debug("Returning user ids: {}", collect(users, "id"));

这里的collect方法的实现如下:

public static Collection collect(Collection collection, String propertyName) {
    return CollectionUtils.collect(collection, new BeanToPropertyValueTransformer(propertyName));
}

不过不幸的是, 在给Commons Beanutils提了一个patch(BEANUTILS-375 https://issues.apache.org/jira/browse/BEANUTILS-375)之后, 并没有被接受:(

最后是关于toString()方法. 为了让日志更容易理解, 最好为每一个类提供合适的toString()方法. 这里可以借助ToStringBuilder工具类. 另外一个就是关于数组和某些集合类型. 因为数组是使用的默认的toString方法. 而某些集合没有很好的实现toString方法. 对于数组我们可以使用JDK的Arrays.deepToString()方法(http://docs.oracle.com/javase/6/docs/api/java/util/Arrays.html#deepToString%28java.lang.Object[]%29).

4) 小心日志的副作用

有时候日志或多或少的会影响系统的行为, 比如最近碰到的一个情况就是在某些条件下, Hibernate会抛出LazyInitializationException. 这是因为某些输出日志导致延迟初始化的集合在session建立时被加载. 而在某些场景下当提高日志输出级别时, 问题就会消失.

另一个副作用就是日志导致系统运行越来越慢. 比如不恰当的使用toString方法或者字符串连接, 使得系统出现性能问题, 曾经碰到的一个现象, 某个系统每隔15分钟重启一次, 这个主要是执行log输出出现线程饥饿导致, 一般情况下, 如果一个系统一小时内生成的日志有几百MB的时候, 就要小心了.

而如果因为日志输出本身的问题导致正常的业务逻辑被中断, 那就更严重了. 比如下面这种代码, 最好不要这样写:

try {
    log.trace("Id=" + request.getUser().getId() + " accesses " + manager.getPage().getUrl().toString())
} catch(NullPointerException e) {}

5) 日志信息应该简洁且可描述

一般, 每一条日志数据会包括描述和上下文两部分, 比如下面的日志:

log.debug("Message processed");
log.debug(message.getJMSMessageID());

log.debug("Message with id '{}' processed", message.getJMSMessageID());

第一条只有描述, 第二条只有上下文, 第三条才算完整的一条日志, 还有下面这种日志:

if(message instanceof TextMessage)
    //...
else
    log.warn("Unknown message type");

在上面的警告日志中没有包含实际的message type, message id等信息, 只是表明程序有问题, 那么是什么导致了问题呢? 上下文是什么? 我们什么都不知道.

另外一个问题就是在日志中加上一个莫名其妙的内容, 即所谓的"magic log". 比如有些程序员会在日志中随手敲上"&&&!#"这样一串字符, 用来帮助他们定位.

一个日志文件中的内容应该易读, 清晰, 可描述. 而不要使用莫名其妙的字符, 日志要给出当前操作做了什么, 使用的什么数据. 好的日志应该被看成文档注释的一部分.

最后一点, 切记不要在日志中包含密码和个人隐私信息!

6) 正确的使用输出模式

log输出模式可以帮助我们在日志中增加一些清晰的上下文信息. 不过对添加的信息还是要多加小心. 比如说, 如果你是每小时输出一个文件, 这样你的日志文件名中已经包含了部分日期时间信息, 因此就没必要在日志中再包含这些信息. 另外在多线程环境下也不要在自己在日志中包含线程名称, 因为这个也可以在模式中配置.

根据我的经验, 一个理想的日志模式将包含下列信息:

• 当前时间(不需要包含日志, 精确到毫秒)
• 日志级别(如果你关心这个)
• 线程名称
• 简单的日志名(非全限定名的那种)
• 日志描述信息

比如像下面这个logback配置:

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern>%d{HH:mm:ss.SSS} %-5level [%thread][%logger{0}] %m%n</pattern>
    </encoder>
</appender>

千万不要在日志信息中包含下列内容:

• 文件名
• 类名(我想这个应该是全限定名吧)
• 代码行号

还有下面这种写法也是要避免的:

log.info("");

因为程序员知道, 在日志模式中会指定行号, 因此他就可以根据日志输的行号出判断指定的方法是否被调用了(比如这里可能是authenticate()方法, 进而判断登录的用户已经经过了验证). 另外, 大家也要清楚一点, 在日志模式中指定类名, 方法名以及行号会带来严重的性能问题. 下面是我针对这个做的一个简单的测试, 配置如下:

<appender name="CLASS_INFO" class="ch.qos.logback.core.OutputStreamAppender">
    <encoder>
        <pattern>%d{HH:mm:ss.SSS} %-5level [%thread][%class{0}.%method\(\):%line][%logger{0}] %m%n</pattern>
    </encoder>
    <outputStream class="org.apache.commons.io.output.NullOutputStream"/>
</appender>
<appender name="NO_CLASS_INFO" class="ch.qos.logback.core.OutputStreamAppender">
    <encoder>
        <pattern>%d{HH:mm:ss.SSS} %-5level [%thread][LoggerTest.testClassInfo\(\):30][%logger{0}] %m%n</pattern>
    </encoder>
    <outputStream class="org.apache.commons.io.output.NullOutputStream"/>
</appender>

下面是测试代码:

import org.junit.Test;
import org.perf4j.StopWatch;
import org.perf4j.slf4j.Slf4JStopWatch;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class LoggerTest {

    private static final Logger log = LoggerFactory.getLogger(LoggerTest.class);
    private static final Logger classInfoLog = LoggerFactory.getLogger("CLASS_INFO");
    private static final Logger noClassInfoLog = LoggerFactory.getLogger("NO_CLASS_INFO");

    private static final int REPETITIONS = 15;
    private static final int COUNT = 100000;

    @Test
    public void testClassInfo() throws Exception {
        for (int test = 0; test < REPETITIONS; ++test)
            testClassInfo(COUNT);
    }

    private void testClassInfo(final int count) {
        StopWatch watch = new Slf4JStopWatch("Class info");
        for (int i = 0; i < count; ++i)
            classInfoLog.info("Example message");
        printResults(count, watch);
    }

    @Test
    public void testNoClassInfo() throws Exception {
        for (int test = 0; test < REPETITIONS; ++test)
            testNoClassInfo(COUNT * 20);
    }

    private void testNoClassInfo(final int count) {
        StopWatch watch = new Slf4JStopWatch("No class info");
        for (int i = 0; i < count; ++i)
            noClassInfoLog.info("Example message");
        printResults(count, watch);
    }

    private void printResults(int count, StopWatch watch) {
        log.info("Test {} took {}ms (avg. {} ns/log)", new Object[]{
                watch.getTag(),
                watch.getElapsedTime(),
                watch.getElapsedTime() * 1000 * 1000 / count});
    }

}

在上面的测试代码中, CLASS_INFO日志输出了1500万次, 而NO_CLASS_INFO输出了3亿次. 后者采用一个静态的文本来取代日志模式中的动态类信息.

从下面的对比图可以看出, 直接在日志模式中指定类名的日志比使用反射动态获取类名的要快13倍(平均输出每条日志耗时:8.8 vs 115微秒). 对于一个java程序员来说, 一条日志耗时100微秒是可以接受的. 这也就是说, 一个后台应用其中1%的时间消耗在了输出日志上. 因此我们有时候也需要权衡一下, 每秒100条日志输出是否是合理的.

最后要提到的是日志框架中比较高级的功能: Mapped Diagnostic Context. MDC(http://www.slf4j.org/api/org/slf4j/MDC.html )主要用来简化基于thread-local的map参数管理. 你可以往这个map中增加任何key-value内容, 然后在随后的日志输出中作为模式的一部分, 与当前线程一起输出.

7) 给方法的输入输出加上日志

当我们在开发过程中发现了一个bug, 一般我们会采用debug的方式一步步的跟踪, 直到定位到最终的问题位置(如果能通过写一个失败的单元测试来暴露问题, 那就更帅了^_^). 但是如果实际情况不允许你debug时, 比如在客户的系统上几天前出现的bug. 如果你没有详细的日志的话, 你能找到问题的根源么?

如果你能根据一些简单的规则来输出每个方法的输入和输出(参数和返回值). 你基本上可以扔掉调试器了. 当然针对每一个方法加上日志必须是合理的: 访问外部资源(比如数据库), 阻塞, 等待等等, 这些地方可以考虑加上日志. 比如下面的代码:

public String printDocument(Document doc, Mode mode) {
    log.debug("Entering printDocument(doc={}, mode={})", doc, mode);
    String id = //Lengthy printing operation
    log.debug("Leaving printDocument(): {}", id);
    return id;
}

因为在方法调用前后加上了日志, 我们可以非常方便的发现代码的性能问题, 甚至找出死锁和线程饥饿(starvation)等严重问题:这种情况下都只有输入(entering)日志, 不会有输出(leaving)日志. 如果方法名类名使用得当, 那么输出的日志信息也将会非常赏心悦目. 因为你可以根据日志完整了解系统的运行情况, 因此分析问题的时候, 也将变得更加轻而易举. 为了减少日志代码, 也可以采用简单的AOP来做日志输出. 但是也要小心, 这种做法可能产生大量的日志.

对于这种日志, 一般采用DEBUG/TRACE级别. 当某些方法的调用非常频繁, 那么大量的日志输出将会影响到系统的性能, 此时我们可以提高相关类的日志级别或者干脆去掉日志输出. 不过一般情况下, 还是建议大家多输出一些日志. 另外也可以将日志看成一种单元测试. 输出的日志将像单元测试一样, 会覆盖到整个方法的执行过程. 没有日志的系统是不可想象的. 因此通过观察日志的输出将是我们了解系统是在正确的运行还是挂了的唯一方式.

8) 用日志检查外部系统

这里是针对前面的一种场景: 如果你的系统需要和其他系统通信, 那么需要考虑是否需要用日志记录这种交互. 一般情况下, 如果一个应用需要与多个系统进行集成, 那么诊断和分析问题将非常困难. 比如在最近的一个项目中, 由于我们在Apache CXF web服务上完整的记录了消息数据(包括SOAP和HTTP头信息), 使得我们在系统集成和测试阶段非常happy.

如果通过ESB的方式来多个系统进行集成, 那么可以在总线(bus)上使用日志来记录请求和响应. 这里可以参考Mules(http://www.mulesoft.org/)的<log-component/>(http://www.mulesoft.org/documentation/display/MULE2USER/Configuring+Components).

有时候与外部系统进行通信产生的大量日志可能让我们无法接受. 另一方面, 我们希望打开日志临时进行一下测试, 或者在系统出现问题的时候我们希望打开短暂的输出日志. 这样我们可以在输出日志和保证系统性能之间取得一个平衡. 这里我们需要借助日志日别. 比如像下面的这样做:

Collection<Integer> requestIds = //...

if(log.isDebugEnabled())
    log.debug("Processing ids: {}", requestIds);
else
    log.info("Processing ids size: {}", requestIds.size());

在上面的代码中, 如果日志级别配置为DEBUG, 那么将但应所有的requestIds信息. 但是如果我们配置INFO级别, 那么只会输出requestId的数量. 不过就像我们前面提到的日志的副作用那样, 如果在INFO级别下requestIds为null将产生NullPointerException.

9) 正确输出异常日志

对于日志输出的第一条原则就是不要用日志输出异常, 而是让框架或者容器去处理. 记录异常本不应该是logger的工作. 而许多程序员都会用日志输出异常, 然后可能返回一个默认值(null, 0或者空字符串). 也可能在将异常包装一下再抛出. 比如像下面的代码这样:

log.error("IO exception", e);
throw new MyCustomException(e);

这样做的结果可能会导致异常信息打印两次(抛出的地方打一次, 捕获处理的地方再打一次).

但是有时候我们确实希望打印异常, 那么应该如何处理呢? 比如下面对NPE的处理:

try {
    Integer x = null;
    ++x;
} catch (Exception e) {
    log.error(e);        //A
    log.error(e, e);        //B
    log.error("" + e);        //C
    log.error(e.toString());        //D
    log.error(e.getMessage());        //E
    log.error(null, e);        //F
    log.error("", e);        //G
    log.error("{}", e);        //H
    log.error("{}", e.getMessage());        //I
    log.error("Error reading configuration file: " + e);        //J
    log.error("Error reading configuration file: " + e.getMessage());        //K
    log.error("Error reading configuration file", e);        //L
}

上面的代码, 正确输出异常信息的只有G和L, A和B甚至不能在SLF4J中编译通过, 其他的都会丢失异常堆栈信息或者打印了不恰当的信息. 这里只要记住一条, 在日志中输出异常信息, 第一个参数一定是一个字符串, 一般都是对问题的描述信息, 而不能是异常message(因为堆栈里面会有), 第二个参数才是具体的异常实例.

注: 对于远程调用类型的服务抛出的异常,一定要注意实现序列化, 否则在客户端将抛出NoClassDefFoundError异常, 而掩盖了真实的异常信息

10) 让日志易读,易解析

对日志感兴趣的可以分为两类:

• 人(比如程序员)
• 机器(系统管理员写的shell脚本)

日志的内容必须照顾到这两个群体. 引用鲍勃大叔"Clean Code(http://www.amazon.com/Clean-Code-Handbook-Software-Craftsmanship/dp/0132350882)"一书的话来说:日志应该像代码一样可读并且容易理解.

另一方面, 如果一个系统每小时要输出几百MB甚至上G的日志, 那么我们需要借助grep, sed以及awk来分析日志. 如果可能, 我们应该让日志尽可能的被人和机器理解. 比如, 避免格式化数字, 使用日志模式则可以方便用正则表达式进行识别. 如果无法兼顾, 那么可以将数据用两种格式输出, 比如像下面这样:

log.debug("Request TTL set to: {} ({})", new Date(ttl), ttl);
// Request TTL set to: Wed Apr 28 20:14:12 CEST 2010 (1272478452437)

final String duration = DurationFormatUtils.formatDurationWords(durationMillis, true, true);
log.info("Importing took: {}ms ({})", durationMillis, duration);
//Importing took: 123456789ms (1 day 10 hours 17 minutes 36 seconds)

上面的日志, 既照顾了计算机("ms after 1970 epoch"这种时间格式), 又能更好的让人能理解("1 day 10 hours 17 minutes 36 seconds") . 另外, 这里顺便广告一下DurationFormatUtils(http://commons.apache.org/lang/api-release/org/apache/commons/lang/time/DateFormatUtils.html), 一个非常不错的工具:)