DIY Ruby CPU 分析 Part II

【编者按】作者 Emil Soman，Rubyist，除此之外竟然同时也是艺术家，吉他手，Garden City RubyConf 组织者。本文是 DIY Ruby CPU Profiling 的第二部分。本文系 OneAPM 工程师编译整理。

在第一部分中我们学习了 CPU 分析的含义和进行 CPU 分析的两种方法，点此处回顾第一篇精彩内容。在这一部分我们将研究 CPU time 和 Wall time，这些部分总被用来测量执行开销。我们也会写一些实现这些测量方法的代码作为建立 CPU 分析的第一步。

Part II. CPU time 和 Wall time

Wall time

Wall time 是在一个方法被调用和返回之间的真实时间。因此，如果你想要测量一个方法执行的 「Wall clock time」，理论上可以用秒表来测量。只要在方法开始执行时打开秒表，在方法返回时按下停止。这个时间通常也被称为真实时间。

关于 Wall time 很重要的一点是，可以预见，每次试图测量同一段代码可能得到不同的结果。这是因为一系列后台进程会影响 Wall time. 当 CPU 同时运行多个进程的时候，操作系统给同时运行的进程排期并且试图为它们公平的分配 CPU 空间。这意味着 CPU 花费的总时间被分成多个片而我们的方法只占用其中的一些时间片。因此，当 Wall clock 开始计时，我们的进程可能会闲置并且为并行运行的其他进程让路。这意味着花费在其他进程的时间将增加我们的 Wall time!

CPU time

CPU time 是指 CPU 执行方法的时间。CPU time 的度量单位是用于执行方法的 CPU 时钟周期。如果我们了解 CPU 频率，它的单位是周期每秒，也可以称作赫兹，那么我们可以将其转换为时间。如果 CPU 执行某一方法花了 x 个时钟周期，这个 CPU 频率是 y 赫兹，那么 CPU 执行方法的时间为 x/y 秒。有时操作系统会为我们自动进行转换从而使我们免于进行这种计算。
CPU 时间不等同于 Wall time，其中的差别在于方法的指令类型。我们可以宽泛的将指令分为两种类型：CPU 密集型 和 I/O 密集型. 在执行 I/O 指令时，CPU 空闲下来可以转去执行其他 CPU 密集型指令。因此，如果我们的方法在 I/O 指令上花费时间，CPU 可以不把时间投入在该方法上，而是去处理其他事情，直到 I/O 操作完成。 这段时间内 Wall time 在计时而 CPU time 停止计时，落后于 Wall time.

我们来看看一个需要5分钟来执行的慢方法的情况。如果想知道这个方法花费了多长时间，你的 Wall clock 可以显示「执行该方法需要五分钟」，但 CPU 会显示「执行该方法中用时 3 分钟」。所以应该听从哪一个说法呢？究竟哪个时间能够更准确的测量执行方法的时间？

答案是：看情况。这取决于你希望测量的方法的类型。如果该方法的大部分时间用于 I/O 操作，或者该方法没有直接处理 CPU 密集型指令，由 CPU time 描述的时间开销将十分不准确。对于这些类型的方法，通过 Wall time 来测量时间更加合适。而对于其他情况，坚持通过 CPU time 来测量是很可靠的。

测量 CPU time 和 Wall time

鉴于想要写一个 CPU 分析器，我们需要一种测量 CPU time 和 Wall time 的方法。下面来看一看已经能够测量这两项的 Ruby 的 Benchmark module 中的代码。

def measure(label = "") # :yield:
  t0, r0 = Process.times, Process.clock_gettime(BENCHMARK_CLOCK)
  yield
  t1, r1 = Process.times, Process.clock_gettime(BENCHMARK_CLOCK)
  Benchmark::Tms.new(t1.utime  - t0.utime,
                     t1.stime  - t0.stime,
                     t1.cutime - t0.cutime,
                     t1.cstime - t0.cstime,
                     r1 - r0,
                     label)
end

由此可见，Ruby 通过两种进程类中的方法来测量时间：

1. 通过times测量 CPU time.
2. 通过clock_gettime来测量真实时间，也就是 Wall time.
   但是times方法返回的结果为1秒，这表示通过分析器用times只能测量仅需要几秒就能完成的 方法的 CPU time. 然而clock_gettime就有趣多了。

clock_gettime

Process::clock_gettime是早在 Ruby 2.1 版本就已经被添加的方法，它使用 POSIX clock_gettime()功能并回退到 OS 仿真来获得时间以防clock_gettime在 OS 中失效或无法实施。该功能接受clock_id及时间结果作为参数。有很多可以被选为这种计时器的clock_ids，但我们感兴趣的是：

1. CLOCK_MONOTONIC: 这个计时器测量逃走的 Wall clock time，因为过去的任意时间点不会被系统时钟的变化影响，最适合测量 Wall time.
2. CLOCK_PROCESS_CUPTIME_ID: 这个计时器测量每一个进程的 CPU time，意即计算进程中所有线程的时间。我们可以用它来测量 CPU time.
   让我们利用这个来写一些代码：

module DiyProf
  # These methods make use of `clock_gettime` method introduced in Ruby 2.1
  # to measure CPU time and Wall clock time.

  def self.cpu_time
    Process.clock_gettime(Process::CLOCK_PROCESS_CPUTIME_ID, :microsecond)
  end

  def self.wall_time
    Process.clock_gettime(Process::CLOCK_MONOTONIC, :microsecond)
  end
end

可以在 benchmark 代码中使用这些方法：

puts "****CPU Bound****"
c1, w1 = DiyProf::cpu_time, DiyProf::wall_time
10000.times do |i|
  Math.sqrt(i)
end
c2, w2 = DiyProf::cpu_time, DiyProf::wall_time
puts "CPU time	=	#{c2-c1}
Wall time	=	#{w2-w1}"

puts "
****IO Bound****"
require 'tempfile'

c1, w1 = DiyProf::cpu_time, DiyProf::wall_time
1000.times do |i|
  Tempfile.create('file') do |f|
    f.puts(i)
  end
end
c2, w2 = DiyProf::cpu_time, DiyProf::wall_time
puts "CPU time	=	#{c2-c1}
Wall time	=	#{w2-w1}"

运行这些代码会得出类似以下的结果：

****CPU Bound****
CPU time	=	5038
Wall time	=	5142

****IO Bound****
CPU time	=	337898
Wall time	=	475864

这些清楚地展现了单个 CPU 内核的情况，在仅运行 CPU 密集型指令时 CPU time 和 Wall time 几乎相等，而运行 I/O 密集型指令时 CPU time 总是少于 Wall time.

概括

我们学习了 CPU time 和 Wall time 的含义与差异，以及什么时候用哪种。与此同时，写了一些 Ruby 代码来测量 CPU time 和 Wall time 来为我们做的 CPU 分析器测量时间。在第三部分我们将讨论 Ruby TracePoint API 并利用它做一个仪表分析器。

原文链接：http://crypt.codemancers.com/posts/2015-03-06-diy-ruby-cpu-profiling-part-i/

OneAPM for Ruby 能够深入到所有 Ruby 应用内部完成应用性能管理和监控，包括代码级别性能问题的可见性、性能瓶颈的快速识别与追溯、真实用户体验监控、服务器监控和端到端的应用性能管理。 想阅读更多技术文章，请访问 OneAPM 官方博客。