CoWはコウ可視化するんやで (aka. Rubyなどがforkした後のCoWを可視化してみる)

同僚の皆さんへのアンサーソングです。

hiboma.hatenadiary.jp

ryuichi1208.hateblo.jp

RubyKaigi やらですっかり遅く... と思ったがRubyKaigi takeoutの振り返りも書いてない...

---

タイトルの通り（通り？）、forkしたプロセスがCoWをどれくらい起こしているか可視化するツールを作りました。

github.com

まだ私の理解が浅いところもあるのですが、いったん動作例などを掲示してみます。

hiboma.c の場合

上のhibomaさんのCoWのサンプルプログラムの例です。プロジェクトのmiscというディレクトリ の下に exec_waiter.rb という補助スクリプトを置いてあります。それを経由してプログラムを起動すると、親のPIDを表示して実行が停止します。

cowsnoop/misc$ ruby exec_waiter.rb ./hiboma
Program "./hiboma" is waiting now to be traced.
Please setup your BPF fantastic tools against:
  PID = 198039

Then - hit return to continue

別のターミナルで cowsnoop を起動します。

$ sudo ./mruby/bin/cowsnoop --track-first-clone 198039
Tracking first forked child.

戻って何かキーを押すと hiboma コマンドにexecするので、トレーサの方に戻ると、確かに1秒毎に1回のCoWの発生を検知しています。

mmap: 0x100000000000 
parent pid:198039
child pid:198142
cow address: 0x100000000000
cow address: 0x100000001000
cow address: 0x100000002000
cow address: 0x100000003000                                                                                             
cow address: 0x100000004000
cow address: 0x100000005000
cow address: 0x100000006000
cow address: 0x100000007000
cow address: 0x100000008000
...

[!] Tracking: child pid = 198142
[2021-09-24 15:40:02 +0000]   7: @@@@@@@
[2021-09-24 15:40:03 +0000]   1: @
[2021-09-24 15:40:04 +0000]   1: @
[2021-09-24 15:40:05 +0000]   1: @
[2021-09-24 15:40:06 +0000]   1: @
[2021-09-24 15:40:07 +0000]   1: @
[2021-09-24 15:40:08 +0000]   1: @
[2021-09-24 15:40:09 +0000]   1: @
[2021-09-24 15:40:10 +0000]   1: @
[2021-09-24 15:40:11 +0000]   1: @
[2021-09-24 15:40:12 +0000]   1: @
...

Ruby のスクリプトの場合

以下のようなRubyスクリプトを作ります。ここにもアップしています。

puts "Current pid: #{$$} / Hit key to continue"
gets

$a = [];
p Process.waitpid(fork do
  puts $$
  loop do
    $a << Hash.new
    sleep 0.0001
  end
end)

これを同様に起動し、

$ ruby bigarray.rb
Current pid: 198287 / Hit key to continue

トレースし、

$ sudo ./mruby/bin/cowsnoop --track-first-clone 198287
Tracking first forked child.

元のプログラムの起動を再開します。すると、子プロセス 198357 のCoWの発生を時系列で追うことができます。

[!] Tracking: child pid = 198357
[2021-09-24 15:43:53 +0000]  53: @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[2021-09-24 15:43:54 +0000]   7: @@@@@@@
[2021-09-24 15:43:55 +0000]   3: @@@
[2021-09-24 15:43:56 +0000]   8: @@@@@@@@
[2021-09-24 15:43:57 +0000]   4: @@@@
[2021-09-24 15:43:58 +0000]   7: @@@@@@@
[2021-09-24 15:43:59 +0000]   5: @@@@@
[2021-09-24 15:44:00 +0000]  46: @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[2021-09-24 15:44:01 +0000]   0: 
[2021-09-24 15:44:02 +0000] 383: @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[2021-09-24 15:44:03 +0000]   0: 
[2021-09-24 15:44:04 +0000]   0: 
[2021-09-24 15:44:05 +0000]   0: 
[2021-09-24 15:44:06 +0000]   0: 
[2021-09-24 15:44:07 +0000]   0: 
[2021-09-24 15:44:08 +0000]   0: 
[2021-09-24 15:44:09 +0000]   0: 
[2021-09-24 15:44:10 +0000]   0: 
[2021-09-24 15:44:11 +0000]   0: 
[2021-09-24 15:44:12 +0000]   0: 
[2021-09-24 15:44:13 +0000]  25: @@@@@@@@@@@@@@@@@@@@@@@@@
[2021-09-24 15:44:14 +0000]   0: 
[2021-09-24 15:44:15 +0000]   0: 
[2021-09-24 15:44:17 +0000]   0: 
[2021-09-24 15:44:18 +0000]   1: @
[2021-09-24 15:44:19 +0000]   0: 
...

この時、一緒に親子のVSZ/RSSをトラックすると、最初の方は子プロセスの方がもちろんRSSが小さい状態です。

$ ps auxf | grep -e RSS -e bigarray
USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
vagrant   198287  0.0  0.2  78844 22136 pts/1    S+   15:43   0:00  |           \_ ruby bigarray.rb
vagrant   198357  1.6  0.2  78844 19856 pts/1    S+   15:43   0:00  |               \_ ruby bigarray.rb
vagrant   198369  0.0  0.0   8008   880 pts/2    S+   15:44   0:00              \_ grep --color=auto -e RSS -e bigarray

プログラムの性質上、次第に子プロセスのRSSが肥大化していきます。また、どこかのタイミングでVSZも拡張します。

USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
vagrant   198287  0.0  0.2  78844 22136 pts/1    S+   15:43   0:00  |           \_ ruby bigarray.rb
vagrant   198357  1.8  0.2  79132 20080 pts/1    S+   15:43   0:00  |               \_ ruby bigarray.rb
vagrant   198393  0.0  0.0   8008   816 pts/2    S+   15:44   0:00              \_ grep --color=auto -e RSS -e bigarray

VSZが拡張したあたりで、CoWが一切起こらなくなる（すなわち、親子で共通の領域からはみ出たところにオブジェクトが作られはじめる？）、ということが確認できます。

---

cowsnoopに機能を追加すれば、元々の関心ごとだったunicornがワーカーごとにどれくらいCoWを発生させているのかという点が追いかけられるかもしれません。

ちなみにこのcowsnoopは、いわゆるBPF CO-REのトレースツールですが、mruby + libbpf で書いています。もちろんブリッジするコードはCで書いていますし、またBPFバイナリ部分は普通にというかCから作っています（Rucyはまだ全然実戦投入できません...）。

ですがトレーサのメイン部分をRubyで書けるというのは、僕にとって大変気分の良いことです。

github.com

また、トレーサのようなツールを書く際は結構探索的なコーディングをする傾向がある気がしていて、意外とスクリプト言語で書く需要があるんじゃないかと思います。

RubyKaigi takeout を経て、 Observability of Ruby, by Ruby, for Ruby の掛け声で、Rubyで書けるRubyのパフォーマンス測定ツール群（もちろん他のプログラムもトレースできるでしょう...）を Infrared.rb というプロジェクトで始めることにしました。このブログでもまたいろいろと紹介できればと思います。

github.com