正确记录应用程序的10个技巧

最新推荐文章于 2024-09-14 22:07:12 发布

danpu0978

最新推荐文章于 2024-09-14 22:07:12 发布

阅读量367

点赞数

文章标签：大数据编程语言数据库 python linux

我们最新的JCP合作伙伴 Tomasz Nurkiewicz已提交了许多帖子，描述了正确应用程序日志记录的基本原理。我发现它们非常有趣，因此我决定将它们汇总为更紧凑的格式，然后将其呈现给您。因此，以下是他关于干净实用的日志的建议：（注意：对原始帖子进行了略微编辑以提高可读性）

1）使用适当的工具进行工作

许多程序员似乎忘记了记录应用程序的行为及其当前活动的重要性。当有人提出：

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

很高兴在代码中的某处，他可能没有意识到维护，调整和故障识别期间应用程序日志的重要性。低估好原木的价值是一个可怕的错误。

在我看来，SLF4J是可用的最佳日志记录API，主要是因为它提供了强大的模式替换支持：

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

在Log4j中，您将必须使用：

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

这不仅较长且可读性较差，而且由于广泛使用字符串连接而导致效率低下。 SLF4J添加了一个不错的{}替换功能。另外，由于避免了字符串连接，并且如果过滤了日志记录语句，则不会调用toString（），因此不再需要isDebugEnabled（）。顺便说一句，您是否注意到过滤器字符串参数周围的单引号？

SLF4J只是一个外观。作为一种实现，我将推荐已经发布的Logback框架，而不是完善的Log4J 。它具有许多有趣的功能，并且与 Log4J 相反，它是积极开发的。

最后推荐的工具是Perf4J 。引用他们的座右铭：

Perf4J到System.currentTimeMillis（），而log4j到System.out.println（）

我已经将Perf4J添加到一个负载较重的现有应用程序中，并在其他几个应用程序中看到了它的实际效果。这个简单的工具产生的漂亮图表给管理员和企业用户都留下了深刻的印象。而且，我们能够立即发现性能缺陷。 Perf4J本身值得拥有自己的文章，但现在只需查看其开发人员指南。

另外，请注意CekiGülcü （ Log4J ， SLF4J和Logback项目的创始人）建议了一种简单的方法来摆脱公共记录依赖（请参阅他的评论）。

2）别忘了，您可以找到记录级别

每次做出日志记录语句时，您都会认真思考哪种日志记录级别适合此类事件，不是吗？不知何故，有90％的程序员从不关注日志记录级别，仅将所有内容记录在同一级别上，通常是INFO或DEBUG。为什么？与System.out。相比，日志记录框架有两个主要优点，即类别和级别。两者都允许您有选择地永久性地或仅在诊断时间内选择性地过滤日志记录语句。如果您真的看不到差异，请在每次开始输入“ log”时打印此表并查看。在您的IDE中：

错误 –发生了非常严重的错误，必须立即进行调查。没有系统可以容忍在此级别上记录的项目。例如：NPE，数据库不可用，关键任务用例无法继续。

警告 –该过程可能会继续，但要格外小心。实际上，我一直希望在这里拥有两个级别：一个针对存在变通办法的明显问题（例如：“当前数据不可用，使用缓存的值”），第二个针对潜在的问题和建议（将其命名为ATTENTION）。示例：“在开发模式下运行的应用程序”或“使用密码无法保护管理控制台”。该应用程序可以容忍警告消息，但是应该始终对警告消息进行论证和检查。

信息 –重要的业务流程已完成。在理想情况下，管理员或高级用户应该能够理解INFO消息并快速找出应用程序在做什么。例如，如果某个应用程序只涉及机票预订，则每张机票应该只有一个INFO语句，上面写着“ [谁]预订了从[哪里]到[哪里]的机票”。 INFO消息的其他定义：显着更改应用程序状态的每个操作（数据库更新，外部系统请求）。

调试 -开发人员资料。稍后我将讨论什么样的信息值得记录。

跟踪 –非常详细的信息，仅用于开发。在生产环境上部署之后，您可能会在很短的时间内保留跟踪消息，但是将这些日志语句视为临时日志，最终应该或可能将其关闭。 DEBUG和TRACE之间的区别是最困难的，但是如果您在开发和测试该功能后放入日志记录语句并将其删除，则它可能应该处于TRACE级别。

上面的列表只是一个建议，您可以创建自己的一组说明要遵循，但是有一些说明很重要。我的经验是，所有情况下都始终在不进行过滤的情况下记录下来（至少从应用程序代码中进行记录），但是具有快速过滤日志并以适当的详细程度提取信息的能力可能会节省生命。

最后值得一提的是臭名昭著的is * Enabled（）条件。有些人把它放在每个日志记录语句之前：

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

