LoginSignup
23
3

More than 3 years have passed since last update.

食べログAdvent Calendar 2019Day 9tabelog
@tsukasa_oishi(おおいし つかさ)in食べログ

実行中のRubyプロセスの中で行われていることを見てみた

Last updated at Posted at 2019-12-08

はじめに

食べログでプログラマをしているおおいしつかさです。
去年もAdventCalendarに参加したのですが、RubyといいつつCのコードしか書かないという体たらく。いけませんいけません。こんなことではいかんのだ。
今年から心を入れ替えてちゃんとRubyのことを書くぞう。:cat2:そういえば12月に入って寒い日だったのですが子供と遊園地行こうとしていまして電車待ちの時間に本屋をのぞいていたと思ってください。そうするとですね、子供がにこにこしてプリキュアのシールセットを持ってきたのですな。なんだか知らないけど700円くらいするのです。これが欲しい。そうか、でもそれを買ったら遊園地に行けなくなるぞう、それでもいいのか。いいよ!と言われたのでなんだか知らないけど700円くらいするプリキュアのシールセットを買ってとんぼ返りで家に帰ってきました。身の引き締まる思いです。

実行中のRubyプロセス

Railsアプリを運用していると、実行中のRubyプロセスの中を見たくなるときがあります。
でも、あらかじめ欲しい情報をログに出力するように仕込んでいないと難しいですよね。
SystemTapを使うと、実行中のプロセスでもその中で行われていることをトレースすることができるようになります。

実際に見てみる

以下のように、エンターを叩くとサイコロを振って進む、わくわくするような「ひとりすごろくゲーム」があるとします。

[block:0 score:0] dice roll: # ここでエンター
6マスすすむ
92点獲得
[block:6 score:92] dice roll: # ここでエンター
2マスすすむ
80点獲得
...
[block:95 score:1521] dice roll: # ここでエンター
5マスすすむ
11点獲得
ゴール!
score: 1532

これはrubyで実装されていて、現在ゲーム進行中だとしましょう。つまり、rubyプロセスが動いているわけです。
ここでSystemTapさんが登場すると以下のような情報を得ることができます。

     0 ruby(89997): -> Sugoroku#dice_roll (sugoroku.rb:54)
    12 ruby(89997):  -> Dice#roll (sugoroku.rb:7)
    24 ruby(89997):  <- Dice#roll (sugoroku.rb:8)
    60 ruby(89997): <- Sugoroku#dice_roll (sugoroku.rb:57)
     0 ruby(89997): -> Sugoroku#calc_score (sugoroku.rb:60)
     5 ruby(89997):  -> Board#score (sugoroku.rb:18)
     8 ruby(89997):  <- Board#score (sugoroku.rb:19)
    16 ruby(89997): <- Sugoroku#calc_score (sugoroku.rb:64)
     0 ruby(89997): -> Sugoroku#goal? (sugoroku.rb:50)
     3 ruby(89997):  -> Board#goal? (sugoroku.rb:22)
     6 ruby(89997):  <- Board#goal? (sugoroku.rb:23)
     9 ruby(89997): <- Sugoroku#goal? (sugoroku.rb:51)

どのメソッドが呼ばれたのかを、ファイル名と行番号付きで表しています。
また、メソッドの中でさらになんのメソッドが呼ばれたのかがインデントでわかるようになっています。メソッドが返っていく様子(<-がそれです)もわかりますね。
各行の最初に表示されている整数は、マイクロ秒を表しいます。0から計測が開始されて、一連のメソッドでどのくらい時間がかかって処理が戻ってきたのかがわかりますね。

この情報を得るために、rubyのコードには一切手を加えていません。rubyのコードは純粋にめちゃつまんないすごろくゲームだけを処理しています。
この情報はSystemTapのコードを書いて動かすことで得ているのです。実際のSystemTapのコードは以下になります。

probe process("path/to/ruby").mark("method__entry") {
  if (pid() == target()) {
      printf("%s -> %s#%s (%s:%d)\n", thread_indent(1), user_string($arg1), user_string($arg2), user_string($arg3), $arg4)
  }
}

probe process("path/to/ruby").mark("method__return") {
  if (pid() == target()) {
    printf("%s <- %s#%s (%s:%d)\n", thread_indent(-1), user_string($arg1), user_string($arg2), user_string($arg3), $arg4)
  }
}

動かすときは以下のようにしています。-xオプションで情報を渡すことができます。コード内のtarget()がそれを返します。
つまり、指定したプロセスIDの場合のみ、出力するようにしているわけです。

