【编者按】作者 Emil Soman,Rubyist,除此之外竟然同时也是艺术家,吉他手,Garden City RubyConf 组织者。本文是 DIY Ruby CPU Profiling 的第二部分。本文系OneAPM 工程师编译整理。 在第一部分中我们学习了 CPU 分析的含义和进行 CPU 分析的两种方法,点此处回顾第一篇精彩内容。在这一部分我们将研究 CPU time 和 Wall time,这些部分总被用来测量执行开销。我们也会写一些实现这些测量方法的代码作为建立 CPU 分析的第一步。
Wall time 是在一个方法被调用和返回之间的真实时间。因此,如果你想要测量一个方法执行的 「Wall clock time」,理论上可以用秒表来测量。只要在方法开始执行时打开秒表,在方法返回时按下停止。这个时间通常也被称为真实时间。
关于 Wall time 很重要的一点是,可以预见,每次试图测量同一段代码可能得到不同的结果。这是因为一系列后台进程会影响 Wall time. 当 CPU 同时运行多个进程的时候,操作系统给同时运行的进程排期并且试图为它们公平的分配 CPU 空间。这意味着 CPU 花费的总时间被分成多个片而我们的方法只占用其中的一些时间片。因此,当 Wall clock 开始计时,我们的进程可能会闲置并且为并行运行的其他进程让路。这意味着花费在其他进程的时间将增加我们的 Wall 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 分析器,我们需要一种测量 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 通过两种进程类中的方法来测量时间:
times
测量 CPU time. clock_gettime
来测量真实时间,也就是 Wall time. times
方法返回的结果为1秒,这表示通过分析器用 times
只能测量仅需要几秒就能完成的 方法的 CPU time. 然而 clock_gettime
就有趣多了。 Process::clock_gettime
是早在 Ruby 2.1 版本就已经被添加的方法,它使用 POSIX clock_gettime()
功能并回退到 OS 仿真来获得时间以防 clock_gettime
在 OS 中失效或无法实施。该功能接受 clock_id
及时间结果作为参数。有很多可以被选为这种计时器的 clock_ids
,但我们感兴趣的是:
CLOCK_MONOTONIC
: 这个计时器测量逃走的 Wall clock time,因为过去的任意时间点不会被系统时钟的变化影响,最适合测量 Wall time. 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/t=/t#{c2-c1}/nWall time/t=/t#{w2-w1}" puts "/n****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/t=/t#{c2-c1}/nWall time/t=/t#{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 官方博客。