Skip to content

Ruby の ソースコードレベルでの gdb によるスタックトレース方法

Jump to bottom Edit New page
tora edited this page Feb 11, 2011 · 7 revisions

Ruby の ソースコードレベルでの gdb によるスタックトレース方法

プロセスIDを確認する

# ps -ef | grep ruby | grep -v grep
quanp    16252     1  0 15:37 ?        00:00:00 /usr/local/bin/ruby /usr/local/b

gdb を そのプロセスID に対して起動する

# gdb /usr/local/bin/ruby 16252
GNU gdb (GDB) Red Hat Enterprise Linux (7.0.1-23.el5)
Copyright (C) 2009 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /usr/local/bin/ruby...done.
Attaching to program: /usr/local/bin/ruby, process 16252
Reading symbols from /lib64/libpthread.so.0...(no debugging symbols found)...done.
[Thread debugging using libthread_db enabled]
[New Thread 0x405ce940 (LWP 16261)]
[New Thread 0x411f6940 (LWP 16260)]
[New Thread 0x4187c940 (LWP 16259)]
[New Thread 0x41e0b940 (LWP 16258)]
[New Thread 0x40dc1940 (LWP 16257)]
[New Thread 0x41b26940 (LWP 16256)]
[New Thread 0x404f7940 (LWP 16255)]
Loaded symbols for /lib64/libpthread.so.0
Reading symbols from /lib64/librt.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/librt.so.1
Reading symbols from /lib64/libdl.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libdl.so.2
Reading symbols from /lib64/libcrypt.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libcrypt.so.1
Reading symbols from /lib64/libm.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib64/libm.so.6
Reading symbols from /lib64/libc.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib64/libc.so.6
Reading symbols from /lib64/ld-linux-x86-64.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
Reading symbols from /usr/local/lib/ruby/1.9.1/x86_64-linux/enc/encdb.so...done.
Loaded symbols for /usr/local/lib/ruby/1.9.1/x86_64-linux/enc/encdb.so
Reading symbols from /usr/local/lib/ruby/1.9.1/x86_64-linux/enc/trans/transdb.so...done.
Loaded symbols for /usr/local/lib/ruby/1.9.1/x86_64-linux/enc/trans/transdb.so
Reading symbols from /usr/local/lib/ruby/1.9.1/x86_64-linux/etc.so...done.
Loaded symbols for /usr/local/lib/ruby/1.9.1/x86_64-linux/etc.so
Reading symbols from /usr/local/lib/ruby/1.9.1/x86_64-linux/iconv.so...done.
Loaded symbols for /usr/local/lib/ruby/1.9.1/x86_64-linux/iconv.so
Reading symbols from /usr/local/lib/ruby/gems/1.9.1/gems/json-1.2.3/ext/json/ext/parser.so...done.
Loaded symbols for /usr/local/lib/ruby/gems/1.9.1/gems/json-1.2.3/ext/json/ext/parser.so
Reading symbols from /usr/local/lib/ruby/1.9.1/x86_64-linux/enc/utf_16be.so...done.
Loaded symbols for /usr/local/lib/ruby/1.9.1/x86_64-linux/enc/utf_16be.so
Reading symbols from /usr/local/lib/ruby/1.9.1/x86_64-linux/enc/utf_16le.so...done.
Loaded symbols for /usr/local/lib/ruby/1.9.1/x86_64-linux/enc/utf_16le.so
Reading symbols from /usr/local/lib/ruby/1.9.1/x86_64-linux/enc/utf_32be.so...done.
Loaded symbols for /usr/local/lib/ruby/1.9.1/x86_64-linux/enc/utf_32be.so
Reading symbols from /usr/local/lib/ruby/1.9.1/x86_64-linux/enc/utf_32le.so...done.
Loaded symbols for /usr/local/lib/ruby/1.9.1/x86_64-linux/enc/utf_32le.so
Reading symbols from /usr/local/lib/ruby/gems/1.9.1/gems/json-1.2.3/ext/json/ext/generator.so...done.
Loaded symbols for /usr/local/lib/ruby/gems/1.9.1/gems/json-1.2.3/ext/json/ext/generator.so
Reading symbols from /usr/local/lib/ruby/1.9.1/x86_64-linux/socket.so...done.
Loaded symbols for /usr/local/lib/ruby/1.9.1/x86_64-linux/socket.so
Reading symbols from /usr/local/lib/ruby/gems/1.9.1/gems/castoro-gateway-0.0.7/lib/castoro-gateway/cache.so...done.
Loaded symbols for /usr/local/lib/ruby/gems/1.9.1/gems/castoro-gateway-0.0.7/lib/castoro-gateway/cache.so
Reading symbols from /usr/lib64/libstdc++.so.6...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libstdc++.so.6
Reading symbols from /lib64/libgcc_s.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libgcc_s.so.1
Reading symbols from /usr/local/lib/ruby/1.9.1/x86_64-linux/stringio.so...done.
Loaded symbols for /usr/local/lib/ruby/1.9.1/x86_64-linux/stringio.so
Reading symbols from /usr/local/lib/ruby/1.9.1/x86_64-linux/syck.so...done.
Loaded symbols for /usr/local/lib/ruby/1.9.1/x86_64-linux/syck.so
Reading symbols from /lib64/libnss_files.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libnss_files.so.2
Reading symbols from /usr/local/lib/ruby/1.9.1/x86_64-linux/strscan.so...done.
Loaded symbols for /usr/local/lib/ruby/1.9.1/x86_64-linux/strscan.so
0x0000003e45c0b150 in pthread_cond_timedwait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0

