像其他调查技术一样，使用日志在某些情况下有意义，而在其他情况下则没有意义。 在本文中，我们将研究使用日志可以帮助你更容易理解软件行为的各种情况。 我们将首先讨论日志信息的几个关键点，然后分析这些特征如何帮助开发者调查应用程序的问题。

日志信息的最大优势之一是，它可以让你直观地看到某段代码在特定时间的执行情况。 当你使用 debugger 时，正如我们在前面文章中讨论的那样，你的注意力主要集中在现在。 当 debugger 暂停某一行代码的执行时，你看的是数据的样子。 debugger 不会给你很多关于执行历史的细节。 你可以使用执行 stack 跟踪来确定执行路径，但其他一切都集中在当前。

相比之下，日志关注的是应用程序在过去一段时间的执行情况（图 1）。日志信息与时间有密切关系。

图 1

记住要考虑你的应用程序所运行的系统的时区。 由于时区不同，日志时间可能会有几个小时的偏移（例如，在应用程序运行的地方和开发者所在的地方之间），这可能会造成混淆。

使用日志来识别异常情况

日志可以帮助你在问题发生后发现问题，并调查其根本原因。 通常，我们使用日志来决定从哪里开始调查。 然后，我们继续使用其他工具和技术来探索问题，如 debugger 或 profiler。 你通常可以在日志中找到异常stack的痕迹。下一个片段显示了一个Java异常 stack 跟踪的例子：

java.lang.NullPointerException
at java.base/java.util.concurrent.ThreadPoolExecutor runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker run(ThreadPoolExecutor.java:628) ~[na:na]
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable run(TaskThread.java:61) ~[tomcat-embed-core-9.0.26.jar:9.0.26]
at java.base/java.lang.Thread.run(Thread.java:830) ~[na:na]

在应用程序的日志中看到这个异常 stack 跟踪，或类似的东西，会告诉你某个功能可能出了问题。 每个异常都有自己的含义，可以帮助你确定应用程序在哪里遇到了问题。 例如，一个 NullPointerException 告诉你，某条指令通过一个不包含对象实例引用的变量引用了一个属性或方法（图 2）。

图 2

我经常发现，这个概念让初学者感到困惑。让我们来看看一个简单的 NullPointerException，这可能是所有Java开发者遇到的第一个异常，也是最容易理解的一个。 然而，当你在日志中发现一个 NullPointerException时，你首先需要问自己：为什么这个引用会缺失？它的缺失可能是因为应用程序之前执行的某条指令没有达到预期的效果（图 3）。

图 3

使用异常stack跟踪来确定什么在调用一个方法

开发人员认为不寻常的技术之一，但我发现在实践中很有优势，那就是记录异常stack跟踪，以确定是什么在调用一个特定的方法。 自从开始我的软件开发者生涯以来，我一直在与（通常）大型应用程序的混乱代码库打交道。 我经常遇到的困难之一是，当一个应用程序在远程环境中运行时，要弄清楚谁在调用某个特定的方法。 如果你只是阅读应用程序的代码，你会发现该方法有数百种可能被调用的方式。

当然，如果你足够幸运，并且有权限，你可以使用《Java 故障诊断 - 远程调试应用》中讨论的远程窃听。 然后你可以访问 debugger 提供的执行stack跟踪。 但如果你不能远程使用 debugger 呢？在这种情况下，你可以使用日志技术来代替!

Java 中的异常有一个经常被忽视的作用：它们可以跟踪执行stack的痕迹。 在讨论异常的时候，我们经常把执行stack跟踪称为异常stack跟踪。但说到底，它们是同样的东西。 异常stack跟踪显示了导致特定异常的方法调用链，即使没有抛出那个异常，你也可以获得这些信息。 在代码中，只要使用异常就足够了：

new Exception().printStackTrace();

考虑一下清单 1 中的方法。 如果你没有调试器，你可以简单地打印异常堆栈跟踪，就像我在这个例子中所做的那样，作为方法的第一行来查找执行堆栈跟踪。 请记住，这只是打印stack跟踪，并没有抛出异常，所以它不会干扰执行的逻辑。 这个例子是在 https://gitee.com/tunte/java-troubleshooting-sample.git 项目 da-ch5-ex1 中。

清单 1 使用异常打印日志中的执行 stack 跟踪

