日志行需要 10 毫秒答案

【问题标题】：Log line taking 10's of milliseconds日志行需要 10 毫秒
【发布时间】：2021-03-18 16:46:34
【问题描述】：

在某些情况下，在以下代码中调用 java.util.logging.Logger.log() 时，我发现延迟非常高：

private static Object[] NETWORK_LOG_TOKEN = new Object[] {Integer.valueOf(1)};

private final TimeProbe probe_ = new TimeProbe();

public void onTextMessagesReceived(ArrayList<String> msgs_list) {
    final long start_ts = probe_.addTs(); // probe A

    // Loop through the messages
    for (String msg: msgs_list) {
        probe_.addTs(); // probe B
        log_.log(Level.INFO, "<-- " + msg, NETWORK_LOG_TOKEN);
        probe_.addTs(); // probe C

        // Do some work on the message ...
        probe_.addTs(); // probe D
    }
        
    final long end_ts = probe_.addTs(); // probe E
    if (end_ts - start_ts >= 50)  {
        // If the run was slow (>= 50 millis) we print all the recorded timestamps
        log_.info(probe_.print("Slow run with " + msgs_list.size() + " msgs: "));
    }
    probe_.clear();
}

probe_ 只是这个非常基本的类的一个实例：

public class TimeProbe {
    final ArrayList<Long> timestamps_ = new ArrayList<>();
    final StringBuilder builder_ = new StringBuilder();

    public void addTs() {
        final long ts = System.currentTimeMillis();
        timestamps_.add(ts);
        return ts;
    }

    public String print(String prefix) {
        builder_.setLength(0);
        builder_.append(prefix);
        for (long ts: timestamps_) {
            builder_.append(ts);
            builder_.append(", ");
        }
        builder_.append("in millis");
        return builder_.toString();
    }

    public void clear() {
        timestamps_.clear();
    }
}

这里是记录 NETWORK_LOG_TOKEN 条目的处理程序：

final FileHandler network_logger = new FileHandler("/home/users/dummy.logs", true);
    network_logger2.setFilter(record -> {
        final Object[] params = record.getParameters();
        // This filter returns true if the params suggest that the record is a network log
        // We use Integer.valueOf(1) as our "network token"
        return (params != null && params.length > 0 && params[0] == Integer.valueOf(1));
    });

在某些情况下，我得到以下输出（添加带有探针 A、B、C、D、E 的标签以使事情更清楚）：

//                        A              B               C              D             B              C              D             E         
slow run with 2 msgs: 1616069594883, 1616069594883, 1616069594956, 1616069594957, 1616069594957, 1616069594957, 1616069594957, 1616069594957

除了 B 和 C 之间的代码行（在 for 循环的第一次迭代期间），一切都花费不到 1 毫秒，这需要 73 毫秒。并非每次调用onTextMessagesReceived() 时都会发生这种情况，但它确实是个大问题。我欢迎任何解释这种缺乏可预测性的原因的想法。

附带说明一下，我检查了我的磁盘 IO 超低，并且这段时间没有发生 GC 暂停。我认为我的 NETWORK_LOG_TOKEN 设置在设计方面充其量是非常脆弱的，但我仍然想不出为什么有时，这第一条日志行需要永远。任何关于可能发生的事情的指示或建议将不胜感激:)！

【问题讨论】：

这是唯一需要这么长时间的日志语句吗？这对于您的配置中的日志记录语句是否不寻常？你怎么知道这是日志记录而不是你将 ts 添加到 arraylist 的方式？运行这 10k 次，看看它是否稳定下来怎么样？当它意识到您即将循环时，它可能与循环开始时启动的 jit 或其他优化有关，这种效果将在数千次运行中消除。通常，您不能运行一次代码并期望配置文件是合理或准确的。
您是否查看过系统上System.currentTimeMillis() 的粒度？如果这种情况很少见，可能是 NTP 同步，请尝试改用 nanoTime()。它可能是一百万件事，尝试使用github.com/giltene/jHiccup 并查看它的输出。如果什么都没有显示，那么记录器当然有可能实际上在 IO 上被阻塞（将其缓冲区写出），请使用分析器进行确认。

标签： java performance logging

【解决方案1】：

要尝试的事情：

启用 JVM 安全点日志。虚拟机暂停是not always caused by GC。
如果您使用 JDK -XX:-UseBiasedLocking。 JUL 框架中有很多synchronized 的地方。在多线程应用程序中，这可能会导致锁定撤销有偏差，这是安全点暂停的常见原因。
在挂钟模式下运行async-profiler，输出.jfr。然后，使用 JMC，您将能够找到一个线程在给定时刻附近正在做什么。
尝试将日志文件放入 tmpfs 以排除磁盘延迟，或使用 MemoryHandler 而不是 FileHandler 来检查文件 I/O 是否影响暂停。

【讨论】：

谢谢@apangin，我一直在使用 async-profiler，但我无法弄清楚如何查看特定线程在特定时间正在做什么。在 jmc 中看到 jfr 输出给了我一些有趣的信息，但即使是线程选项卡似乎也没有给我足够详细的信息来查看线程在给定时间正在做什么。
@MarkoPaulo 您可以使用 JMC 中的事件浏览器菜单列出所有方法分析样本，按“开始时间”对它们进行排序，然后查找所需间隔附近的事件。

【解决方案2】：

除了 B 和 C 之间的代码行（在 for 循环的第一次迭代期间），一切都花费不到 1 毫秒，这需要 73 毫秒。 [snip] ...但我仍然想不出为什么有时这第一行日志需要永远。

发布到根记录器或其处理程序的第一条日志记录将 trigger lazy loading 中的root handlers。

如果您不需要发布到根记录器处理程序，则在添加 FileHandler 时调用 log_.setUseParentHandlers(false)。这将使您的日志记录不会到达根记录器。它还确保您不会发布到附加到父记录器的其他处理程序。

您还可以在开始循环之前通过执行Logger.getLogger("").getHandlers() 来加载根处理程序。您需要为加载它们付出代价，但时间不同。

log_.log(Level.INFO, "

此行中的字符串连接将执行数组复制并创建垃圾。尝试做：

log_.log(Level.INFO, msg, NETWORK_LOG_TOKEN);

默认的日志方法将遍历当前线程堆栈。您可以通过在紧密循环中使用 logp 方法来避免这种步行：

public Foo {
   private static final String CLASS_NAME = Foo.class.getName();
   private static final Logger log_ = Logger.getLogger(CLASS_NAME);

   public void onTextMessagesReceived(ArrayList<String> msgs_list) {
       String methodName = "onTextMessagesReceived";
       // Loop through the messages
       for (String msg: msgs_list) {
          probe_.addTs(); // probe B
          log_.logp(Level.INFO, CLASS_NAME, methodName, msg, NETWORK_LOG_TOKEN);
          probe_.addTs(); // probe C

          // Do some work on the message ...
          probe_.addTs(); // probe D
      }
   }
}

在您的代码中，您将过滤器附加到 FileHandler。取决于用例，但记录器也接受filters。如果您针对特定消息，有时在记录器而不是处理程序上安装过滤器是有意义的。

【讨论】：