如何使用Java日志来写诗的具体介绍

工欲善其事，必先利其器

很多程序员可能都忘了记录应用程序的行为是一件多么重要的事，当遇到多线程环境下高压力导致的并发bug时，你就能体会到记录log的重要性。

有的人很高兴的就在代码里加上了这么句：

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

他可能都没有意识到应用程序的日志在维护，调优和故障识别中的重要性。

我认为slf4j是最好的日志API，最主要是因为它支持一个很棒的模式注入的方式：

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

log4j的话你只能这样：

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

这样写不仅更啰嗦和可读性差，而且字符串拼接影响效率（当这个级别并不需要输出的时候）。

slf4j引入了{}注入特性，并且由于避免了每次都进行字符串拼接，toString方法不会被调用，也不再需要加上isDebugEnabled了。

slf4j是外观模式的一种应用，它只是一个门面。具体实现的话我推荐logback框架，之前已经做过一次广告了，而不是已经很完备的log4j。它有许多很有意思的特性，和log4j不同的是，它还在积极的开发完善中。

还有一个要推荐的工具是perf4j：

Perf4J is to System.currentTimeMillis() as log4j is to System.out.println()

就好比log4j是System.out.println的一种更好的替换方式一样，perf4j更像是System.currentTimeMillis()的替代。

我已经在一个项目中引入了perf4j，并在高负载的情况下观察它的表现。管理员和企业用户都被这个小工具提供的漂亮的图表惊呆了。

我们可以随时查看性能问题。perf4j应该专门开一篇文章来讲，现在的话可以先看下它的开发者指南。

还有一个Ceki Gülcü（log4j,slf4j和logback工程的创建者）提供了一个简单的方法供我们移除对commons-logging的依赖。

不要忘了日志级别

每次你要加一行日志的时候，你都会想，这里该用哪种日志级别？大概有90%的程序员都不太注意这个问题，都是用一个级别来记录日志，通常不是INFO就是DEBUG。为什么？

日志框架和System.out相比有两大优势：分类和级别。两者可以让你可以选择性的过滤日志，永久的或者只是在排查错误的时候。

• ERROR 发生了严重的错误，必须马上处理。这种级别的错误是任何系统都无法容忍的。比如：空指针异常，数据库不可用，关键路径的用例无法继续执行。

• WARN 还会继续执行后面的流程，但应该引起重视。其实在这里我希望有两种级别：一个是存在解决方案的明显的问题（比如，”当前数据不可用，使用缓存数据”），另一个是潜在的问题和建议（比如“程序运行在开发模式下”或者“管理控制台的密码不够安全”）。应用程序可以容忍这些信息，不过它们应该被检查及修复。

• DEBUG 开发人员关注的事。后面我会讲到什么样的东西应该记录到这个级别。

• TRACE 更为详尽的信息，只是开发阶段使用。在产品上线之后的一小段时间内你可能还需要关注下这些信息，不过这些日志记录只是临时性的，最终应该关掉。DEBUG和TRACE的区别很难区分，不过如果你加了一行日志，在开发测试完后又删了它的话，这条日志就应该是TRACE级别的。

上面的列表只是一个建议，你可以根据自己的规则来记录日志，但最好要有一定的规则。我个人的经验是：在代码层面不要进行日志过滤，而是用正确的日志级别能够快速的过滤出想要的信息，这样能节省你很多时间。

最后要说的就是这个臭名昭著的is*Enabled的条件语句了。有的人喜欢把每次日志前加上这个：

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

个人认为，应该避免在代码里加入这个乱哄哄的东西。性能看起来没有什么提升（尤其是用了slf4j之后）,更像是过早的优化。还有，没发现这么做有点多余么？很少有时候是明确需要这种显式的判断语句的，除非我们证明构造日志消息本身开销太大。不然的话，该怎么记就怎么记，让日志框架去操心这个吧。

你清楚你在记录什么吗？

每次你写下一行日志，花点时间看看你到底在日志文件里打印了些什么。读一遍你的日志，找出异常的地方。首先，至少要避免空指针异常：

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

你确认过request不是null了吗？

记录集合也是一个大坑。如果你用Hibernate从数据库里获取领域对象的集合的时候,不小心写成了这样：

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

slf4j只会在这条语句确实会打印的时候调用toString方法，当然这个很酷。不过如果内存溢出了，N+1选择问题，线程饿死，延迟初始化异常，日志存储空间用完了…这些都有可能发生。