就我个人而言，我发现这种习惯用法只是混乱，应该避免。性能改进（尤其是使用前面讨论的SLF4J模式替换时）似乎无关紧要，并且闻起来像是过早的优化。另外，您能发现重复吗？在极少数情况下，有明确的条件是合理的–当我们可以证明构造日志消息的代价很高时。在其他情况下，只需完成日志记录的工作，然后让日志记录框架完成其工作（过滤）即可。

3）您知道要记录什么吗？

每次发出日志记录语句时，请花点时间查看一下日志文件中将确切显示的内容。之后阅读您的日志，并找出格式错误的句子。首先，避免这样的NPE：

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

您绝对确定此请求不是null吗？

另一个陷阱是记录收集。如果您使用Hibernate从数据库中获取了域对象的集合，并且像下面这样粗心地记录了它们：

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

SLF4J仅在实际打印语句时才调用toString（），这非常好。但是，如果确实发生了…内存不足错误， N + 1选择问题，线程饥饿（日志记录是同步的！），延迟初始化异常，日志存储空间已完全填充–可能会发生每种情况。

例如，最好只记录域对象的ID（甚至只记录集合的大小）。但是在Java中，当具有对象的集合具有getId（）方法时进行id的集合是令人难以置信的困难和麻烦。 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（）。使用数组#deepToString JDK实用程序方法。并经常阅读日志以发现格式错误的邮件。

4）避免副作用

记录语句应该对应用程序的行为没有影响或影响很小。最近，我的一个朋友举了一个系统示例，该系统仅在某些特定环境上运行时才抛出Hibernates的LazyInitializationException。正如您可能从上下文中猜到的那样，当附加会话时，某些日志记录语句会导致延迟初始化的集合被加载。在这种环境下，日志记录级别增加了，并且收集不再被初始化。想想您不知道此上下文会花多长时间找到错误？

另一个副作用是使应用程序变慢。快速答案：如果您记录太多或不正确地使用toString（）和/或字符串连接，则记录会对性能产生负面影响。多大？好吧，我看到由于过多的日志记录导致线程不足，服务器每15分钟重新启动一次。现在这是一个副作用！根据我的经验，几百个MiB可能是每小时可以登录到磁盘的最大数量的上限。

当然，如果日志记录语句本身失败并导致业务流程由于异常而终止，那么这也是一个巨大的副作用。我已经看到了避免这种情况的结构：

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

在警告字符串中包含实际的消息类型，消息ID等是否很难？我知道出了点问题，但是呢？背景是什么？

第三个反模式是“魔术对数”。真实示例：团队中的大多数程序员都知道3个＆字符，后跟一个感叹号，然后是哈希，然后是伪随机字母数字字符串日志，表示“收到了带有XYZ ID的消息”。没有人愿意更改日志，只需有人按键盘并选择一些唯一的“ &&！＃”字符串，以便他自己可以轻松找到它。

结果，整个日志文件看起来像是随机字符序列。甚至有人会认为该文件是有效的Perl程序。取而代之的是，日志文件应可读，干净且具有描述性。不要使用幻数，对数值，数字，ID并包括其上下文。显示正在处理的数据并显示其含义。显示程序实际上在做什么。良好的日志可以很好地记录应用程序代码本身。

我是否提到不记录密码和任何个人信息？别！

6）调整图案

日志记录模式是一个很棒的工具，可以透明地为您创建的每个日志记录语句添加有意义的上下文。但是您必须非常仔细地考虑要在模式中包括哪些信息。例如，日志每小时滚动一次的日志日期是没有意义的，因为日志文件名中已经包含该日期。相反，如果不记录线程名称，则当两个线程同时工作时，您将无法使用日志来跟踪任何进程-日志将重叠。在单线程应用程序中这可能很好-如今几乎已死。

根据我的经验，理想的日志记录模式应包括（当然，除了日志消息本身）：当前时间（无日期，毫秒精度），日志记录级别，线程名称，简单的日志记录器名称（不完全限定）和消息。在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行中出现空的日志记录消息（在authenticate（）方法中，则表明该用户已通过身份验证”）。此外，记录类名称，方法名称和/或行号会对性能产生严重影响。

日志记录框架的一个更高级的功能是“映射诊断上下文”的概念。 MDC只是基于线程本地管理的映射。您可以在该映射中放置任何键-值对，此后从该线程发出的每个日志记录语句都将将此值作为模式的一部分附加。

7）记录方法参数和返回值

当您在开发过程中发现错误时，通常会运行调试器以尝试找出潜在原因。现在想象一下，您不能使用调试器。例如，由于错误是几天前在客户环境中显现出来的，因此您拥有的只是日志。您能在其中找到任何东西吗？

如果遵循记录每个方法的输入和输出（参数和返回值）的简单规则，那么您甚至不需要调试器。当然，您必须是理性的，但是应该考虑以下各种方法：访问外部系统（包括数据库），阻止，等待等。只需遵循以下模式：

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;
}

