将对debug()的调用封装在if isDebugEnabled()中,这是一个好的策略吗?

28

我们团队的政策是像这样进行日志记录:

if (LOGGER.isDebugEnabled()) {  
  LOGGER.debug("model[" + model + "]");
}

不是像这样简单地调用日志记录方法:

LOGGER.debug("model[" + model + "]");

这种做法能够带来一些性能改进,但另一方面它也使代码库更加复杂。 我们的应用程序没有性能问题,而且很可能永远不会出现,引入该策略的论点仅仅是因为它是一个好的实践,所以每次进行日志记录时都应该使用它。

您认为这是一个好的策略吗?

7个回答

28

你应该使用SLF4J并将log4j作为其实现。通过SLF4J,您可以通过使用带参数的消息完全消除isDebugEnabled()

请参见slf4j FAQ中关于日志记录性能的部分

以下两行代码将生成完全相同的输出。但是,在禁用日志记录语句的情况下,第二种形式的性能将至少比第一种形式提高30倍。

logger.debug("The new entry is " + entry + ".");

logger.debug("The new entry is {}.", entry);


8
当参数构建entry是昂贵的时候,字符串格式化无法提供帮助。例如,考虑一些类似于logger.debug("The new entry is {}.", getEntry());的代码,你不知道getEntry()方法需要花费多少成本。 - xmedeko

18

对于那些构建日志字符串会显著影响性能的情况,这是一个很好的策略。原因可能有两个:

  • 需要大量的工作来构建字符串(例如要进行查找,或从许多非常小的片段构建一个非常大的字符串)
  • 它在一个循环中,没有做太多其他工作(但被频繁调用),因此即使构建一个简单的日志字符串所花费的时间比例更高

这应该不是一个笼统的规则,我希望这两种情况都是相对罕见的。

当然,我们真正想要的是能够说:"调用debug方法,传入一个参数,该参数不是调试字符串本身,而是知道如何构建调试字符串的东西,仅在必要时才使用。"这在Java中可能比较丑陋,没有简洁的闭包。(即使在支持lambda表达式形式的闭包的语言中,根据语言处理捕获变量的方式,在某些情况下,捕获相关变量可能是重要的。)


2
SLF的日志方法中没有字符串格式化选项吗? - matt b
我一直倡导始终使用这个规则,因为开发人员不需要考虑构建字符串(参数)的成本。有时,需要为调试日志构建额外的参数,例如 getEntryDebugString()。最好多写几行容易出错的代码,而不是因为罕见的问题而感到遗憾。 - xmedeko

9

我同意迈克尔·A·杰克逊的名言:

程序优化的第一法则:不要去做。

程序优化的第二法则——只有专家才需要考虑的:暂时不要优化。

在大多数情况下,我认为如果不能确定性能增益是显著的,让代码库变得更复杂是不值得的。

我知道这会提高性能,但我认为是否值得在特定情况下添加额外的代码行应该由个人程序员负责。在大多数情况下,额外的代码行只会增加复杂性,在性能方面没有任何显著的收益。


2
很明显,如果作者提出了这个问题,那么他就需要进行优化。也就是说,当你被要求优化一段代码时,你不能回复以上两个引用。我理解你的立场,但在这种情况下并没有帮助。 - OCB
我对这个“不要进行优化”的口号非常不满,给我负数分。它是有严重缺陷的-如果您的优化产生结果(即使只是微不足道的结果),而且它几乎是免费的(像这样,'if'语句是微不足道的),并且没有太复杂(将日志语句包装在if中只是最微不足道的事情),那么就继续做吧。 - bharal
1
不同意,这是一种清单活动,旨在避免麻烦,可以轻松地传达给初级开发人员,以便他们不会无意中引入错误,从而导致其他人花费时间进行调试。 - ammianus

2

我认为在编写日志消息之前调用isDebugEnabled()函数是有意义的。 这样你可以轻松更新你的日志消息。 我们使用以下代码使日志消息更加灵活。

if (LOGGER.isDebugEnabled()) {  
  String msg = "A Message {0} you can put {1} differet Objects in {2}"; //$NON-NLS-1$
  Object[] args = new Object[] {file1.toString(),new Integer(23),anObject};
  LOGGER.debug(MessageFormat.format(msg,args));
}

