GDB: A Gentle Intro

We love Ruby’s elegance, simplicity, and flexibility. But our favorite language perches atop a world of native code. When that other world intrudes on your peaceful Ruby, GDB, the venerable GNU debugger, is the tool to turn to.

We’ll examine setting up Ruby to work with GDB. We’ll learn the fundamental commands, and soon you’ll be debugging with ease. We’ll even peer deep into Ruby object internals and face down crashes, deadlocks, and bugs.

Whether you’re writing a native gem, hacking the Ruby VM, or just want a glimpse of the layers below, this talk is for you!

Transcript

1. https://flic.kr/p/8RePxD GDB A Gentle Intro @jasonrclark http://git.io/v8GbT https://flic.kr/p/o15Y5n
2. 2 $ ps -o pid,pcpu,pmem,cmd PID %CPU %MEM CMD 1 0.0 0.1 bash 10 1.8 0.4 ruby service.rb >>
3. 3 $ tail production.log [14:30:59 (8985)] INFO : Starting! $ >>
4. 4 Threading https://flic.kr/p/4WFtU8
5. Deadlock? https://flic.kr/p/nkwswv
6. GDB 6
7. Gnu Debugger 7
8. MRI 8
9. MRI CRuby 9
10. 10 $ gdb -p 10 ... Attaching to process 10 Reading symbols from /usr/local/bin/ ruby...done. [Thread debugging using libthread_db enabled] Loaded symbols for /usr/local/lib/ruby/ 2.2.0/x86_64-linux/thread.so (gdb) >>
11. 11 $ gdb -p 10 ... Attaching to process 10 Reading symbols from /usr/local/bin/ ruby...done. [Thread debugging using libthread_db enabled] Loaded symbols for /usr/local/lib/ruby/ 2.2.0/x86_64-linux/thread.so (gdb) >>
12. (gdb) backtrace #0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/...:185 #1 0x00007f131f343b03 in native_cond_wait(mutex=0x7f131fcdf5, cond=0x7f131fcdf558) at thread_pthread.c:338 #2 lock_func (timeout_ms=0, mutex=0x7f, th=0x7f131f8c46) at thread.c:4268 #3 rb_mutex_lock (self=139720114712880) at thread.c:4342 #4 0x00007f131f31c9ee in vm_call_cfunc_with_frame (ci=0x0, reg_cfp=0x7f131f1a7f70, th=0x7f131f8c46e0) at vm_insnhelper.c:1380 >>
13. 13 RuntimeError: raise ‘Heck’ config.ru:13:in `call' rack-1.6.4/...tempfile_reaper.rb:15:in `call' rack-1.6.4/...lint.rb:49:in `_call' rack-1.6.4/...lint.rb:37:in `call' rack-1.6.4/...showexceptions.rb:24:in `call' rack-1.6.4/...commonlogger.rb:33:in `call' rack-1.6.4/...chunked.rb:54:in `call' rack-1.6.4/...content_length.rb:15:in `call' thin-1.6.3/...connection.rb:86:in `block in thin-1.6.3/...connection.rb:84:in `catch' thin-1.6.3/...connection.rb:84:in `pre_process' thin-1.6.3/...connection.rb:53:in `process' thin-1.6.3/...connection.rb:39:in `receive_data eventmachine-1.0.7/lib/eventmachine.rb:187:in eventmachine-1.0.7/lib/eventmachine.rb:187:in thin-1.6.3/...backends/base.rb:73:in `start' thin-1.6.3/...server.rb:162:in `start'
14. (gdb) backtrace #0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/...:185 #1 0x00007f131f343b03 in native_cond_wait(mutex=0x7f131fcdf5, cond=0x7f131fcdf558) at thread_pthread.c:338 #2 lock_func (timeout_ms=0, mutex=0x7f, th=0x7f131f8c46) at thread.c:4268 #3 rb_mutex_lock (self=139720114712880) at thread.c:4342 #4 0x00007f131f31c9ee in vm_call_cfunc_with_frame (ci=0x0, reg_cfp=0x7f131f1a7f70, th=0x7f131f8c46e0) at vm_insnhelper.c:1380
15. (gdb) backtrace #0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/...:185 #1 0x00007f131f343b03 in native_cond_wait(mutex=0x7f131fcdf5, cond=0x7f131fcdf558) at thread_pthread.c:338 #2 lock_func (timeout_ms=0, mutex=0x7f, th=0x7f131f8c46) at thread.c:4268 #3 rb_mutex_lock (self=139720114712880) at thread.c:4342 #4 0x00007f131f31c9ee in vm_call_cfunc_with_frame (ci=0x0, reg_cfp=0x7f131f1a7f70, th=0x7f131f8c46e0) at vm_insnhelper.c:1380
16. (gdb) backtrace #0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/...:185 #1 0x00007f131f343b03 in native_cond_wait(mutex=0x7f131fcdf5, cond=0x7f131fcdf558) at thread_pthread.c:338 #2 lock_func (timeout_ms=0, mutex=0x7f, th=0x7f131f8c46) at thread.c:4268 #3 rb_mutex_lock (self=139720114712880) at thread.c:4342 #4 0x00007f131f31c9ee in vm_call_cfunc_with_frame (ci=0x0, reg_cfp=0x7f131f1a7f70, th=0x7f131f8c46e0) at vm_insnhelper.c:1380
17. (gdb) backtrace #0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/...:185 #1 0x00007f131f343b03 in native_cond_wait(mutex=0x7f131fcdf5, cond=0x7f131fcdf558) at thread_pthread.c:338 #2 lock_func (timeout_ms=0, mutex=0x7f, th=0x7f131f8c46) at thread.c:4268 #3 rb_mutex_lock (self=139720114712880) at thread.c:4342 #4 0x00007f131f31c9ee in vm_call_cfunc_with_frame (ci=0x0, reg_cfp=0x7f131f1a7f70, th=0x7f131f8c46e0) at vm_insnhelper.c:1380
18. 18 (gdb) info threads Id Target Id Frame 4 Thread 0x7f131f1b4700 (LWP 11) "ruby-timer-thr" in poll () at ../sysdeps/unix/syscall-temp... 3 Thread 0x7f131db8a700 (LWP 12) “service.rb:6" pthread_cond_wait@@GLIBC_2.3.2 () 2 Thread 0x7f131d988700 (LWP 13) “service.rb:12" vm_exec_core (th=0x7f131d989058... * 1 Thread 0x7f131f1aa700 (LWP 10) "ruby" pthread_cond_wait@@GLIBC... >>
19. 19 (gdb) info threads Id Target Id Frame 4 Thread 0x7f131f1b4700 (LWP 11) "ruby-timer-thr" in poll () at ../sysdeps/unix/syscall-temp... 3 Thread 0x7f131db8a700 (LWP 12) “service.rb:6" pthread_cond_wait@@GLIBC_2.3.2 () 2 Thread 0x7f131d988700 (LWP 13) “service.rb:12" vm_exec_core (th=0x7f131d989058... * 1 Thread 0x7f131f1aa700 (LWP 10) "ruby" pthread_cond_wait@@GLIBC...
20. 20 (gdb) info threads Id Target Id Frame 4 Thread 0x7f131f1b4700 (LWP 11) "ruby-timer-thr" in poll () at ../sysdeps/unix/syscall-temp... 3 Thread 0x7f131db8a700 (LWP 12) “service.rb:6" pthread_cond_wait@@GLIBC_2.3.2 () 2 Thread 0x7f131d988700 (LWP 13) “service.rb:12" vm_exec_core (th=0x7f131d989058... * 1 Thread 0x7f131f1aa700 (LWP 10) "ruby" pthread_cond_wait@@GLIBC...
21. 21 (gdb) thread apply all backtrace Thread 3 (Thread 0x7f131db8a700 (LWP 12)): #0 pthread_cond_wait@@GLIBC_2.3.2 () at .. #1 0x00007f131f343b03 in native_cond_wait #2 lock_func (timeout_ms=0, mutex=0x7f131f #3 rb_mutex_lock (self=139720114712840) at #4 0x00007f131f31c9ee in vm_call_cfunc_wit #5 vm_call_cfunc (th=th@entry=0x7f131fcdda #6 0x00007f131f32c82e in vm_call_method (t #7 0x00007f131f32108b in vm_exec_core (th= #8 0x00007f131f3255d8 in vm_exec (th=0x7f1 #9 0x00007f131f32be0c in invoke_block_from #10 0x00007f131f32bfa0 in vm_invoke_proc (t >>
22. 22 (gdb) thread apply all backtrace Thread 3 (Thread 0x7f131db8a700 (LWP 12)): #0 pthread_cond_wait@@GLIBC_2.3.2 () at .. #1 0x00007f131f343b03 in native_cond_wait #2 lock_func (timeout_ms=0, mutex=0x7f131f #3 rb_mutex_lock (self=139720114712840) at #4 0x00007f131f31c9ee in vm_call_cfunc_wit #5 vm_call_cfunc (th=th@entry=0x7f131fcdda #6 0x00007f131f32c82e in vm_call_method (t #7 0x00007f131f32108b in vm_exec_core (th= #8 0x00007f131f3255d8 in vm_exec (th=0x7f1 #9 0x00007f131f32be0c in invoke_block_from >>
23. 23 ---Type <return> to continue, or q <return> Thread 1 (Thread 0x7f131f1aa700 (LWP 10)): #0 pthread_cond_wait@@GLIBC_2.3.2 () at .. #1 0x00007f131f343b03 in native_cond_wait #2 lock_func (timeout_ms=0, mutex=0x7f131f #3 rb_mutex_lock (self=139720114712880) at #4 0x00007f131f31c9ee in vm_call_cfunc_wit #5 vm_call_cfunc (th=th@entry=0x7f131f8c46 #6 0x00007f131f32c82e in vm_call_method (t #7 0x00007f131f32108b in vm_exec_core (th= #8 0x00007f131f3255d8 in vm_exec (th=th@en #9 0x00007f131f33319f in rb_iseq_eval_main >>
24. 24 (gdb) exit Undefined command: "exit". Try “help". (gdb) >>
25. 25 (gdb) exit Undefined command: "exit". Try “help”. (gdb) quit $ >>
26. https://flic.kr/p/o15Y5n 26 Attach gdb -p PID
27. https://flic.kr/p/o15Y5n 27 Inspect backtrace info threads thread apply all backtrace
28. https://flic.kr/p/o15Y5n 28 $$$$ exit quit
29. A Unique Problem 29 https://flic.kr/p/dPiDp3
30. 30 [1] pry(main)> [1,1,2,3].uniq! => [1, 2, 3]
31. 31 [1] pry(main)> [1,1,2,3].uniq! => [1, 2, 3] [2] pry(main)> [1,2,3].uniq! => nil
32. 32 $ cat snowflake.rb p [1,1,2,3].uniq! p [1,2,3].uniq!
33. 33 $ cat snowflake.rb p [1,1,2,3].uniq! p [1,2,3].uniq! $ ruby snowflake.rb [1, 2, 3] nil
34. 34 $ gdb --args ruby snowflake.rb GNU gdb (Debian 7.7.1+dfsg-5) 7.7.1 Copyright (C) 2014 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/ gpl.html> ... For help, type "help". Type "apropos word" to search for commands related to "word". (gdb) >>
35. 35 (gdb) run Starting program: /usr/local/bin/ruby... [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/ x86_64-linux-gnu/libthread_db.so.1". [New Thread 0x7ffff7ff5700 (LWP 13)] [1,2,3] nil [Thread 0x7ffff7ff5700 (LWP 13) exited] [Inferior 1 (process 9) exited normally] (gdb) >>
36. 36 (gdb) run Starting program: /usr/local/bin/ruby... [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/ x86_64-linux-gnu/libthread_db.so.1". [New Thread 0x7ffff7ff5700 (LWP 13)] [1,2,3] nil [Thread 0x7ffff7ff5700 (LWP 13) exited] [Inferior 1 (process 9) exited normally] (gdb) >>
40. Eeeeeeek! https://flic.kr/p/nkwswv
41. 41 int the_answer (long value) { return 42; }
42. 42 int the_answer (long value) { return 42; }
43. 43 int the_answer (long value) { return 42; }
44. 44 int the_answer (long value) { return 42; }
45. 45 int the_answer (long value) { return 42; }
46. 46 static VALUE rb_ary_uniq_bang(VALUE ary) { VALUE hash; long hash_size; rb_ary_modify_check(ary); if (RARRAY_LEN(ary) <= 1) return Qnil; if (rb_block_given_p()) hash = ary_make_hash_by(ary); else hash = ary_make_hash(ary); hash_size = RHASH_SIZE(hash); if (RARRAY_LEN(ary) == hash_size) {
47. 47 static VALUE rb_ary_uniq_bang(VALUE ary) { VALUE hash; long hash_size; rb_ary_modify_check(ary); if (RARRAY_LEN(ary) <= 1) return Qnil; if (rb_block_given_p()) hash = ary_make_hash_by(ary); else hash = ary_make_hash(ary); hash_size = RHASH_SIZE(hash); if (RARRAY_LEN(ary) == hash_size) {
48. 48 static VALUE rb_ary_uniq_bang(VALUE ary) { VALUE hash; long hash_size; rb_ary_modify_check(ary); if (RARRAY_LEN(ary) <= 1) return Qnil; if (rb_block_given_p()) hash = ary_make_hash_by(ary); else hash = ary_make_hash(ary); hash_size = RHASH_SIZE(hash); if (RARRAY_LEN(ary) == hash_size) {
49. 49 $ gdb --args ruby snowflake.rb ... Reading symbols from ruby...done. (gdb) break rb_ary_uniq_bang Breakpoint 1 at 0x19a370: file array.c, line 4162. (gdb) >>
50. 50 (gdb) run Starting program: /usr/local/bin/ruby snowflake.rb Breakpoint 1, rb_ary_uniq_bang (ary=93825000955160) at array.c:4162 4162 { (gdb) >>
51. 51 (gdb) run Starting program: /usr/local/bin/ruby snowflake.rb Breakpoint 1, rb_ary_uniq_bang (ary=93825000955160) at array.c:4162 4162 { (gdb) >>
52. 52 (gdb) run Starting program: /usr/local/bin/ruby snowflake.rb Breakpoint 1, rb_ary_uniq_bang (ary=93825000955160) at array.c:4162 4162 { (gdb) >>
53. https://flic.kr/p/o15Y5n 53 Starting gdb --args ruby snowflake.rb
54. https://flic.kr/p/o15Y5n 54 C functions! int the_answer (long value)
55. https://flic.kr/p/o15Y5n 55 ruby-doc.org rb_ary_uniq_bang
56. https://flic.kr/p/o15Y5n 56 Breakpoints break rb_ary_uniq_bang
57. Looking Around https://flic.kr/p/uq8MA
58. 58 (gdb) list 4157 * 4158 */ 4159 4160 static VALUE 4161 rb_ary_uniq_bang(VALUE ary) 4162 { 4163 VALUE hash; 4164 long hash_size; 4165 4166 rb_ary_modify_check(ary); >>
59. 59 (gdb) display ary 1: ary = 93825000955160 >>
60. Eeeeeeek! https://flic.kr/p/nkwswv
61. 61 struct Data { int value; }
62. 62 struct Data { int value; } value 0xC001C0DE
63. 63 struct ValuableData { Data data; int priority; } value priority 0xC001C0DE
64. 64 struct RBasic { VALUE flags; const VALUE klass; } flags klass 0xBAADC0DE
65. struct RArray { struct RBasic basic; union { struct { long len; union { long capa; VALUE shared; } aux; const VALUE *ptr; } heap; const VALUE ary[RARRAY_EMBED_LEN_MAX]; } as; }; 65 flags klass len capa ...
66. 66 RBasic RClass RObject RBignum RRational RFloat RComplex RHash RSymbol RString RArray RRegexp
67. 67 (gdb) display ary 1: ary = 93825000955160 flags klass 0x555555da5d18 >>
68. 68 (gdb) display *(struct RArray*)ary 1: ary = {basic = {flags = 106503, klass = 9382499777180}, as = {heap = {len = 3, aux = {capa = 5, shared = 5}, ptr = 0x7}, ary = {3, 5, 7}}} >>
69. 69 (gdb) display *(struct RArray*)ary 1: ary = {basic = {flags = 106503, klass = 9382499777180}, as = {heap = {len = 3, aux = {capa = 5, shared = 5}, ptr = 0x7}, ary = {3, 5, 7}}} >>
70. 70 /* for debug print within C code */ void rb_p(VALUE obj)
71. 71 (gdb) call rb_p(ary) [">= 0"] >>
72. https://flic.kr/p/o15Y5n 72 Source list
73. https://flic.kr/p/o15Y5n 73 Look display ary
74. https://flic.kr/p/o15Y5n 74 struct struct C { BOOL scary /* FALSE */ }
75. https://flic.kr/p/o15Y5n 75 Debug Print call rb_p(ary)
76. 76 https://flic.kr/p/tLkpZG
77. 77 (gdb) call rb_p(ary) [">= 0"] >>
78. 78 (gdb) call rb_backtrace() from <internal:gem_prelude>:1:in `<compiled>' from <internal:gem_prelude>:1:in `require' from rubygems.rb:115:in `<top (required)>' from rubygems.rb:1210:in `<module:Gem>' from rubygems.rb:1210:in `require' from rubygems/specification.rb:37:in `<top (...)>’ from rubygems/specification.rb:146:in `<class...>’ from rubygems/requirement.rb:74:in `default' from rubygems/requirement.rb:74:in `new' from rubygems/requirement.rb:125:in `initialize' from rubygems/requirement.rb:125:in `uniq!' >>
79. 79 (gdb) call rb_backtrace() from <internal:gem_prelude>:1:in `<compiled>' from <internal:gem_prelude>:1:in `require' from rubygems.rb:115:in `<top (required)>' from rubygems.rb:1210:in `<module:Gem>' from rubygems.rb:1210:in `require' from rubygems/specification.rb:37:in `<top (...)>’ from rubygems/specification.rb:146:in `<class...>’ from rubygems/requirement.rb:74:in `default' from rubygems/requirement.rb:74:in `new' from rubygems/requirement.rb:125:in `initialize' from rubygems/requirement.rb:125:in `uniq!' >>
80. 80 $ ruby --disable-gems snowflake.rb
81. Move It! https://flic.kr/p/mAst2V
82. 82 (gdb) list 4157 * 4158 */ 4159 4160 static VALUE 4161 rb_ary_uniq_bang(VALUE ary) 4162 { 4163 VALUE hash; 4164 long hash_size; 4165 4166 rb_ary_modify_check(ary); >>
83. 83 (gdb) next 4166 rb_ary_modify_check(ary); >>
84. 84 (gdb) step rb_ary_modify_check (ary=9382499768664) at array.c:312 312 rb_check_frozen(ary); >>
85. 85 (gdb) step rb_ary_modify_check (ary=9382499768664) at array.c:312 312 rb_check_frozen(ary); (gdb) list 309 static inline void 310 rb_ary_modify_check(VALUE ary) 311 { 312 rb_check_frozen(ary); 313 } >>
86. 86 (gdb) finish Run till exit from #0 rb_ary_modify_check (ary=9382500108300) at array.c:312 4167 if (RARRAY_LEN(ary) <= 1) (gdb) >>
87. 87 (gdb) list 4164 long hash_size; 4165 4166 rb_ary_modify_check(ary); 4167 if (RARRAY_LEN(ary) <= 1) 4168 return Qnil; 4169 if (rb_block_given_p()) 4170 hash = ary_make_hash_by(ary); 4171 else 4172 hash = ary_make_hash(ary); 4173 >>
88. 88 (gdb) list 4164 long hash_size; 4165 4166 rb_ary_modify_check(ary); 4167 if (RARRAY_LEN(ary) <= 1) 4168 return Qnil; 4169 if (rb_block_given_p()) 4170 hash = ary_make_hash_by(ary); 4171 else 4172 hash = ary_make_hash(ary); 4173 >>
89. 89 (gdb) list 4170 hash = ary_make_hash_by(ary); 4171 else 4172 hash = ary_make_hash(ary); 4173 4174 hash_size = RHASH_SIZE(hash); 4175 if (RARRAY_LEN(ary) == hash_size) { 4176 return Qnil; 4177 } 4178 rb_ary_modify_check(ary); 4179 ARY_SET_LEN(ary, 0); >>
90. 90 (gdb) continue Continuing. >>
92. https://flic.kr/p/o15Y5n 92 Movin’ next step finish list continue
93. Silly GDB Tricks https://flic.kr/p/dHofYV
94. 94 (gdb) call (void)close(1) (gdb) call (void)close(2) (gdb) call (int)open(“gdb.log”, 2, 0) (gdb) call (int)open(“gdb.log”, 2, 0)
95. 95 (gdb) call(rb_p(rb_eval_string_protect( "Thread.list.each do |t| puts t; puts t.backtrace.join(‘\n'); end",(int*)0))) #<Thread:0x00555555a93328> eval:1:in `backtrace' eval:1:in `block in <main>' eval:1:in `each' eval:1:in `<main>' drop.rb:2:in `drop' drop.rb:2:in `<main>' >>
96. 96 (gdb) call(rb_p(rb_eval_string_protect( "Thread.list.each do |t| puts t; puts t.backtrace.join(‘\n'); end",(int*)0))) #<Thread:0x00555555a93328> eval:1:in `backtrace' eval:1:in `block in <main>' eval:1:in `each' eval:1:in `<main>' drop.rb:2:in `drop' drop.rb:2:in `<main>'
97. 97 $ cat gdb_script attach 107 thread all apply backtrace call (void)rb_backtrace() quit >>
98. 98 $ gdb --batch -x gdb_script ... Thread 2 (Thread 0x7f09a71d070 (LWP 108)): #0 0x00007f09a638e50d in poll () at ../sysdeps/unix/syscall-template.S:81 #1 0x00007f09a735d in timer_thread_sleep at thread_pthread.c:1442 #2 thread_timer (p=0x7f09a9466018) at thread_pthread.c:1549 #3 0x00007f09a6d9e0a4 in start_thread at pthread_create.c:309 Inferior 1 [process 10] will be detached. $ >>
99. 99 $ gem install newrelic_rpm $ nrdebug 1234 Are you sure you want to attach to PID 1234 ('ruby -e loop do end')}? Extracting debug information from this process may cause it to hang, crash, or otherwise malfunction... To continue, type 'continue': Generated 'nrdebug-1234-1447787527.log'
100. 100 $ cat ~/.gdbinit define exit quit end >>
101. Recap 101 https://flic.kr/p/rx2WTU
102. Deadlock? https://flic.kr/p/nkwswv
103. A Unique Problem 103 https://flic.kr/p/dPiDp3
104. Looking Around https://flic.kr/p/uq8MA
105. Move It! https://flic.kr/p/mAst2V
106. Silly GDB Tricks https://flic.kr/p/dHofYV
107. https://flic.kr/p/8RePxD ? @jasonrclark http://git.io/v8GbT https://flic.kr/p/ebUyxU