# rubyプロセスのプロセスIDが 89997 なら
$ sudo stap ruby_method.stp -x 89997

SystempTapの使い方

SystemTapについては、日本語だとRedHatのサイトが一番参考になるかなと思います。
ネット上にもちょこちょこいろいろ情報があるのでそちらを参考にしてみてください。

他にもメソッドコールは存在するぞう

上のすごろくゲーム、エンターキーの入力を待つのにgetsを使っています。
でもSystemTapの出力にgetsの情報がないですよね？ 正確にはそちらはrubyで書かれたメソッドではなくて、C言語で書かれているので mark("method__entry")では拾えなかったのです。
Cで書かれたメソッドの呼び出しも拾いたいときは、mark("cmethod__entry")を使います。

     0 ruby(90886): <- ARGF.class#gets (sugoroku.rb:37)
    17 ruby(90886): <- Kernel#gets (sugoroku.rb:37)
    25 ruby(90886): -> Sugoroku#dice_roll (sugoroku.rb:54)
    30 ruby(90886): -> Dice#roll (sugoroku.rb:7)
     0 ruby(90886): -> Kernel#rand (sugoroku.rb:7)
    13 ruby(90886): <- Kernel#rand (sugoroku.rb:7)
     0 ruby(90886): <- Dice#roll (sugoroku.rb:8)
     4 ruby(90886): -> Integer#to_s (sugoroku.rb:56)
     0 ruby(90886): <- Integer#to_s (sugoroku.rb:56)
    12 ruby(90886): -> Kernel#puts (sugoroku.rb:56)
     0 ruby(90886): -> IO#puts (sugoroku.rb:56)
     8 ruby(90886):  -> IO#write (sugoroku.rb:56)
    31 ruby(90886):  <- IO#write (sugoroku.rb:56)
    34 ruby(90886): <- IO#puts (sugoroku.rb:56)
     0 ruby(90886): <- Kernel#puts (sugoroku.rb:56)
     3 ruby(90886): <- Sugoroku#dice_roll (sugoroku.rb:57)
     7 ruby(90886): -> Sugoroku#calc_score (sugoroku.rb:60)
    11 ruby(90886): -> Board#score (sugoroku.rb:18)
     0 ruby(90886): <- Board#score (sugoroku.rb:19)
     3 ruby(90886): -> Integer#to_s (sugoroku.rb:63)
     0 ruby(90886): <- Integer#to_s (sugoroku.rb:63)
     4 ruby(90886): -> Kernel#puts (sugoroku.rb:63)
     0 ruby(90886): -> IO#puts (sugoroku.rb:63)
     3 ruby(90886):  -> IO#write (sugoroku.rb:63)
     9 ruby(90886):  <- IO#write (sugoroku.rb:63)
    11 ruby(90886): <- IO#puts (sugoroku.rb:63)
     0 ruby(90886): <- Kernel#puts (sugoroku.rb:63)
     3 ruby(90886): <- Sugoroku#calc_score (sugoroku.rb:64)
     6 ruby(90886): -> Sugoroku#goal? (sugoroku.rb:50)
    10 ruby(90886): -> Board#goal? (sugoroku.rb:22)
     0 ruby(90886): <- Board#goal? (sugoroku.rb:23)
     2 ruby(90886): <- Sugoroku#goal? (sugoroku.rb:51)
     6 ruby(90886): -> Integer#to_s (sugoroku.rb:36)
     8 ruby(90886): <- Integer#to_s (sugoroku.rb:36)
    10 ruby(90886): -> Integer#to_s (sugoroku.rb:36)
    13 ruby(90886): <- Integer#to_s (sugoroku.rb:36)
    17 ruby(90886): -> Kernel#print (sugoroku.rb:36)
    20 ruby(90886): -> IO#write (sugoroku.rb:36)
     0 ruby(90886): <- IO#write (sugoroku.rb:36)
     2 ruby(90886): <- Kernel#print (sugoroku.rb:36)
     5 ruby(90886): -> Kernel#gets (sugoroku.rb:37)
     8 ruby(90886): -> ARGF.class#gets (sugoroku.rb:37)

これですべてのメソッド呼び出しを追えるようになりました。

コードに手を加えなくていいというのは嘘でした!

実はruby2.5からは、rubyのコードに手を加えないと method__entryは拾えません(cmethod__entryは拾えます)。
以下のコードが必要になります。

TracePoint.new{}.enable