当你缺少if语句时,你会浪费时间。记住……你的项目变得越来越大,日志信息也是如此。
日志信息不应该拖慢你的代码!

2
存在一种非常方便的基于消息格式的替代方法:参数化消息。http://www.slf4j.org/faq.html#logging_performance - Pikachu

2
我找不到在线的参考资料(也许我在书中看过),但有一个例子是一些BIOS调用将字符串写入屏幕。
写字符串到屏幕的代码检查确保字符串不会越过屏幕,然后调用一个函数将字符写到屏幕上。写字符到屏幕的函数检查确保字符不会被写到屏幕外面。
从写字符到屏幕的函数中删除检查代码会大大提高速度,因为打印每个字符的频率非常高。他们还提供了一种方法,在调用之前检查屏幕位置的情况下进行检查。
因此,如果您可以在高级别上检查并避免低级别的检查,则可以显着加快速度。
在您提供的情况下,如果代码在循环中或者有很多日志记录语句,则会有明显的好处,因为您将:
- 删除字符串创建(以及相关的GC) - 减少if语句的数量(尽管hotspot很可能会优化它们)。
我认为,一般情况下,如果有简单的解决方法就不应该添加已知成本高昂的任何内容。这显然属于这种情况——添加if语句不难做到,稍后放进去很麻烦,并且可以明显提高速度/内存。
我认为这与过早优化的区别在于,这是已知始终代价高昂的问题,因此问题归结为是否要将累计成本添加到程序中?成本几乎是恒定的,并且在编写代码时就已知。

0
我将记录器设置为INFO级别,并运行了以下测试:
@Test
void loggerTest() {
    System.out.println("START " + LocalDateTime.now());

    System.out.println("TRACE: " + LocalDateTime.now());
    log.trace("{}", sleepAndReturnString(5000L, "TRACE PRINT"));
    System.out.println("DEBUG: " + LocalDateTime.now());
    log.debug("{}", sleepAndReturnString(5000L, "DEBUG PRINT"));
    System.out.println("INFO: " + LocalDateTime.now());
    log.info("{}", sleepAndReturnString(5000L, "INFO PRINT"));
    System.out.println("WARN: " + LocalDateTime.now());
    log.warn("{}", sleepAndReturnString(5000L, "WARN PRINT"));
    System.out.println("ERROR: " + LocalDateTime.now());
    log.error("{}", sleepAndReturnString(5000L, "ERROR PRINT"));

    System.out.println("END " + LocalDateTime.now());
}

public static String sleepAndReturnString(long millis, String message) {
    try {
        Thread.sleep(millis);
    } catch (InterruptedException e) {
        log.error("", e);
    }
    return message;
}

logback.xml 文件:

<configuration>

<property name="MY__PATTERN"
          value="%d{yyyy-MM-dd HH:mm:ss.SSS} | %highlight(%-5level) | %message%n%rEx"/>

<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
        <outputPatternAsHeader>true</outputPatternAsHeader>
        <pattern>${MY__PATTERN}</pattern>
    </encoder>
</appender>

<root level="info">
    <appender-ref ref="CONSOLE"/>
</root>

这是在控制台中打印的内容:
START 2023-01-20T11:17:57.255
TRACE: 2023-01-20T11:17:57.255
DEBUG: 2023-01-20T11:18:02.256
INFO: 2023-01-20T11:18:07.262
2023-01-20 11:18:12.267 | INFO  | INFO PRINT
WARN: 2023-01-20T11:18:12.283
2023-01-20 11:18:17.285 | WARN  | WARN PRINT
ERROR: 2023-01-20T11:18:17.285
2023-01-20 11:18:22.287 | ERROR | ERROR PRINT
END 2023-01-20T11:18:22.287

正如我们所看到的,每次线程休眠5秒钟,尽管TRACE和DEBUG消息没有打印到控制台。这表明使用isLevelEnabled是合理的,并且可以提高性能。


0
如果“model”已知,仅记录它并不会太耗费资源。 但是,如果像下面这样为了记录而获取“model”,就可能会牺牲简单性。
LOGGER.debug("model[" + proxy.getModel() + "]");

网页内容由stack overflow 提供, 点击上面的
可以查看英文原文,
原文链接