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

このように書くと冗長になるだけでなく、可読性は低く、stringのスプライシングは効率に影響します（このレベルで出力が必要ない場合）。

slf4j では {} インジェクション機能が導入されており、毎回文字列の連結が回避されるため、toString メソッドは呼び出されず、isDebugEnabled は不要になります。

slf4j は外観モードのアプリケーションであり、単なるファサードです。具体的な実装については、すでに完成した log4j ではなく、以前に一度宣伝した logback フレームワークをお勧めします。これには多くの興味深い機能があり、log4j とは異なり、現在も開発と改良が活発に行われています。

もう 1 つの推奨ツールは perf4j です。

log4j が System.out.println() に対してあるのと同じように、Perf4J は System.currentTimeMillis() に対して使用されます

log4j が System.out.println のより良いバージョンであるのと同じです。同様に、perf4j は System.currentTimeMillis() の代替に似ています。

プロジェクトに perf4j を導入し、高負荷時のパフォーマンスを観察しました。管理者もビジネス ユーザーも同様に、このガジェットが提供する美しいグラフに驚かされます。

いつでもパフォーマンスの問題を確認できます。現時点では、perf4j に関する専用の記事があるはずです。まずは開発者ガイドを読んでください。

また、Ceki Gülcü (log4j、slf4j、logback プロジェクトの作成者) は、commons-logging への依存関係を削除する簡単な方法を提供しています。

ログ レベルを忘れないでください

ログ行を追加するたびに、ここでどのログ レベルを使用するべきか考えるでしょう。プログラマの約 90% はこの問題にあまり注意を払っていませんが、彼らは皆、ログの記録に 1 つのレベル (通常は INFO または DEBUG) を使用しています。なぜ？

ログ フレームワークには、System.out と比較して、分類とレベルという 2 つの大きな利点があります。どちらの方法でも、永続的に、またはトラブルシューティングの場合にのみ、ログを選択的にフィルタリングできます。

• エラー 重大なエラーが発生したため、直ちに対処する必要があります。このレベルのエラーは、どのシステムでも許容できません。例: Null ポインター例外、データベースが使用不可、クリティカル パスのユースケースは実行を続行できません。

• WARN は引き続き以下のプロセスを実行しますが、真剣に受け止める必要があります。実際、ここには 2 つのレベルがあることを望みます。1 つは解決策に関する明らかな問題 (たとえば、「現在のデータは利用できません。キャッシュされたデータを使用してください」)、もう 1 つは潜在的な問題と提案 (「プログラムは開発モードで実行されます」または「管理コンソールのパスワードは十分に安全ではありません」)。アプリケーションはこれらのメッセージを許容できますが、チェックして修復する必要があります。

• DEBUG 開発者の懸念事項。このレベルでどのようなものを記録すればよいかについては後ほどお話します。

• TRACE より詳細な情報は開発段階でのみ使用されます。製品の発売後もしばらくはこの情報に注意する必要があるかもしれませんが、これらのログ記録は一時的なものにすぎず、最終的にはオフにする必要があります。 DEBUG と TRACE の違いは区別しにくいですが、ログの行を追加し、開発とテスト後に削除した場合、ログは TRACE レベルになるはずです。

上記のリストは単なる提案であり、独自のルールに従ってログを記録できますが、特定のルールを設けることが最善です。私の個人的な経験では、コード レベルでログをフィルタリングするのではなく、正しいログ レベルを使用して必要な情報をすばやくフィルタリングすることで、時間を大幅に節約できます。

最後に話したいのは、悪名高い is*Enabled 条件文です。各ログの前にこれを追加することを好む人もいます:

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

個人的には、これはコードでは避けるべきだと思います。パフォーマンスの向上は見られず (特に slf4j を使用した後)、時期尚早の最適化のようです。また、これは少し冗長であることに気づきませんか?ログ メッセージの作成自体にコストがかかりすぎることが証明されない限り、そのような明示的な判断ステートメントが明確に必要になることはほとんどありません。それ以外の場合は、必要なことをすべて覚えて、ロギング フレームワークに任せてください。 何を録音しているか知っていますか?

ログ行を書き込むたびに、ログ ファイルに正確に何が出力されたかを確認してください。ログを読んで異常を探します。まず、少なくとも null ポインター例外を回避します。

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 中国語 Web サイトの他の関連記事を参照してください。