RubyKaigi 2015 Keynote

Transcript

1. Linux loves Ruby Ruby loves Linux How to debug your linux box KOSAKI Motohiro Linux kernel hacker
2. Who am I  Live in Boston  Linux Kernel core developer  Ruby core team  Ruby linuxport maintainer  Japan OSS contributor award  One of current Linux VM authors  etc..
3. Linux FS, Storage and MM Summit
4. What is linuxport maintainer?
5. Example: tcp select Fixed at commit d84ba638e4ba3c40023ff997aa5e8d3ed002af36 tcp: select(writefds) don't hang up when a peer close connection
6. Example: fadvise on tmpfs Linux kernel commit 3d3727cdb07ff17ddc3c551ef8d03d37b60a0372 "mm, fadvise: don't return -EINVAL when filesystem cannot implement fadvise()"
7. Example: Btrfs readdir failed Fixed at commit 3765fefaee2da83f10829fa64a74e6b7360350cb “btrfs: fix d_off in the first dirent”
8. I’m a bridge engineer between Linux and Ruby
9. How to push your patches to OSS commnity Plan B Plan C Plan D Plan A Big messy patch Clean patch set Plan E Patch for open source is like a Tetris
10. Impressions from other Ruby committers
11. Matz’s impression Oops ＼(^o^)／
12. @nalsh’s impression Oops ＼(^o^)／
13. Today’s topic Linux has a lot of debugging facilities. But many Rubyist don’t case. The Debugging Big 3 Ftrace Perf tools SystemTap
14. Ftrace # cd /sys/kernel/debug/tracing # echo 1 > events/sched/sched_switch/enable # echo 1 > /sys/kernel/debug/tracing/tracing_on # cat trace <idle>-0 [003] d... 863621.584712: sched_switch: prev_comm= swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=gnome-shell next_pid=3233 next_prio=120 gnome-shell-3200 [000] d... 863621.584721: sched_switch: prev_comm=gnome-shell prev_pid=3200 prev_prio=120 prev_state=S ==> next_comm=gnome-shell next_pid=3231 next_prio=120 Example: collect context switch result
15. #perf top
16. #perf trace Like strace, but system wide
17. Perf record and report
18. Perf record and report (cont)
19. What is SystemTap? SystemTap is the worst debugging tool except all those other tools that have been tried from time to time. -- Winston Churchill Terrible language spec and useful debugging facilities
20. SystemTap: c-callgraph global depth function trace(entry_p) { printf("%*s%s%s¥n", depth, "", (entry_p>0 ? "->“ : "<-"), ppfunc()) } probe process("./foo_bar_baz").function("*").call { depth += 2; trace(1) } probe process("./foo_bar_baz").function("*").return { trace(-1); depth-=2 } int foo(int i) { return i+1; } int bar(int i) { return foo(i+1); } int baz(int i) { return bar(i+1); } int main(void) { return baz(1); } Foo_bar_baz.c c-callgraph.stp
21. SystemTap c-callgraph # sudo stap ./c-callgraph.stp -c ./foo_bar_baz ->main ->baz ->bar ->foo <-foo <-bar <-baz <-main
22. Example: ruby-callgraph def foo; end def bar; foo; end def baz; bar; end Baz foo_bar_baz.rb global depth function trace(entry_p, clazz, method) { printf("%*s%s%s:%s¥n", depth, "", (entry_p>0? "->“ : "<-"), clazz, method) } probe process("/…/libruby.so.2.3").provider("ruby"). mark("method__entry") { depth+=2 trace(1, user_string($arg1), user_string($arg2)) } probe process("/…/libruby.so.2.3"). provider("ruby").mark("method__return") { trace(-1, user_string($arg1), user_string($arg2)) depth-=2 } ruby_callgraph.stp
23. result #sudo stap -W ./ruby_callgraph.stp -c “./ruby --disable- gems ./foo_bar_baz.rb“ ->Object:baz ->Object:bar ->Object:foo <-Object:foo <-Object:bar <-Object:baz
24. Result2: remove -–disable-gems #sudo stap -W ./ruby_callgraph.stp -c “./ruby ./foo_bar_baz.rb“ (snip) <-MonitorMixin:mon_check_owner <-MonitorMixin:mon_exit <-Kernel:require ->Object:baz ->Object:bar ->Object:foo <-Object:foo <-Object:bar <-Object:baz No indent??
25. Kernel.#require is not Ruby method! diff --git a/vm.c b/vm.c index 1a43061..2af4dcf 100644 --- a/vm.c +++ b/vm.c @@ -1666,7 +1666,7 @@ vm_exec(rb_thread_t *th) EXEC_EVENT_HOOK(th, RUBY_EVENT_C_RETURN, th->cfp->self, rb_vm_frame_method_entry(th->cfp)->called_id, rb_vm_frame_method_entry(th->cfp)->owner, Qnil); - RUBY_DTRACE_METHOD_RETURN_HOOK(th, + RUBY_DTRACE_CMETHOD_RETURN_HOOK(th, rb_vm_frame_method_entry(th->cfp)- >owner, rb_vm_frame_method_entry(th->cfp)- >called_id);
26. Fixed ->Gem:use_gemdeps <-Gem:use_gemdeps ->Kernel:require (snip) <-Kernel:require ->Object:baz ->Object:bar ->Object:foo <-Object:foo <-Object:bar <-Object:baz
27. Example: callgraph2 (C + Ruby) def foo Dir.glob(”*”); end def bar; foo; end def baz; bar; end Baz foo_bar_baz2.rb global depth function trace(entry_p, clazz, method) { printf("%*s%s%s:%s¥n", depth, "", (entry_p>0?"->":"<-"), clazz, method) } probe process("/…/libruby.so.2.3").provider("ruby"). mark("method__entry") { depth+=2 trace(1, user_string($arg1), user_string($arg2)) } (snip) probe syscall.getdents { printf("%*s->%s(%s)¥n", depth, "", name, argstr) } ruby_callgraph2.stp
28. result ->Object:baz ->Object:bar ->Object:foo ->getdents(8, 0x1eb4080, 32768) ->getdents(8, 0x1eb4080, 32768) <-Object:foo <-Object:bar <-Object:baz
29. Example2: require “time” require "time" require_time.rg find_require_entry.stp probe process("/home/kosaki/local/ruby-dtrace/lib/libruby.so.2.3"). provider("ruby").mark("find__require__entry") { loaded_file=user_string($arg1) source_file=user_string($arg2) source_line=$arg3 printf("%s %s %d¥n", loaded_file, source_file, source_line) }
30. Result: sample1 #sudo stap ./find_require-entry.stp -c “./ruby --disable-gems ./require_time.rb“ enc/encdb.so /home/kosaki/ruby/bin/ruby 0 enc/trans/transdb.so /home/kosaki/ruby/bin/ruby 0 unicode_normalize <internal:enc/prelude> 4 time ./require_time.rb 1 date /home/kosaki//ruby/lib/ruby/2.3.0/time.rb 3 date_core /home/kosaki//ruby/lib/ruby/2.3.0/date.rb 3
31. Result: example2 #sudo stap ./find_require-entry.stp -c “./ruby --disable-gems ./require_time.rb“ enc/encdb.so /home/kosaki/ruby/bin/ruby 0 enc/trans/transdb.so /home/kosaki/ruby/bin/ruby 0 unicode_normalize <internal:enc/prelude> 4 time ./require_time.rb 1 date /home/kosaki//ruby/lib/ruby/2.3.0/time.rb 3 date_core /home/kosaki//ruby/lib/ruby/2.3.0/date.rb 3 ???
32. ruby/dmyenc.c void Init_enc(void) { if (require("enc/encdb.so") == 1) { require("enc/trans/transdb.so"); } } encdb.so is required from C source.
33. YARV: how to find line number 0000100111 1101011010 0000011100 iseq (VM命令列） iseq_line_info_entry[] POS LINE 4 10 16 15 … … Something like machine code コンパイルするときに 対応表を一緒につくっておく
34. 調査結果  encdb.so, transdb.so はC言語から require されている特殊なファイルであることがわかっ た  YARVのCFPは行番号を逆引きするためのテーブ ルをコンパイル時につくっていることが分かっ た  CFPはC言語のことなんか知りません  ＼(^o^)／
35. Someone famous said 原理的にRubyで書けることはCでも書けます．Ruby そのものがCで記述されているんですから，当然とい えば当然なんですけど． -- まつもとゆきひろ What Ruby can do is actually what C lang can do. Because CRuby is written by C lang, it's a matter of course. -- Matz ruby/doc/extension.ja.rdoc
36. SIGSEGV case #0 0x40035431 in kill () from /lib/libc.so.6 #1 0x4003507e in raise () from /lib/libc.so.6 #2 0x4003672f in abort () from /lib/libc.so.6 #3 0x080dabb0 in rb_bug (fmt=0x80f8816 "Segmentation fault") at error.c:179 #4 0x080b766f in sigsegv (sig=11) at signal.c:412 #5 0x40035338 in sigaction () from /lib/libc.so.6 #6 0x0805d4d4 in call_cfunc (func=0x80c063c <rb_str_split_m>, ファイル名も行番号もデバッガは取れてる。やれば出来る
37. 方針  Cの世界では呼び出し元アドレスはスタックに 格納されている。スタック読めば場所は（人間 には読めない形式で）分かる  Linuxの実行ファイル（ELF）と、デバッグ情報 ファイル（DWARF）はちゃんと読めばファイ ル名も行番号もとれる  RubyはSEGV時の表示のためにすでに類似処理 がある  なんとかなりそう・・
38. Done -rb_require_internal(VALUE fname, int safe) +rb_require_internal2(VALUE fname, int safe, const char* caller_filename, int caller_lineno) { volatile int result = -1; rb_thread_t *th = GET_THREAD(); @@ -959,7 +959,8 @@ rb_require_internal(VALUE fname, int safe) } volatile saved; char *volatile ftptr = 0; - RUBY_DTRACE_HOOK(REQUIRE_ENTRY, StringValuePtr(fname)); + RUBY_DTRACE_HOOK_LOCATION(REQUIRE_ENTRY, StringValuePtr(fname), + caller_filename, caller_lineno); TH_PUSH_TAG(th); saved.safe = rb_safe_level(); @@ -972,12 +973,14 @@ rb_require_internal(VALUE fname, int safe) FilePathValue(fname); rb_set_safe_level_force(0); - RUBY_DTRACE_HOOK(FIND_REQUIRE_ENTRY, StringValuePtr(fname)); + RUBY_DTRACE_HOOK_LOCATION(FIND_REQUIRE_ENTRY, StringValuePtr(fname), + caller_filename, caller_lineno); path = rb_str_encode_ospath(fname); found = search_required(path, &path, safe); - RUBY_DTRACE_HOOK(FIND_REQUIRE_RETURN, StringValuePtr(fname)); + RUBY_DTRACE_HOOK_LOCATION(FIND_REQUIRE_RETURN, StringValuePtr(fname), + caller_filename, caller_lineno); if (found) { if (!path || !(ftptr = load_lock(RSTRING_PTR(path)))) {
39. 結果 # sudo stap ./find_require-entry.stp -c "./ruby-dtrace --disable- gems ./require_time.rb" enc/encdb.so ../dmyenc.c 6 enc/trans/transdb.so ../ruby.c 1450 unicode_normalize <internal:enc/prelude> 4 time ./require_time.rb 1 date /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/time.rb 3 date_core /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/date.rb 3
40. Remove –disable-rubygems enc/encdb.so ../dmyenc.c 6 enc/trans/transdb.so ../ruby.c 1450 unicode_normalize <internal:enc/prelude> 4 rubygems.rb <internal:gem_prelude> 4 rbconfig /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems.rb 8 thread /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems.rb 9 rubygems/compatibility /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems.rb 16 rubygems/defaults /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems.rb 18 rubygems/deprecate /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems.rb 19 rubygems/errors /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems.rb 20 rubygems/specification /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems.rb 1228 rubygems/version /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems/specification.rb 9 rubygems/requirement /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems/specification.rb 10 rubygems/version /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems/requirement.rb 1 rubygems/deprecate /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems/requirement.rb 2 rubygems/platform /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems/specification.rb 11 rubygems/deprecate /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems/platform.rb 1 rubygems/deprecate /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems/specification.rb 12 rubygems/basic_specification /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems/specification.rb 13 rubygems/stub_specification /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems/specification.rb 14 rubygems/util/list /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems/specification.rb 15 stringio /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems/specification.rb 16 rubygems/exceptions /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems.rb 1231 rubygems/defaults/operating_system /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems.rb 1240 rubygems/defaults/ruby /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems.rb 1249 rubygems/core_ext/kernel_gem /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems.rb 1259 rubygems/core_ext/kernel_require /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems.rb 1260 monitor /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb 7 thread /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/monitor.rb 9 did_you_mean /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb 54 rubygems/path_support /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb 54 time /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb 54 date /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb 54 date_core /home/kosaki/local/ruby-dtrace/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb 54
41. Zooming (snip) thread /home/kosaki/ruby/lib/ruby/2.3.0/monitor.rb 9 did_you_mean /home/kosaki/ruby/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb 54 rubygems/path_support /home/kosaki/ruby/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb 54 time /home/kosaki/ruby/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb 54 date /home/kosaki/ruby/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb 54 date_core /home/kosaki/ruby/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb 54 なんということでしょう。 すべてのライブラリはrubygems経由で呼び出されているとし か分からない
42. 解決案  おそらく kernel.#require にオプション引数で オリジナルのソースファイル名、行番号を渡す ようにするしかないのではないか？  それか、rubygemsにDTRACEHOOKを代わり に呼び出してもらう  近日中に議論
43. RECAP  Linuxport mainatainer という役割がなにをす るものであるかを紹介した  Linuxのデバッグツール御三家の使い方を見た  RubyのSystemTap integrationの使い方を見 た  発表資料を作ろうとすると、意外なバグにあた り作業が進まないという法則を確認した(?)  おかげでバグがたくさん直ったぞい
44. Questions?
45. Language Barrier ... once again demonstrating that Aussies a sense of humor beyond the grasp of the rest of us mere mortals. -- Paul Jackson I believe most developers use Incorrect English, the second most common is American English, followed by Indian English and British English. -- Arnd Bergmann