耗时10毫秒的日志行
在下面的代码中，在某些情况下调用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循环的第一次迭代期间)，所有的代码都需要不到1ms，这一行代码花费了惊人的73毫秒。这并不是每次调用onTextMessagesReceived()时都会发生，但它确实发生了，这是一个很大的问题。我欢迎任何解释这种缺乏可预测性的原因的想法。
顺便说一句，我已经检查到我的磁盘IO非常低，并且在这段时间没有发生GC暂停。我会认为我的NETWORK_LOG_TOKEN设置充其量在设计方面是相当脆弱的，但我仍然想不出为什么有时第一个日志行总是要花费很长时间。任何关于可能发生的事情的指示或建议都将不胜感激:)！
回答 2
Stack Overflow用户
发布于 2021-03-19 01:40:27
可以尝试的内容：
JVM
- 启用安全点日志。虚拟机暂停是not always caused by GC.
- 如果您使用的是JDK < 15，请禁用偏向锁定：
-XX:-UseBiasedLocking。JUL框架中有很多synchronized的地方。在多线程应用程序中，这可能会导致有偏差的锁撤销，这是安全点暂停的常见原因。
- 在挂钟模式下运行async-profiler，输出为.jfr。然后，使用JMC，您将能够找到线程在给定时刻附近到底在做什么。
- 尝试将日志文件放到tmpfs上以排除磁盘延迟，或者使用
MemoryHandler而不是FileHandler来检查文件I/O是否会影响暂停。
Stack Overflow用户
发布于 2021-03-19 03:31:47
除了B和C之间的代码行(在
循环的第一次迭代期间)，所有的代码都需要不到1ms，这一行代码花费了惊人的73毫秒。snip ...but我仍然想不出为什么有时候，第一个日志行总是要花费很长时间。
发布到根记录器或其处理程序的第一条日志记录将对root handlers执行trigger lazy loading操作。
如果不需要发布到根记录器处理程序，那么在添加FileHandler时调用log_.setUseParentHandlers(false)。这将使您的日志记录不会传到根记录器。它还可以确保您不会发布到附加到父记录器的其他处理程序。
您还可以通过在开始循环之前执行Logger.getLogger("").getHandlers()来加载根处理程序。您将为加载它们付出代价，但在不同的时间。
log_.log(Level.INFO，"<--“+ msg，NETWORK_LOG_TOKEN)；
这一行中的字符串连接将进行数组复制并创建垃圾。试着去做：
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。如果您的目标是特定的消息，有时在记录器上安装过滤器而不是在处理程序上安装筛选器是有意义的。
https://stackoverflow.com/questions/66695434
复制相似问题
腾讯云开发者
