Java 로그를 사용하여 시를 작성하는 방법에 대한 자세한 소개

일을 잘하려면 먼저 도구를 갈고닦아야 합니다

많은 프로그래머는 동시성 버그가 발생했을 때 애플리케이션의 동작을 기록하는 것이 얼마나 중요한지 잊어버렸을 것입니다. 스레드 환경의 높은 압력으로 인해 발생하는 로그 기록의 중요성을 실감할 수 있습니다.

어떤 사람들은 다음 문장을 코드에 기꺼이 추가했습니다.

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는 외관 모드의 애플리케이션이며 단지 외관일 뿐입니다. 구체적인 구현을 위해서는 이미 완성된 log4j 대신 이전에 한 번 광고되었던 logback 프레임워크를 권장합니다. 흥미로운 기능이 많이 있으며 log4j와 달리 아직 개발 및 개선이 활발하게 진행되고 있습니다.

권장할 또 다른 도구는 perf4j입니다.

Perf4J는 System.currentTimeMillis()에 대한 것이고 log4j는 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 심각한 오류가 발생했으며 즉시 처리해야 합니다. 이 수준의 오류는 어떤 시스템에서도 허용될 수 없습니다. 예: Null 포인터 예외, 데이터베이스를 사용할 수 없으며 중요 경로의 사용 사례를 계속 실행할 수 없습니다.

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

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

위 내용은 Java 로그를 사용하여 시를 작성하는 방법에 대한 자세한 소개의 상세 내용입니다. 자세한 내용은 PHP 중국어 웹사이트의 기타 관련 기사를 참조하세요!