ruby2.5からは、パフォーマンス向上のためにTracePointはdisableになっているからです。
ちなみにTracePointを使っても、メソッド呼び出しを拾うことができますよ。

rubyで使えるprobeの一覧

RubyにはDTraceのprobeが組み込まれています。これをSystemTapから使うことができるのです。
手元のruby2.6.5で見てみたところ、以下のprobeが表示されました。だいたい名前から、どういうものかは想像がつきますね。

$ sudo stap -L 'process("path/to/ruby").mark("*")'
process("/home/oishi_t/local/bin/ruby").mark("array__create") $arg1:long $arg2:long $arg3:long
process("/home/oishi_t/local/bin/ruby").mark("cmethod__entry") $arg1:long $arg2:long $arg3:long $arg4:long
process("/home/oishi_t/local/bin/ruby").mark("cmethod__return") $arg1:long $arg2:long $arg3:long $arg4:long
process("/home/oishi_t/local/bin/ruby").mark("find__require__entry") $arg1:long $arg2:long $arg3:long
process("/home/oishi_t/local/bin/ruby").mark("find__require__return") $arg1:long $arg2:long $arg3:long
process("/home/oishi_t/local/bin/ruby").mark("gc__mark__begin")
process("/home/oishi_t/local/bin/ruby").mark("gc__mark__end")
process("/home/oishi_t/local/bin/ruby").mark("gc__sweep__begin")
process("/home/oishi_t/local/bin/ruby").mark("gc__sweep__end")
process("/home/oishi_t/local/bin/ruby").mark("hash__create") $arg1:long $arg2:long $arg3:long
process("/home/oishi_t/local/bin/ruby").mark("load__entry") $arg1:long $arg2:long $arg3:long
process("/home/oishi_t/local/bin/ruby").mark("load__return") $arg1:long $arg2:long $arg3:long
process("/home/oishi_t/local/bin/ruby").mark("method__cache__clear") $arg1:long $arg2:long $arg3:long
process("/home/oishi_t/local/bin/ruby").mark("method__entry") $arg1:long $arg2:long $arg3:long $arg4:long
process("/home/oishi_t/local/bin/ruby").mark("method__return") $arg1:long $arg2:long $arg3:long $arg4:long
process("/home/oishi_t/local/bin/ruby").mark("object__create") $arg1:long $arg2:long $arg3:long
process("/home/oishi_t/local/bin/ruby").mark("parse__begin") $arg1:long $arg2:long
process("/home/oishi_t/local/bin/ruby").mark("parse__end") $arg1:long $arg2:long
process("/home/oishi_t/local/bin/ruby").mark("raise") $arg1:long $arg2:long $arg3:long
process("/home/oishi_t/local/bin/ruby").mark("require__entry") $arg1:long $arg2:long $arg3:long
process("/home/oishi_t/local/bin/ruby").mark("require__return") $arg1:long $arg2:long $arg3:long
process("/home/oishi_t/local/bin/ruby").mark("string__create") $arg1:long $arg2:long $arg3:long
process("/home/oishi_t/local/bin/ruby").mark("symbol__create") $arg1:long $arg2:long $arg3:long

さらに奥深くみる

もっと奥深く見てみることにしましょう。
たとえば、rubyのStringオブジェクトが生成されたとき、内部的にはstr_new0というCの関数が呼ばれています。ここを捉えてみましょう。

probe process("path/to/ruby").function("str_new0") {
  if (pid() == target()) {
    printf("char:%s\n", user_string_n($ptr, $len))
  }
}

すごろくゲームが以下のような出力をしたとき、

6マスすすむ
42点獲得
[block:11 score:48] dice roll:

SystemTapの出力は以下となります。

char:6
char:6マスすすむ
char:42
char:42点獲得
char:11
char:48

すごろくゲームが該当の文字を出力している箇所のコードは以下のようなものです。

puts "#{v}マスすすむ"
puts "#{s}点獲得"
print "[block:#{@block} score:#{@score}] dice roll:"

このように関数が呼ばれたときのその引数の値を見ることができるのです。

さらに guruモードを使うとその引数の値を変更することもできます!

probe process("/home/oishi_t/local/bin/ruby").function("str_new0") {
  if (pid() == target()) {
    $len = -1
  }
}

文字列の長さを-1にしてしまいました。すごろくゲームは以下のような例外を吐くようになります。

