用异步分析器和perf测量DirectByteBuffer

Question

我在玩异步分析器和perf，并决定测量DirectByteBuffer磁盘IO的内核活动。下面是代码(用Scala编写的，但它的Java版本应该很明显)：

val path = Paths.get("/tmp/test")

val buffer = ByteBuffer.allocateDirect(4096 * 4096)

def main(args: Array[String]): Unit = {
  var fullReadsCount = 0
  while (true) {
    var bytesRead = 0
    var ch: SeekableByteChannel = null
    try {
      ch = Files.newByteChannel(path)
      while (bytesRead >= 0) {
        bytesRead = ch.read(buffer)
        buffer.clear()
      }
    } finally {
      if (ch != null)
        ch.close()
    }
    fullReadsCount += 1
    if(fullReadsCount % 100 == 0) println(fullReadsCount)
  }
}

我多次运行这段代码，并同时执行perf和async-profiler，并注意到以下结果：

1. 异步分析器 $~/profiler.sh -i 28169 -d 30 //.264788732 61.02% 9317 copy_user_enhanced_fast_string_k 41510919 9.57% 1467 generic_file_read_iter_k 9333863 2.15% 331 find_get_entry_k 4181131 0.96% 148 __radix_tree_lookup_k 4057194 0.94% 143 copy_page_to_iter_k 1860485 0.43% 63 __d_lookup_rcu_k 1610407 0.37% 50 _raw_spin_unlock_irqrestore_k
2. perf sudo perf record -F 31499 -g -p <pid> -- sleep 30

​

​

在所有的跑动中，我注意到copy_user_enhanced_fast_string百分比在perf和async-profiler 61.02% vs 77.65%中是不同的。

问题：为什么perf和async-profiler采样的copy_user_enhanced_fast_string百分比是不同的？我试着提供相同的条件(频率和采样周期)，但我没有同时运行这两个分析器。31499赫兹≈28169纳米)。

还是我对结果的解读是错误的？

Answer 1

所选的分析间隔(28μs)太短。

检查dmesg -可能有一些内核警告，如

perf interrupt took too long (18047 > 18000), lowering kernel.perf_event_max_sample_rate to 25000

async-profiler在处理PMU事件的机制上不同于perf。perf只是在环形缓冲区中收集样本，而异步分析器则向进程发送一个信号，以调用特定于应用程序的回调。通常对用户来说没有明显的差异，但是当剖析频率太高时，信号可能会带来额外的噪声并影响进程调度。

我建议增加剖面间隔到至少100μs (10000赫兹)。这将使测量更加可靠。