最好的方式是只记录对象的ID（或者只记录集合的大小）。不过收集ID需要对每个对象调用getId方法，这个在Java里可真不是件简单的事。Groovy有个很棒的展开操作符（users*.id）,在Java里我们可以用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));
}

最后要说的是，toString方法可能没有正确的实现或者使用。

首先，为了记录日志，为每个类创建一个toString的做法比比皆是，最好用 ToStringBuilder来生成（不过不是它的反射实现的那个版本）。

第二，注意数组和非典型的集合。数组和一些另类的集合的toString实现可能没有挨个调用每个元素的toString方法。可以使用JDK提供的Arrays#deepToString方法。经常检查一下你自己打印的日志，看有没有格式异常的一些信息。

避免副作用

日志打印一般对程序的性能没有太大影响。最近我一个朋友在一些特殊的平台上运行的一个系统抛出了Hibernate的LazyInitializationException异常。你可能从这已经猜到了，当会话连接进来的时候，一些日志打印导致延迟初始化的集合被加载。在这种情况下，把日志级别提高了，集合也就不再被初始化了。如果你不知道这些上下文信息，你得花多长时间来发现这个BUG。

另一个副作用就是影响程序的运行速度。快速回答一下这个问题：如果日志打印的过多或者没有正确的使用toString和字符串拼接，日志打印就会对性能产生负面影响。能有多大？好吧，我曾经见过一个程序每15分钟就重启一次，因为太多的日志导致的线程饿死。这就是副作用！从我的经验来看，一小时打印百来兆差不多就是上限了。

当然如果由于日志打印异常导致的业务进程中止，这个副作用就大了。我经常见到有人为了避免这个而这么写：

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

这是段真实的代码，但是为了让世界清净点，请不要这么写。

描述要清晰

每个日志记录都会包含数据和描述。看下这个例子：

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");

在这个警告日志里加上消息类型，消息ID等等这些难道很困难吗？我是知道发生错误了，不过到底是什么错误？上下文信息是什么？

第三个反面例子是“魔法日志”。一个真实的例子：团队里的很多程序员都知道，3个&号后面跟着！号再跟着一个#号，再跟着一个伪随机数的日志意味着”ID为XYZ的消息收到了”。没人愿意改这个日志，某人敲下键盘，选中某个唯一的”&&&!#”字符串，他就能很快找到想要的信息。

结果是，整个日志文件看起来像一大串随机字符。有人不禁会怀疑这是不是一个perl程序。

日志文件应当是可读性强的，清晰的，自描述的。不要用一些魔数，记录值，数字，ID还有它们的上下文。记录处理的数据以及它的含义。记录程序正在干些什么。好的日志应该是程序代码的一份好的文档。

我有提过不要打印密码还有个人信息吗？相信没有这么傻的程序员。

调整你的格式

日志格式是个很有用的工具，无形中在日志添加了很有价值的上下文信息。不过你应该想清楚，在你的格式中包含什么样的信息。比如说，在每小时循环写入的日志中记录日期是没有意义的，因为你的日志名就已经包含了这个信息。相反的，如果你没记录线程名的话当两个线程并行的工作的时候，你就无法通过日志跟踪线程了——日志已经重叠到一起了。在单线程的应用程序中，这样做没问题，不过那个已经是过去的事儿了。

从我的经验来看，理想的日志格式应当包括（当然除了日志信息本身了）：当前时间（无日期，毫秒级精度），日志级别，线程名，简单的日志名称（不用全称）还有消息。在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(“”);
因为程序员认为行号会作为日志格式的一部分，并且他知道如果空日志消息出现在这个文件的67行的话，意味着这个用户是认证过的。不仅这样，记录类名方法名，或者行号对性能都有很大的影响。

日志框架的一个比较高级的特性是诊断上下文映射（Mapped Diagnostic Context）。MDC只是一个线程本地的一个map。你可以把任何键值对放到这个map里，这样的话这个线程的所有日志记录都能从这个map里取到相应的信息作为输出格式的一部分。

记录方法的参数和返回值

如果你在开发阶段发现了一个BUG，你通常会用调试器来跟踪具体的原因。现在假设不让你用调试器了，比如，因为这个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;
}

由于你在方法的开始和结束都记录了日志，所以你可以人工找出效率不高的代码，甚至还可以检测到可能会引起死锁和饥饿的诱因——你只需看一下“Entering”后面是不是没有”Leaving“就明白了。如果你的方法名的含义很清晰，清日志将是一件愉快的事情。同样的，分析异常也更得更简单了，因为你知道每一步都在干些什么。代码里要记录的方法很多的话，可以用AOP切面来完成。这样减少了重复的代码，不过使用它得特别小心，不注意的话可能会导致输出大量的日志。

