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 更难使用。

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

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

Answer 2

[此答案无效。但我一直保留它，直到 OP 从成员那里得到一些帮助，因为这篇文章包含两个帮助其他人理解问题的 cmets]。

在这种情况下，VisualVM 测量了实际的 CPU 时间，但您测量的时间值是“经过的时间”。

如果执行线程必须等待 IO 或网络，则该时间不会被测量为 CPU 时间。