Upgrade to Pro — share decks privately, control downloads, hide ads and more …

GDB: A Gentle Intro

92e7389893670a1920a4fd98aec0d246?s=47 Jason R Clark
November 17, 2015

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!

92e7389893670a1920a4fd98aec0d246?s=128

Jason R Clark

November 17, 2015
Tweet

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) >>
  37. 37

  38. 38

  39. 39

  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. >>

  91. 91

  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