java - VisualVM - 奇怪的自拍时间

Question

今天我对得到的 Visual VM 分析结果感到困惑。

我有以下简单的Java方法:

public class Encoder {
  ...
  private BitString encode(InputStream in, Map<Character, BitString> table) 
      throws IOException {

    BufferedReader reader = new BufferedReader(new InputStreamReader(in));

    BitString result = new BitString();
    int i;
    while ((i = reader.read()) != -1) {
      char ch = (char) i;
      BitString string = table.get(ch);
      result = result.append(string);
    }

    return result;
  }
}

此方法从流中一次读取一个字符。对于每个字符，它查找它的位串表示形式，并将这些位串连接起来以表示整个流。

BitString 是一种自定义数据结构，它使用底层字节数组表示位序列。

该方法的性能非常差。问题在于 BitString#append - 该方法创建一个新的字节数组，从两个输入 BitString 复制位并将其作为新的 BitString 实例返回。

public BitString append(BitString other) {

  BitString result = new BitString(size + other.size);
  int pos = 0;

  for (byte b : this) {
    result.set(pos, b);
    pos++;
  }
  for (byte b : other) {
    result.set(pos, b);
    pos++;
  }

  return result;
}

但是，当我尝试使用 VisualVM 验证发生的情况时，我得到的是:

我对 Visual VM 和一般分析的经验很少。据我了解，这看起来问题似乎出在 encode 方法本身的某个地方，而不是 append 中。

可以肯定的是，我用自定义时间测量包围了整个编码方法和追加调用，如下所示:

public class Encoder {
  private BitString encode(InputStream in, Map<Character, BitString> table)
      throws IOException {

>>  long startTime = System.currentTimeMillis();
>>  long appendDuration = 0;

    BufferedReader reader = new BufferedReader(new InputStreamReader(in));

    BitString result = new BitString();
    int i;
>>  long count = 0;
    while ((i = reader.read()) != -1) {
      char ch = (char) i;
      BitString string = table.get(ch);

>>    long appendStartTime = System.currentTimeMillis();
      result = result.append(string);
>>    long appendEndTime = System.currentTimeMillis();
>>    appendDuration += appendEndTime - appendStartTime;

>>    count++;
>>    if (count % 1000 == 0) {
>>      log.info(">>> CHARACTERS PROCESSED: " + count);
>>      long endTime = System.currentTimeMillis();
>>      log.info(">>> TOTAL ENCODE DURATION: " + (endTime - startTime) + " ms");
>>      log.info(">>> TOTAL APPEND DURATION: " + appendDuration + " ms");
>>    }
    }

    return result;
  }
}

我得到了以下结果:

CHARACTERS PROCESSED: 102000
TOTAL ENCODE DURATION: 188276 ms
APPEND CALL DURATION: 188179 ms

这似乎与 Visual VM 的结果相矛盾。

我错过了什么？

Answer 1

您看到此行为是因为 VisualVM 只能在安全点对调用堆栈进行采样，并且 JVM 正在优化代码中的安全点。这导致样本被集中在“自拍时间”下，从而人为夸大并产生误导。有两种可能的修复方法:

• 为了让 VisualVM 更好地工作，请添加 JVM 选项以保留更多安全点，例如 -XX:-Inline 和 -XX:+UseCountedLoopSafepoints。这些会减慢您的代码速度，但会使分析结果更加准确。这个解决方案很简单，而且通常就足够好了。请记住在不进行分析时删除这些选项!
• 如果您不介意切换分析器，可以使用 Java Mission Control或honest-profiler 。它们能够使用 JVM 的特殊 API 在安全点以外的地方进行采样。该解决方案更准确一些，因为您正在分析完全优化的代码，但在我看来，这些分析器比 VisualVM 更难使用。

在您的具体情况下，JVM 可能会内联对 BitString.append() 的方法调用以提高性能。这会导致通常位于方法调用末尾的安全点被删除，这意味着该方法将不再显示在探查器中。

有一篇很棒的博客文章 here有关安全点是什么及其工作原理的更多详细信息，以及另一个 here其中更详细地讨论了安全点和采样分析器之间的交互。