sugoroku.rb:38:in `gets': negative string size (or size too big) (ArgumentError)

まさにguruモードです。やばすぎる。

拾うことができるrubyの関数

以下のコマンドで一覧が表示されます。

$ sudo stap -L 'process("path/to/ruby").function("*")'
process("/home/oishi_t/local/bin/ruby").function("ADD_ELEM@/home/oishi_t/local/src/ruby-2.6.5/compile.c:545")
process("/home/oishi_t/local/bin/ruby").function("APPEND_ELEM@/home/oishi_t/local/src/ruby-2.6.5/compile.c:557")
process("/home/oishi_t/local/bin/ruby").function("APPEND_LIST@/home/oishi_t/local/src/ruby-2.6.5/compile.c:1027")
process("/home/oishi_t/local/bin/ruby").function("BSD__sfvwrite@/home/oishi_t/local/src/ruby-2.6.5/vsnprintf.c:243") $fp:rb_printf_buffer* $uio:struct __suio* $len:size_t
process("/home/oishi_t/local/bin/ruby").function("BSD__sprint@/home/oishi_t/local/src/ruby-2.6.5/vsnprintf.c:321")
process("/home/oishi_t/local/bin/ruby").function("BSD__ultoa@/home/oishi_t/local/src/ruby-2.6.5/vsnprintf.c:429") $octzero:int $base:int $endp:char* $val:long unsigned int
process("/home/oishi_t/local/bin/ruby").function("BSD_vfprintf@/home/oishi_t/local/src/ruby-2.6.5/vsnprintf.c:539") $fp:rb_printf_buffer* $fmt0:char const* $ap:va_list $PRI_EXTRA_MARK_LEN:int const $sign:char $expt:int $expstr:char[] $ulval:long unsigned int $fieldsz:long int $uio:struct __suio $iov:struct __siov[] $buf:char[] $ox:char[] $blanks:char[] const $zeroes:char[] const
process("/home/oishi_t/local/bin/ruby").function("Balloc@/home/oishi_t/local/src/ruby-2.6.5/util.c:1086")
process("/home/oishi_t/local/bin/ruby").function("Bfree@/home/oishi_t/local/src/ruby-2.6.5/util.c:1121")
...(省略。めっちゃいっぱいあります)

たいていの関数には触れます。

パフォーマンスに与える影響

シンプルなRailsプロセスを作って、abでアクセスしてパフォーマンスを計測してみます。
SystemTapがうごいているときとそうでないときとで違いを見てみようという魂胆です。SystemTapはcmethod__entryとcmethod__returnを拾ってみます。

# SystemTapが動いていないとき
Requests per second:    36.43 [#/sec] (mean)

# SystemTapが動いているとき
Requests per second:    10.07 [#/sec] (mean)

oh...。トレースはほどほどにしたほうがよさそうです。
すべてのCで書かれたメソッドをトレースしてprintfしているのでこの値なのかもしれません。何も処理をしなかったらどうでしょうか。

Requests per second:    15.12 [#/sec] (mean)

トレースはほどほどに!

カーネル内の動きを追う

SystemTapはカーネル内部の動きも追うことができます。というか、そちら(カーネルの挙動の調査)が本職です。
上であげたRedHatのサイトに、ソケット関数を追うコードが載っているのでそれを動かしてみます。

probe kernel.function("*@net/socket.c").call {
  if (pid() == target()) {
    printf ("%s -> %s\n", thread_indent(1), probefunc())
  }
}

probe kernel.function("*@net/socket.c").return {
  if (pid() == target()) {
    printf ("%s <- %s\n", thread_indent(-1), probefunc())
  }
}

以下のような出力になります。

    0 ruby(94503): -> sock_poll
     8 ruby(94503): <- do_select
     0 ruby(94503): -> sys_accept4
     3 ruby(94503):  -> sockfd_lookup_light
     4 ruby(94503):  <- sys_accept4
     6 ruby(94503):  -> sock_alloc
     9 ruby(94503):   -> sock_alloc_inode
    12 ruby(94503):   <- alloc_inode
    15 ruby(94503):  <- sys_accept4
    17 ruby(94503):  -> sock_alloc_file
    21 ruby(94503):  <- sys_accept4
    24 ruby(94503):  -> move_addr_to_user
    26 ruby(94503):  <- sys_accept4
    27 ruby(94503): <- tracesys

この場合のabテストの結果は以下のとおりです。

Requests per second:    31.94 [#/sec] (mean)

悪くありませんね。

こうして年は暮れていきます

なんだかまたrubyのコードを書いていない気がしないでもありません(すごろくゲームは作ったよ!)。
明日は @fdash の「Android StudioのBreakpoints再入門」になります。お楽しみに!

23
3
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
23
3