Rubyのソースコード内にあるデバッグ用関数を使って、ソースファイル名および行番号を表示する

(gdb) print rb_sourcefile()
$1 = 0x14819500 "/usr/local/lib/ruby/gems/1.9.1/gems/castoro-gateway-0.0.7/lib/castoro-gateway/gateway.rb"
(gdb) print rb_sourceline() 
$2 = 153

なお、上記のデバッグ用関数は、Ruby の VM から見て、このソースファイルのこの行を実行している。という情報を表示するようです。

従って、複数のスレッドが動作している時には、当たらからず遠からずのようです。

そこで、個々のスレッドについて、調べます。

行の途中で勝手に改行しないように設定する

(gdb) set width 999

スレッド一覧を表示する

(gdb) info threads
  8 Thread 0x404f7940 (LWP 16255)  0x0000003e45c0b150 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  7 Thread 0x41b26940 (LWP 16256)  0x0000003e45c0aee9 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  6 Thread 0x40dc1940 (LWP 16257)  0x0000003e45c0aee9 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  5 Thread 0x41e0b940 (LWP 16258)  0x0000003e45c0aee9 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  4 Thread 0x4187c940 (LWP 16259)  0x0000003e45c0aee9 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  3 Thread 0x411f6940 (LWP 16260)  0x0000003e450ccfc2 in select () from /lib64/libc.so.6
  2 Thread 0x405ce940 (LWP 16261)  0x0000003e450ccfc2 in select () from /lib64/libc.so.6
* 1 Thread 0x2b0bf793e050 (LWP 16252)  0x0000003e45c0b150 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0

調べたいスレッドを選択する

(gdb) thread 2
[Switching to thread 2 (Thread 0x405ce940 (LWP 16261))]#0  0x0000003e450ccfc2 in select () from /lib64/libc.so.6

C言語レベルでのスタックトレースを表示する