这种日志最合适的级别就是DEBUG和TRACE了。如果你发现某个方法调用 的太频繁，记录它的日志可能会影响性能的话，只需要调低它的日志级别就可以了，或者把日志直接删了（或者整个方法调用只留一个？）不过日志多了总比少了要强。把日志记录当成单元测试来看，你的代码应该布满了日志就像它的单元测试到处都是一样。系统没有任何一部分是完全不需要日志的。记住，有时候要知道你的系统是不是正常工作，你只能查看不断刷屏的日志。

观察外部系统

这条建议和前面的有些不同：如果你和一个外部系统通信的话，记得记录下你的系统传出和读入的数据。系统集成是一件苦差事，而诊断两个应用间的问题(想像下不同的公司，环境，技术团队）尤其困难。最近我们发现记录完整的消息内容，包括Apache CXF的SOAP和HTTP头，在系统的集成和测试阶段非常有效。

这样做开销很大，如果影响到了性能的话，你只能把日志关了。不过这样你的系统可能跑的很快，挂的也很快，你还无能为力？当和外部系统进行集成的时候，你只能格外小心并做好牺牲一定开销的准备。如果你运气够好，系统集成由ESB处理了，那在总线把请求和响应给记录下来就最好不过了。可以参考下Mule的这个日志组件。

有时候和外部系统交换的数据量决定了你不可能什么都记下来。另一方面，在测试阶段和发布初期，最好把所有东西都记到日志里，做好牺牲性能的准备。可以通过调整日志级别来完成这个。看下下面这个小技巧：

Collection<Integer> requestIds = //...
if(log.isDebugEnabled())
    log.debug("Processing ids: {}", requestIds);
else
    log.info("Processing ids size: {}", requestIds.size());

如果这个logger是配置成DEBUG级别，它会打印完整的请求ID的集合。如果它配置成了打印INFO信息的话，就只会输出集合的大小。你可能会问我是不是忘了isInfoEnabled条件了，看下第二点建议吧。这里还有一个值得注意的是ID的集合不能为null。尽管在DEBUG下，它为NULL也能正常打印，但是当配置成INFO的时候一个大大的空指针。还记得第4点建议中提到的副作用吧？

正确的记录异常

首先，不要记录异常，让框架或者容器来干这个。当然有一个例外：如果你从远程服务中抛出了异常（RMI，EJB等），异常会被序列化，确保它们能返回给客户端 （API中的一部分）。不然的话，客户端会收到NoClassDefFoundError或者别的古怪的异常，而不是真正的错误信息。

异常记录是日志记录的最重要的职责之一，不过很多程序员都倾向于把记录日志当作处理异常的方式。他们通常只是返回默认值（一般是null,0或者空字符串），装作什么也没发生一样。还有的时候，他们会先记录异常，然后把异常包装了下再抛出去：

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

这样写通常会把栈信息打印两次，因为捕获了MyCustomException异常的地方也会再打印一次。日志记录，或者包装后再抛出去，不要同时使用，否则你的日志看起来会让人很迷惑。

如果我们真的想记录日志呢？由于某些原因（大概是不读API和文档？），大约有一半的日志记录我认为是错误的。做个小测试，下面哪个日志语句能够正确的打印空指针异常？

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下面根本就编译不过，其它的会把栈跟踪信息给丢掉了或者打印了不正确的信息。比如，E什么也不打印，因为空指针异常本身没有提供任何异常信息而栈信息又没打印出来 .记住，第一个参数通常都是文本信息，关于这个错误本身的。不要把异常信息给写进来，打印日志后它会自动出来的，在栈信息的前面。不过想要打印这个，你当然还得把异常传到第二个参数里面才行。

日志应当可读性强且易于解析

现在有两组用户对你的日志感兴趣：我们人类（不管你同不同意，码农也是在这里边），还有计算机（通常就是系统管理员写的shell脚本）。日志应当适合这两种用户来理解。如果有人在你后边看你的程序的日志却看到了这个：

那你肯定没听从我的建议。日志应该像代码一样易于阅读和理解。

另一方面，如果你的程序每小时就生成了半GB的日志，没有谁或者任何图形化的文本编辑器能把它们看完。这时候我们的老家伙们，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天10小时17分36秒“这样的东西。

总之，日志也可以写得像诗一样优雅，如果你愿意琢磨的话。

Atas ialah kandungan terperinci 如何使用Java日志来写诗的具体介绍. Untuk maklumat lanjut, sila ikut artikel berkaitan lain di laman web China PHP!