【編者按】作者 Emil Soman，Rubyist，除此之外竟然同時(shí)也是藝術(shù)家，吉他手，Garden City RubyConf 組織者。本文是 DIY Ruby CPU Profiling 的第二部分。本文系 OneAPM 工程師編譯整理。

DIY Ruby CPU 分析——Part I

Part II. CPU time 和 Wall time

Wall time

Wall time 是在一個(gè)方法被調(diào)用和返回之間的真實(shí)時(shí)間。因此，如果你想要測(cè)量一個(gè)方法執(zhí)行的 「Wall clock time」，理論上可以用秒表來(lái)測(cè)量。只要在方法開(kāi)始執(zhí)行時(shí)打開(kāi)秒表，在方法返回時(shí)按下停止。這個(gè)時(shí)間通常也被稱(chēng)為真實(shí)時(shí)間。

關(guān)于 Wall time 很重要的一點(diǎn)是，可以預(yù)見(jiàn)，每次試圖測(cè)量同一段代碼可能得到不同的結(jié)果。這是因?yàn)橐幌盗泻笈_(tái)進(jìn)程會(huì)影響 Wall time. 當(dāng) CPU 同時(shí)運(yùn)行多個(gè)進(jìn)程的時(shí)候，操作系統(tǒng)給同時(shí)運(yùn)行的進(jìn)程排期并且試圖為它們公平的分配 CPU 空間。這意味著 CPU 花費(fèi)的總時(shí)間被分成多個(gè)片而我們的方法只占用其中的一些時(shí)間片。因此，當(dāng) Wall clock 開(kāi)始計(jì)時(shí)，我們的進(jìn)程可能會(huì)閑置并且為并行運(yùn)行的其他進(jìn)程讓路。這意味著花費(fèi)在其他進(jìn)程的時(shí)間將增加我們的 Wall time!

CPU time

CPU time 是指 CPU 執(zhí)行方法的時(shí)間。CPU time 的度量單位是用于執(zhí)行方法的 CPU 時(shí)鐘周期。如果我們了解 CPU 頻率，它的單位是周期每秒，也可以稱(chēng)作赫茲，那么我們可以將其轉(zhuǎn)換為時(shí)間。如果 CPU 執(zhí)行某一方法花了 x 個(gè)時(shí)鐘周期，這個(gè) CPU 頻率是 y 赫茲，那么 CPU 執(zhí)行方法的時(shí)間為 x/y 秒。有時(shí)操作系統(tǒng)會(huì)為我們自動(dòng)進(jìn)行轉(zhuǎn)換從而使我們免于進(jìn)行這種計(jì)算。
CPU 時(shí)間不等同于 Wall time，其中的差別在于方法的指令類(lèi)型。我們可以寬泛的將指令分為兩種類(lèi)型：CPU 密集型 和 I/O 密集型. 在執(zhí)行 I/O 指令時(shí)，CPU 空閑下來(lái)可以轉(zhuǎn)去執(zhí)行其他 CPU 密集型指令。因此，如果我們的方法在 I/O 指令上花費(fèi)時(shí)間，CPU 可以不把時(shí)間投入在該方法上，而是去處理其他事情，直到 I/O 操作完成。 這段時(shí)間內(nèi) Wall time 在計(jì)時(shí)而 CPU time 停止計(jì)時(shí)，落后于 Wall time.

我們來(lái)看看一個(gè)需要5分鐘來(lái)執(zhí)行的慢方法的情況。如果想知道這個(gè)方法花費(fèi)了多長(zhǎng)時(shí)間，你的 Wall clock 可以顯示「執(zhí)行該方法需要五分鐘」，但 CPU 會(huì)顯示「執(zhí)行該方法中用時(shí) 3 分鐘」。所以應(yīng)該聽(tīng)從哪一個(gè)說(shuō)法呢？究竟哪個(gè)時(shí)間能夠更準(zhǔn)確的測(cè)量執(zhí)行方法的時(shí)間？