因为您同时记录了方法调用的开始和结束，所以您可以手动发现效率低下的代码，甚至检测死锁和饥饿的可能原因，只需照顾“输入”而无需相应的“离开”即可。如果您的方法具有有意义的名称，则很高兴阅读日志。同样，分析出了什么问题也很简单，因为在每一步您都可以准确地知道已经处理了什么。您甚至可以使用简单的AOP方面在代码中记录各种方法。这样可以减少代码重复，但是要小心，因为它可能导致大量的大量日志。

您应该将DEBUG或TRACE级别视为最适合这些类型的日志。而且，如果您发现某个方法的调用次数过多，并且日志记录可能会损害性能，则只需降低该类的日志记录级别或完全删除日志（也许只为整个方法调用留一个日志即可）。但是，拥有太多而不是总是更好的做法日志记录语句太少。以与单元测试相同的方式对待日志记录语句–与单元测试一样，您的代码应包含在日志记录例程中。系统的任何部分都不应保留任何日志。请记住，有时观察日志滚动是判断应用程序是否正常运行或永久挂起的唯一方法。

8）当心外部系统

这是上一个技巧的特殊情况：如果您与外部系统进行通信，请考虑记录来自应用程序的所有数据并进入。集成是一项艰巨的工作，要诊断两个应用程序之间的问题（认为两个不同的供应商，环境，技术堆栈和团队）特别困难。例如，最近，我们发现在集成和系统测试期间，在Apache CXF Web服务中记录完整的消息内容（包括 SOAP和HTTP标头）非常有用。

这是很大的开销，如果性能成为问题，则可以始终禁用日志记录。但是，拥有一个快速但又破烂的应用程序，没有人能解决的意义是什么？与外部系统集成时要格外小心，并准备支付该费用。如果您很幸运，并且所有集成都由ESB处理，那么总线可能是记录每个传入请求和响应的最佳位置。参见例如Mule的log-component 。

有时，与外部系统交换的信息量很大，无法记录所有内容。另一方面，在测试期间和短时间内的生产中（例如，当发生问题时），我们希望将所有内容保存在日志中并准备支付性能成本。这可以通过仔细使用日志记录级别来实现。请看以下成语：

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

如果此特定的记录器配置为记录DEBUG消息，它将打印整个requestIds集合内容。但是，如果将其配置为打印INFO消息，则仅输出集合的大小。如果您想知道为什么我忘记了isInfoEnabled（）条件，请回到技巧2。值得一提的是，在这种情况下，requestIds集合不应为null。尽管如果启用了DEBUG，它将被正确记录为null，但是，如果将记录器配置为INFO，则会抛出大的NullPointerException异常。还记得技巧4中关于副作用的课程吗？

9）正确记录异常

首先，避免记录异常，让您的框架或容器（无论它是什么）为您完成。这个规则有一个例外，如果您从某个可以序列化例外的远程服务（RMI，EJB远程会话bean等）抛出例外，请确保所有这些例外都可用于客户端（ API的一部分）。否则，客户端将收到NoClassDefFoundError：SomeFancyException而不是“ true”错误。

记录异常是所有记录中最重要的角色之一，但是许多程序员倾向于将记录视为处理异常的一种方式。他们有时返回默认值（通常为null，0或空字符串），并假装什么都没有发生。其他时候，他们首先记录异常，然后将其包装并抛出：

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

这个构造几乎总是会打印两次相同的堆栈跟踪记录，因为某些东西最终会捕获MyCustomException并记录其原因。记录日志，或包装回去（最好），不要两者都记录，否则您的日志会造成混乱。

但是，如果我们真的想记录异常吗？由于某种原因（因为我们不阅读API和文档？），我看到的日志记录语句中大约有一半是错误的。快速测验，以下哪个日志语句将正确记录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中编译，其他人则丢弃了堆栈跟踪和/或打印了不正确的消息。例如，E将不打印任何内容，因为NPE通常不提供任何异常消息，并且也不会打印堆栈跟踪。请记住，第一个参数始终是文本消息，请写一些有关问题性质的信息。不要包括异常消息，因为它将在日志语句之后，堆栈跟踪之前自动打印。但是，为此，您必须将异常本身作为第二个参数传递。

10）日志易于阅读，易于解析

有两类接收器对您的应用程序日志特别感兴趣：人类（您可能会不同意，但程序员也属于该类）和计算机（通常是由系统管理员编写的shell脚本）。日志应适合这两个组。如果有人从背后查看您的应用程序日志，发现（来源Wikipedia）：

那么您可能没有遵循我的提示。日志应该可读易懂，就像代码一样。

另一方面，如果您的应用程序每小时产生半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)

计算机将欣赏“ 1970年以后的毫秒”时间格式，而人们会很高兴看到“ 1天10小时17分36秒”的文本。顺便说一句，看一看DurationFormatUtils ，很好的工具。

伙计们，我们的JCP合作伙伴 Tomasz Nurkiewicz提供了“日志记录技巧”。别忘了分享！

相关文章：