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或诚实探查器。它们能够使用 JVM 的特殊 API 在安全点以外的地方进行采样。这个解决方案更准确一些，因为您正在分析完全优化的代码，但在我看来，这些分析器比 VisualVM 更难使用。

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

这里有一篇很棒的博客文章，详细介绍了安全点是什么以及它们如何工作，这里还有一篇文章更详细地讨论了安全点和采样分析器之间的交互。