A detailed introduction to how to use Java logs to write poetry

If you want to do your job well, you must first sharpen your tools

Many programmers may have forgotten how important it is to record the behavior of the application. When encountering multiple When concurrency bugs are caused by high pressure in a thread environment, you can realize the importance of recording logs.

Some people are happy to add this sentence to the code:

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

He may not realize the importance of application logs in maintenance, tuning and fault identification. .

I think slf4j is the best logAPI, mainly because it supports a great way of pattern injection:

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

log4j## If #, you can only do this:

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

Writing like this is not only more verbose and less readable, but

string splicing affects efficiency (when output is not required at this level).

slf4j introduces the {} injection feature, and since string splicing is avoided every time, the toString method will not be called, and isDebugEnabled is no longer needed.

slf4j is an application of appearance mode, it is just a facade. For specific implementation, I recommend the logback framework, which has been advertised once before, instead of the already complete log4j. It has many interesting features, and unlike log4j, it is still under active development and improvement.

Another tool to recommend is perf4j:

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

Just like log4j is a better replacement for System.out.println, perf4j is more like a replacement for System.currentTimeMillis().

I have introduced perf4j in a project and observed its performance under high load. Administrators and business users alike are stunned by the beautiful charts provided by this gadget.

We can view performance issues at any time. There should be a dedicated article on perf4j. For now, you can read its developer guide first.

Also Ceki Gülcü (creator of the log4j, slf4j and logback projects) provides a simple way for us to remove our dependence on commons-logging.

Don’t forget the log level

Every time you want to add a line of log, you will think, which log level should be used here? About 90% of programmers don't pay much attention to this problem and all use one level to record logs, usually either INFO or DEBUG. Why?

The log framework has two major advantages over System.out: classification and level. Both allow you to selectively filter logs, permanently or just when troubleshooting.

• ERROR A serious error has occurred and must be handled immediately. This level of error cannot be tolerated by any system. For example: Null pointer exception, the database is unavailable, and use cases on the critical path cannot continue to execute.

• WARN will continue to execute the subsequent process, but it should be taken seriously. In fact, I hope there are two levels here: one is obvious problems with solutions (for example, "The current data is not available, use

  cached data"), and the other is potential problems and suggestions (such as "The program is running in development mode" or "The password for the management console is not secure enough"). Applications can tolerate these messages, but they should be checked and repaired.

• DEBUG Developer concerns. I will talk about what kind of things should be recorded at this level later.

• TRACE More detailed information is only used during the development phase. You may still need to pay attention to this information for a short period of time after the product is launched, but these log records are only temporary and should eventually be turned off. The difference between DEBUG and TRACE is difficult to distinguish, but if you add a line of log and then delete it after development and testing, the log should be of TRACE level.

The above list is just a suggestion. You can record logs according to your own rules, but it is best to have certain rules. My personal experience is: do not filter logs at the code level, but use the correct log level to quickly filter out the desired information, which can save you a lot of time.

The last thing I want to say is the infamous is*Enabled conditional statement. Some people like to add this before each log:

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

Personally, I think that adding this messy stuff to the code should be avoided. There seems to be no performance improvement (especially after using slf4j), more like premature optimization. Also, don’t you realize that this is a bit redundant? Rarely is there a clear need for such an explicit

judgment statement, unless we prove that constructing the log message itself is too expensive. Otherwise, just remember whatever you want and let the logging framework take care of this.

Do you know what you are recording?

Every time you write a log line, take a moment to see what exactly you print in the log file. Read through your logs and look for any anomalies. First, at least avoid null pointer exceptions:

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秒“这样的东西。

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

The above is the detailed content of A detailed introduction to how to use Java logs to write poetry. For more information, please follow other related articles on the PHP Chinese website!