とりあえずまとめておく。コレも便利だぜ、とかあったら教えてください
[C] gdb
まずはなにはともあれ 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
bt の出力はこんなかんじ https://gist.github.com/sonots/10803036
[C] gstack
gdb で全スレッドのスタックレースをダンプさせようと思うとめんどくさいが、gstack を使うとできる。
$ sudo gstack <pid>
ただし、core ファイルに対しては適用できない。 pstack というツールもあるらしいが、私の環境だと全く同じものだった(gstack へのシンボリックリンクだった)。
出力はこんなかんじ https://gist.github.com/sonots/f58f632c9e7a5786aa05
[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
[Ruby] sigdump
https://github.com/frsyuki/sigdump
ruby レベルでの全スレッドのスタックトレースをダンプすることができる。gstack の ruby レベル版と言えるか。ついでに、ObjectSpace の状態(どのクラスのインスタンスが何個存在しているかなど）もダンプできる。
require 'sigdump/setup'
しておき、kill -CONT すると、/tmp/sigdump-.log のようなファイルに出力される。
出力はこんなかんじ https://gist.github.com/sonots/e05d8fbcd7ab39e4a5f8
コードに仕込んで好きなところでダンプしたい場合は
Sigdump.dump
を呼び出せばできる。=> sigdump.rb#L13
特にコードを遅くするようなこともないので、とりあえず require しておくのが吉。
[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
[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
[Ruby] tracer
on してから off するまでの ruby レベルの実行をすべてトレース出力するには、 標準ライブラリ tracerを利用できる。
require 'tracer'
# 好きなタイミングでスタートする
Tracer.on
# 好きなタイミングで終了する
Tracer.off
処理が進むたびに逐次出力される。
試しに require 'uri' をトレースした出力はこんなかんじ https://gist.github.com/sonots/551689f166e9b3cf4aa4
[Ruby] stackprof
https://github.com/tmm1/stackprof
これも Ruby レベルのプロファイラ。Ruby 2.1 時代のプロファイラらしい。
たとえば rack middleware としてこんなかんじで仕込んでおいて、1s ごとにプロファイリングしたりできるようだ。 もちろん普通に ruby コードとしてプロファイリングする期間を指定して出力を得ることもできる。
# config.ru
use StackProf::Middleware, enabled: true,
mode: :cpu,
interval: 1000,
save_every: 5
メソッドを指定して、そのメソッドのみのプロファイリング、そのメソッドを呼んでいるやつなどを特定できる。呼んでいるやつがわかるの便利。
$ 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
作者のこちらのブログが非常にわかりやすいので一読をすすめる => http://tmm1.net/ruby21-profiling/