(gdb) bt
#0  0x0000003e450ccfc2 in select () from /lib64/libc.so.6
#1  0x00000000004dd8e0 in do_select (n=9, read=0x1f5898a0, write=0x0, except=0x0, timeout=0x405cd8f0) at thread.c:2424
#2  0x000000000042726e in select_internal (arg=523905344) at io.c:6573
#3  select_call (arg=523905344) at io.c:6646
#4  0x0000000000415fc4 in rb_ensure (b_proc=0x426f90 <select_call>, data1=1079826576, e_proc=0x424cf0 <select_end>, data2=1079826576) at eval.c:680
#5  0x0000000000426646 in rb_f_select (argc=<value optimized out>, argv=<value optimized out>, obj=<value optimized out>) at io.c:6692
#6  0x00000000004cb000 in vm_call_cfunc (th=0x1f6c0e10, reg_cfp=0x2aaaad050cb0, num=4, id=1472, oid=1472, recv=515258800, klass=515258744, flag=0, mn=0x1eb63128, blockptr=0x0) at vm_insnhelper.c:384
#7  0x00000000004cc020 in vm_call_method (th=0x1f6c0e10, cfp=0x2aaaad050cb0, num=4, blockptr=0x0, flag=0, id=1472, mn=0x1eb630f0, recv=515258800) at vm_insnhelper.c:517
#8  0x00000000004ce770 in vm_exec_core (th=0x1f6c0e10, initial=<value optimized out>) at insns.def:999
#9  0x00000000004d21ca in vm_exec (th=0x1f6c0e10) at vm.c:1080
#10 0x00000000004d27bc in invoke_block_from_c (th=0x1f6c0e10, block=0x1f74f3c0, self=521866856, argc=0, argv=0x0, blockptr=0x0, cref=0x0) at vm.c:524
#11 0x00000000004d2c72 in rb_vm_invoke_proc (th=0x1f6c0e10, proc=0x1f74f3c0, self=521866856, argc=0, argv=0x1f1b9b58, blockptr=0x0) at vm.c:571
#12 0x00000000004dc6ce in thread_start_func_2 (th=0x1f6c0e10, stack_start=0x405ce130) at thread.c:391
#13 0x00000000004dc7fe in thread_start_func_1 (th_ptr=0x9) at thread_pthread.c:351
#14 0x0000003e45c0673d in start_thread () from /lib64/libpthread.so.0
#15 0x0000003e450d3d1d in clone () from /lib64/libc.so.6

th= という引数が含まれているフレームを選択する

(gdb) frame 6
#6  0x00000000004cb000 in vm_call_cfunc (th=0x1f6c0e10, reg_cfp=0x2aaaad050cb0, num=4, id=1472, oid=1472, recv=515258800, klass=515258744, flag=0, mn=0x1eb63128, blockptr=0x0) at vm_insnhelper.c:384
384	vm_insnhelper.c: No such file or directory.
	in vm_insnhelper.c

引数 th は、RubyのVMが管理しているスレッド関連の構造体へのポインタです。

Rubyのスクリプトレベルでのスタックトレースを表示する

(gdb) print rb_vmdebug_stack_dump_raw(th, th.cfp)
$1 = void

何も表示されなかった場合は、標準出力(stdout)および標準エラー出力(stderr)が、どこへ出力されるようになっているか確認してみる。

# lsof -p 16252 -a -d 1,2
COMMAND     PID  USER   FD   TYPE DEVICE       SIZE    NODE NAME
castoro-g 16252 quanp    1w   REG  253,3 1767757910 6416259 /var/castoro/gateway.log
castoro-g 16252 quanp    2w   REG  253,3 1767757910 6416259 /var/castoro/gateway.log

上記の場合は、/var/castoro/gateway.log に出力されているはず。 tail コマンドなどで、出力結果が確認できるはず。

# tail -f /var/castoro/gateway.log

別の方法として、標準出力(stdout)および標準エラー出力(stderr)を、使用中の仮想端末(ttyコマンドで表示される)へ切り替えてみる。

(gdb) shell tty
/dev/pts/6　　　← ここで表示された仮想端末へのパスを、↓ freopen() で書き出し用として開く
(gdb) print freopen("/dev/pts/6", "w", stdout)
$2 = 1161107328
(gdb) print freopen("/dev/pts/6", "w", stderr)
$3 = 1161107552

改めて、Rubyのスクリプトレベルでのスタックトレースを表示する。

(gdb) print rb_vmdebug_stack_dump_raw(th, th.cfp)
-- control frame ----------
c:0010 p:---- s:0032 b:0032 l:000031 d:000031 CFUNC  :select
c:0009 p:0038 s:0025 b:0025 l:000019 d:000024 BLOCK  /usr/local/lib/ruby/gems/1.9.1/gems/castoro-common-0.0.7/lib/castoro-common/server.rb:360
c:0008 p:0019 s:0023 b:0023 l:000022 d:000022 METHOD <internal:prelude>:8
c:0007 p:0012 s:0020 b:0020 l:000019 d:000019 METHOD /usr/local/lib/ruby/gems/1.9.1/gems/castoro-common-0.0.7/lib/castoro-common/server.rb:358
c:0006 p:0049 s:0016 b:0016 l:000015 d:000015 METHOD /usr/local/lib/ruby/gems/1.9.1/gems/castoro-common-0.0.7/lib/castoro-common/server.rb:330
c:0005 p:0012 s:0012 b:0012 l:000011 d:000011 METHOD /usr/local/lib/ruby/gems/1.9.1/gems/castoro-gateway-0.0.7/lib/castoro-gateway/console_workers.rb:27
c:0004 p:0030 s:0009 b:0009 l:0016d8 d:0016d8 METHOD /usr/local/lib/ruby/gems/1.9.1/gems/castoro-common-0.0.7/lib/castoro-common/workers.rb:95
c:0003 p:0009 s:0006 b:0006 l:000348 d:000005 BLOCK  /usr/local/lib/ruby/gems/1.9.1/gems/castoro-common-0.0.7/lib/castoro-common/workers.rb:54
c:0002 p:---- s:0004 b:0004 l:000003 d:000003 FINISH
c:0001 p:---- s:0002 b:0002 l:000001 d:000001 TOP   
---------------------------
$4 = void

