まとめておく。コレも便利だぜ、とかあったら教えてください
1. [C] gdb
まずはなにはともあれ gdb。例えば指定スレッドのCレベルでのバックトレースを表示させるにはこんなかんじ。
$ sudo gdb -p <pid>
(gdb) info thread
(gdb) thread 14
(gdb) bt
core を吐かせておいてから追う場合はこう
$ sudo gcore <pid>
$ gdb /usr/lib64/fluent/ruby/bin/ruby core.22111
(gdb) info thread
(gdb) thread 14
(gdb) bt
出力端折ったけど、こんなかんじ https://gist.github.com/sonots/10803036
2. [C] gstack
gdb で全スレッドのバックトレースをダンプさせようと思うとめんどくさいが、gstack を使うとできる。
$ sudo gstack <pid>
ただし、core ファイルに対しては適用できない。
pstack というツールもあるらしいが、私の環境だと全く同じものだった(gstack へのシンボリックリンクだった)。
出力はこんなかんじ https://gist.github.com/sonots/f58f632c9e7a5786aa05
3. [C] strace
実行中プロセスのシステムコールを追い続けるには strace を使おう。
$ strace -s 1024 -f -p <pid>
スレッドを追いたい場合は -f をつける。瞬間のダンプではないので処理がすすめば出力は更新される。
出力はこんなかんじ https://gist.github.com/sonots/8020037
strace については以前書いたやつもあるのでそちらも見てもらえると良い => http://blog.livedoor.jp/sonots/archives/18193659.html
4. [Ruby] gdbruby
https://github.com/gunyarakun/gdbruby
生きているプロセスならば次に記載している sigdump など、他にも ruby レベルのバックトレースを表示するツールがあるが、core ファイルから ruby レベルのバックトレースを表示できるのは gdbruby だけ。
gdbruby.rb core.24113 `rbenv which ruby`
出力サンプルは gunyarakun さんのブログをみると書いてある
=> http://blog.wktk.co.jp/ja/entry/2013/10/30/gdbruby
https://github.com/frsyuki/sigdump
ruby レベルでの全スレッドのバックトレースをダンプすることができる。gstack の ruby レベル版と言えるか。ついでに、ObjectSpace の状態(どのクラスのインスタンスが何個存在しているかなど）もダンプできる。
使い方はダンプしたいアプリのコードで
require 'sigdump/setup'
と require しておき、kill -CONT <pid> すると、/tmp/sigdump-<pid>.log のようなファイルに出力される。
出力はこんなかんじ https://gist.github.com/sonots/e05d8fbcd7ab39e4a5f8
なお、コードに仕込んで好きなところでダンプしたい場合は
Sigdump.dump
を呼び出せばできる。=> sigdump.rb#L13
特にコードを遅くするようなこともないので、とりあえず require しておいてよさそう。
6. [Ruby] rbtrace
https://github.com/tmm1/rbtrace
rbtrace は ruby レベルでの strace のようなもの、とのこと。strace 同様、処理が進めば更新される。
trace 対象のアプリで require しておき、
require 'rbtrace'
$ rbtrace -p <pid> --firehose
とかやると追える。※ require すると外から rbtrace で attach できるようになるようだ。内部的には POSIX message queue を使っているっぽい。
firehose は全出力のオプションで以下のようになる。
Kernel#proc <0.000006>
Proc#call
Dir.chdir
Dir.pwd <0.000004>
Process.pid <0.000003>
String#multiply_vowels
String#gsub
String#* <0.000192>
String#* <0.000003>
String#gsub <0.000585>
String#multiply_vowels <0.000593>
Kernel#rand <0.000003>
Kernel#sleep <0.239254>
Dir.chdir <0.239933>
Proc#call <0.239947>
-m で特定メソッドにしぼったり、--slow で遅いやつだけ出力したりもできる。
=> 詳細は README を読もう https://github.com/tmm1/rbtrace
7. [Ruby] profile
どのメソッドを何回呼び出したのか、平均で何秒かかったのかプロファイリングするには、標準ライブラリの profile を利用できる。
普通に require すると、その瞬間にスタートして、終了時に print する動きをするので、任意の期間に仕込みたい場合は、 profile ではなく profiler を require して以下のようにする。
require 'profiler'
RubyVM::InstructionSequence.compile_option = {
:trace_instruction => true,
:specialized_instruction => false
}
# 好きなタイミングで start する
Profiler__::start_profile
# print して終了する
Profiler__::print_profile(STDERR)
Profiler__::stop_profile
出力はこんなかんじ
% cumulative self self total
time seconds seconds calls ms/call ms/call name
100.00 0.01 0.01 2 5.00 5.00 Hoge.fuga
0.00 0.01 0.00 2 0.00 0.00 IO#puts
0.00 0.01 0.00 1 0.00 0.00 TracePoint#enable
0.00 0.01 0.00 4 0.00 0.00 IO#write
0.00 0.01 0.00 2 0.00 0.00 Fixnum#to_s
0.00 0.01 0.00 2 0.00 0.00 Kernel#puts
0.00 0.01 0.00 4 0.00 2.50 nil#
0.00 0.01 0.00 1 0.00 10.00 Range#each
0.00 0.01 0.00 1 0.00 0.00 TracePoint#disable
0.00 0.01 0.00 1 0.00 10.00 #toplevel
8. [Ruby] tracer
on してから off するまでの ruby レベルの実行をすべてトレース出力するには、 標準ライブラリ tracerを利用できる。
require 'tracer'
# 好きなタイミングでスタートする
Tracer.on
# 好きなタイミングで終了する
Tracer.off
処理が進むたびに逐次出力される。
試しに require 'uri' をトレース出力したのはこんなかんじ
=> https://gist.github.com/sonots/551689f166e9b3cf4aa4
9. [Ruby] stackprof
https://github.com/tmm1/stackprof
これも Ruby レベルのプロファイラ。Ruby 2.1 時代のプロファイラだそうで、ruby 2.1 から入った rb_profile_frames() API を使っているらしい。ruby 標準の profile は正直大分時間と負荷がかかるけれど、こちらだと本番でもイケるらしい。ホントか。
たとえば rack middleware としてこんなかんじで仕込んでおいて、1s ごとにプロファイリングしたりできるようだ。 もちろん普通に ruby コードとしてプロファイリングする箇所を指定して出力を得ることもできる。
# config.ru
use StackProf::Middleware, enabled: true,
mode: :cpu,
interval: 1000,
save_every: 5
コード区間を指定する場合
require 'stackprof'
StackProf.start
// code
StackProf.stop
StackProf.results('/tmp/stackprof.dump')$ stackprof tmp/stackprof-cpu-*.dump
==================================
Mode: cpu(1000)
Samples: 711 (1.52% miss rate)
GC: 119 (16.74%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
465 (65.4%) 95 (13.4%) Coolio::IO#on_readable
332 (46.7%) 70 (9.8%) Fluent::MeasureTime#measure_time
513 (72.2%) 48 (6.8%) Coolio::Loop#run
30 (4.2%) 30 (4.2%) Fluent::EngineClass#now
以下略
SAMPLING が自身自身が呼ばれた回数、TOTAL が自分自身とそこから呼び出しているメソッド(child) を含めた回数を示しているようだ。pct はそれぞれ percentage。
さらにメソッドを指定して、そのメソッドのみのプロファイリングができる。そのメソッドを呼んでいるやつを特定したりできる。呼んでいるやつがわかるというのは便利。
$ stackprof tmp/stackprof-cpu-*.dump --method 'String#blank?'
String#blank? (gems/activesupport-2.3.14.github30/lib/active_support/core_ext/object/blank.rb:80)
samples: 1595 self (2.6%) / 1660 total (2.7%)
callers:
373 ( 41.0%) ApplicationHelper#current_user
192 ( 21.1%) ApplicationHelper#current_repository
callers:
803 ( 48.4%) Object#present?
code:
| 80 | def blank?
1225 (2.0%) / 1225 (2.0%) | 81 | self !~ /[^[:space:]]/
| 82 | end
作者のこちらのブログで作者の職場である GitHub での事例を元に使い方を教えてくれていて、非常にわかりやすいので一読をすすめる => http://tmm1.net/ruby21-profiling/
rbtrace も同じ作者だけど、tmm1 氏はいろんなの持ってる。
(追加) 10. [Ruby] memprof2
https://github.com/sonots/memprof2
Ruby レベルのヒープ(メモリ)プロファイラ。Ruby 2.1 から入った trace_object_allocations API を使っている。
使い方はこんな感じで、Memprof2.start と Memprof2.stop で囲った範囲内で、どの行がどのぐらいメモリを消費しているか調べることができる。
# example.rb
require 'memprof2'
Memprof2.start
foo = ["foo"] * 255 # 調べたいやつ
Memprof2.report
Memprof2.stop$ ruby example.rb
2080 example.rb:3:Array
40 example.rb:3:Array
40 example.rb:3:String
詳細な説明については Ruby でラインメモリプロファイラ の記事に書いている。
メモ追記:
10. [Ruby] GCにかかった時間を追う http://docs.ruby-lang.org/ja/2.1.0/class/GC=3a=3aProfiler.html
11. [Ruby] メモリ allocation を追うやつ https://github.com/csfrancis/alloc_track
12. [C] pmap: report memory map of process https://gist.github.com/sonots/ffe105fdcb6d48c1142c
