转载

DIY Ruby CPU 分析 Part II

【编者按】作者 Emil Soman,Rubyist,除此之外竟然同时也是艺术家,吉他手,Garden City RubyConf 组织者。本文是 DIY Ruby CPU Profiling 的第二部分。本文系OneAPM 工程师编译整理。 DIY Ruby CPU 分析 Part II 在第一部分中我们学习了 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/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 官方博客。

正文到此结束
Loading...