上記出力結果の意味については、Ruby本体ソースコード https://github.com/ruby/ruby/blob/trunk/vm_dump.c 内の以下の関数が参考になります。

  • control_frame_dump()
  • rb_vmdebug_stack_dump_raw()

Ctrl-Z で gdb を一時停止し、シェルに戻る

(gdb) 
[1]+  Stopped                 gdb /usr/local/bin/ruby 5211

スクリプトの内容を表示する

# cat -n /usr/local/lib/ruby/gems/1.9.1/gems/castoro-common-0.0.7/lib/castoro-common/server.rb | head -365 | tail -10
   356	
   357	      def accept
   358	        accepted = @accept_locker.synchronize {
   359	          return nil unless alive?
   360	          return nil unless IO.select([@tcp_server], nil, nil, @accept_expire)　　　　　← この行
   361	          @tcp_server.accept
   362	        }
   363	
   364	        if accepted
   365	          begin

# cat -n /usr/local/lib/ruby/gems/1.9.1/gems/castoro-common-0.0.7/lib/castoro-common/server.rb | head -363 | tail -10
   354	
   355	      private
   356	
   357	      def accept
   358	        accepted = @accept_locker.synchronize {　　　　　　　　　　　　　　　　　　　　　　　　　← この行
   359	          return nil unless alive?
   360	          return nil unless IO.select([@tcp_server], nil, nil, @accept_expire)
   361	          @tcp_server.accept
   362	        }
   363	

# cat -n /usr/local/lib/ruby/gems/1.9.1/gems/castoro-common-0.0.7/lib/castoro-common/server.rb | head -335 | tail -10
   326	        raise ServerError, "It is necessary to specify the block argument." unless block_given?
   327	        
   328	        while not Thread.current[:dying] and alive?
   329	          begin
   330	            accept { |sock|　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　← この行
   331	
   332	              get_try_count = 0
   333	              while get_try_count < @get_try_count
   334	                break if Thread.current[:dying] or not alive?
   335	

# cat -n /usr/local/lib/ruby/gems/1.9.1/gems/castoro-gateway-0.0.7/lib/castoro-gateway/console_workers.rb | head -32 | tail -10
    23	      #
    24	      def work
    25	        
    26	        # client loop..
    27	        @facade.client_loop { |socket, received|　　　　　　　　　　　　　　　　　　　　　　　　　← この行
    28	
    29	          # accept.
    30	          accept_command(socket, received) { |cmd|
    31	
    32	            case cmd

# cat -n /usr/local/lib/ruby/gems/1.9.1/gems/castoro-common-0.0.7/lib/castoro-common/workers.rb | head -100 | tail -10
    91	    def worker_loop
    92	      @logger.info { "starting #{@name}... #{Thread.current}" }
    93	
    94	      until Thread.current[:dying]
    95	        work　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　← この行
    96	      end
    97	
    98	      @logger.info { "stopping #{@name}... #{Thread.current}" }
    99	    end
   100

リンク

上記のデバッグ用関数は、Ruby本体ソースコードの vm_dump.c にあります。

https://github.com/ruby/ruby/blob/trunk/vm_dump.c

上記の関数の他にも、有用な関数が用意されています。お試しあれ。

また、上記のデバッグ用関数を gdb マクロで書き直した ruby_stack_trace マクロコマンドもお試しください。

http://tora-japan.com/wiki/Script_level_stack_trace_for_Ruby_1.9.1_with_gdb

Add a custom footer
Add a custom sidebar
Clone this wiki locally