答案是：看情況。這取決于你希望測(cè)量的方法的類(lèi)型。如果該方法的大部分時(shí)間用于 I/O 操作，或者該方法沒(méi)有直接處理 CPU 密集型指令，由 CPU time 描述的時(shí)間開(kāi)銷(xiāo)將十分不準(zhǔn)確。對(duì)于這些類(lèi)型的方法，通過(guò) Wall time 來(lái)測(cè)量時(shí)間更加合適。而對(duì)于其他情況，堅(jiān)持通過(guò) CPU time 來(lái)測(cè)量是很可靠的。

測(cè)量 CPU time 和 Wall time

鑒于想要寫(xiě)一個(gè) CPU 分析器，我們需要一種測(cè)量 CPU time 和 Wall time 的方法。下面來(lái)看一看已經(jīng)能夠測(cè)量這兩項(xiàng)的 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

由此可見(jiàn)，Ruby 通過(guò)兩種進(jìn)程類(lèi)中的方法來(lái)測(cè)量時(shí)間：

1. 通過(guò)times測(cè)量 CPU time.
2. 通過(guò)clock_gettime來(lái)測(cè)量真實(shí)時(shí)間，也就是 Wall time.
   但是times方法返回的結(jié)果為1秒，這表示通過(guò)分析器用times只能測(cè)量?jī)H需要幾秒就能完成的 方法的 CPU time. 然而clock_gettime就有趣多了。

clock_gettime

Process::clock_gettime是早在 Ruby 2.1 版本就已經(jīng)被添加的方法，它使用 POSIX clock_gettime()功能并回退到 OS 仿真來(lái)獲得時(shí)間以防clock_gettime在 OS 中失效或無(wú)法實(shí)施。該功能接受clock_id及時(shí)間結(jié)果作為參數(shù)。有很多可以被選為這種計(jì)時(shí)器的clock_ids，但我們感興趣的是：

1. CLOCK_MONOTONIC: 這個(gè)計(jì)時(shí)器測(cè)量逃走的 Wall clock time，因?yàn)檫^(guò)去的任意時(shí)間點(diǎn)不會(huì)被系統(tǒng)時(shí)鐘的變化影響，最適合測(cè)量 Wall time.
2. CLOCK_PROCESS_CUPTIME_ID: 這個(gè)計(jì)時(shí)器測(cè)量每一個(gè)進(jìn)程的 CPU time，意即計(jì)算進(jìn)程中所有線程的時(shí)間。我們可以用它來(lái)測(cè)量 CPU time.
   讓我們利用這個(gè)來(lái)寫(xiě)一些代碼：

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}"

運(yùn)行這些代碼會(huì)得出類(lèi)似以下的結(jié)果：

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

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

這些清楚地展現(xiàn)了單個(gè) CPU 內(nèi)核的情況，在僅運(yùn)行 CPU 密集型指令時(shí) CPU time 和 Wall time 幾乎相等，而運(yùn)行 I/O 密集型指令時(shí) CPU time 總是少于 Wall time.

概括

我們學(xué)習(xí)了 CPU time 和 Wall time 的含義與差異，以及什么時(shí)候用哪種。與此同時(shí)，寫(xiě)了一些 Ruby 代碼來(lái)測(cè)量 CPU time 和 Wall time 來(lái)為我們做的 CPU 分析器測(cè)量時(shí)間。在第三部分我們將討論 Ruby TracePoint API 并利用它做一個(gè)儀表分析器。

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

OneAPM for Ruby 能夠深入到所有 Ruby 應(yīng)用內(nèi)部完成應(yīng)用性能管理和監(jiān)控，包括代碼級(jí)別性能問(wèn)題的可見(jiàn)性、性能瓶頸的快速識(shí)別與追溯、真實(shí)用戶體驗(yàn)監(jiān)控、服務(wù)器監(jiān)控和端到端的應(yīng)用性能管理。 想閱讀更多技術(shù)文章，請(qǐng)?jiān)L問(wèn) OneAPM 官方博客。