public List extractDigits() {
    new Exception().printStackTrace(); // Prints the exception stack trace
    List list = new ArrayList<>();
    for (int i = 0; i < input.length(); i++) {
        if (input.charAt(i) >= '0' && input.charAt(i) <= '9') {
            list.add(Integer.parseInt(String.valueOf(input.charAt(i))));
        }
    }

return list;
}

下一个片段显示了应用程序如何在控制台中打印出异常stack跟踪。 在现实世界中，stack跟踪可以帮助你立即确定执行流程，从而导致你想要调查的调用。 在这个例子中，你可以从日志中看到，extractDigits() 方法是在 Decoder 类的第11行从 decode() 方法中调用的：

java.lang.Exception at main.StringDigitExtractor extractDigits(StringDigitExtractor.java:15)
    at main.Decoder.decode(Decoder.java:11)
    at main.Main.main(Main.java:9)

测量执行特定指令所花费的时间

日志信息是衡量一组给定指令执行时间的简单方法。 你可以随时记录某一行代码前后的时间戳的差异。 假设你正在调查一个性能问题，其中一些给定的能力需要太长时间来执行。 你怀疑其原因是应用程序执行的一个查询，以从数据库中检索数据。 对于某些参数值，查询很慢，这降低了应用程序的整体性能。

为了找到导致问题的参数，你可以把查询和查询的执行时间写入日志。 一旦你确定了有问题的参数值，你就可以开始寻找解决方案了。 也许你需要给数据库中的某个表多加一个索引，也许你可以重写查询，使其更快。

清单 2 告诉你如何记录执行一段特定代码所花费的时间。 例如，让我们计算一下应用程序运行从数据库中查找所有产品的操作需要多少时间。 是的，我知道，我们这里没有参数；我简化了这个例子，让你把注意力集中在所讨论的语法上。 但在一个真实世界的应用程序中，你很可能会调查一个更复杂的操作。

清单 2 记录某一行代码的执行时间

public TotalCostResponse getTotalCosts() {

    TotalCostResponse response = new TotalCostResponse();
    // 记录方法执行前的时间戳
    long timeBefore = System.currentTimeMillis();
    // 执行我们要计算执行时间的方法
    var products = productRepository.findAll();
    // 计算执行后的时间戳和执行前的时间戳之间所花费的时间
    long spentTimeInMillis = System.currentTimeMillis() – timeBefore;

    // 打印执行时间
    log.info(“Execution time: ” + spentTimeInMillis);

    var costs = products.stream().collect(
        Collectors.toMap(
            Product::getName,
            p -> p.getPrice().multiply(new BigDecimal(p.getQuantity()))));
    response.setTotalCosts(costs);

    return response;
}

精确测量一个应用程序执行一个给定指令所花费的时间是一个简单而有效的技术。 然而，我只在调查问题时暂时使用这种技术。 我不建议你在代码中长期保留这样的日志，因为它们很可能以后就不需要了，而且它们会使代码更难读。 一旦你解决了问题，不再需要知道那行代码的执行时间，你就可以删除这些日志。

调查多线程架构中的问题

多线程架构是一种使用多个线程来定义其功能的能力，通常对外部干扰很敏感（图 4）。 例如，如果你使用 debugger 或 profiler（干扰应用程序执行的工具），应用程序的行为可能会改变（图 5）。

图 4

图 5

然而，如果你使用日志，应用程序在运行时受到影响的机会就会更小。 日志有时也会干扰多线程的应用程序，但它们对执行的影响不大，不足以改变应用程序的流程。 因此，它们可以成为检索你的调查所需数据的解决方案。

由于日志信息包含一个时间戳，你可以对日志信息进行排序，以找到操作执行的顺序。 在 Java 应用程序中，记录执行某条指令的线程名称有时很有帮助。你可以通过以下指令获得当前执行的线程的名称：

String threadName = Thread.currentThread().getName();

在Java应用程序中，所有线程都有一个名字。开发者可以为它们命名，或者JVM将使用 Thread-x 模式的名称来识别线程，其中x是一个递增的数字。 例如，创建的第一个线程将被命名为 Thread-0；下一个是 Thread-1；以此类推。 正如我们在后续的文章讨论 thread dump 时所说的，命名应用程序的线程是一个很好的做法，这样你在调查一个案例时就可以更容易地识别它们。