[ruby-dev:49993] メソッド呼び出し時の引数の値を VM 側で取得する方法について
From:
Tetsuo Handa <penguin-kernel@...>
Date:
2017-02-28 05:06:04 UTC
List:
ruby-dev #49993
初めまして。 Linux カーネルプログラマの熊猫と申します。
現在、 Ruby VM に手を加えることで、メソッド呼び出し時の引数の値/メソッドから
復帰する時の戻り値の値を取得する方法を探しています。( SystemTap による
Statically Defined Tracepoints を用いたフックでは、メソッド名は取得できても
値までは取得できないことが判明したため、 Ruby VM に手を加える方法を試している
ところです。)
メソッド呼び出し時のフックを挿入すべき個所の見当は付いており、以下のパッチを
当てれば大抵の呼び出しについては rb_inspect() 呼び出しで引数の値を取得することが
できるようになるのですが、 make 中に実行される特定の rb_inspect() 呼び出しで
プロセスが終了してしまうという謎の挙動に遭遇しているため、開発者の方々に質問
させていただきます。
事象再現手順( CentOS 7 向け)
(1) 普通にソースコードからコンパイルします。
----------------------------------------
# yumdownloader --source ruby
# rpm --checksig ruby-2.0.0.648-29.el7.src.rpm
# yum-builddep -y ruby-2.0.0.648-29.el7.src.rpm
# rpm -ivh ruby-2.0.0.648-29.el7.src.rpm
# rpmbuild -bb ~/rpmbuild/SPECS/ruby.spec
(中略。テスト途中で無応答になるものがありますが本題ではないので省略します。)
make: *** [yes-test-all] Error 63
error: Bad exit status from /var/tmp/rpm-tmp.1xpTWi (%check)
RPM build errors:
Bad exit status from /var/tmp/rpm-tmp.1xpTWi (%check)
----------------------------------------
(2) 以下のパッチを当てて再コンパイルします。
----------------------------------------
# cd ~/rpmbuild/BUILD/ruby-2.0.0-p648/
# patch -p1
--- ruby-2.0.0-p648.orig/vm_insnhelper.c
+++ ruby-2.0.0-p648/vm_insnhelper.c
@@ -1295,6 +1295,58 @@ vm_call_iseq_setup_2(rb_thread_t *th, rb
}
}
+/* ///// */
+static void dump_function_entry(rb_thread_t *th, int argc, VALUE *argv)
+{
+ static FILE *fp = NULL;
+ static __thread _Bool dump_recurse = 0;
+ VALUE _klass = 0;
+ VALUE _id = 0;
+ if (dump_recurse)
+ return;
+ dump_recurse = 1;
+ if (!fp)
+ fp = fopen("/tmp/ruby.log", "a");
+ rb_thread_method_id_and_class((th), &_id, &_klass);
+ if (!_klass || !fp) {
+ dump_recurse = 0;
+ return;
+ }
+ if (RB_TYPE_P(_klass, T_ICLASS))
+ _klass = RBASIC(_klass)->klass;
+ else if (FL_TEST(_klass, FL_SINGLETON))
+ _klass = rb_iv_get(_klass, "__attached__");
+ switch (TYPE(_klass)) {
+ case T_CLASS:
+ case T_ICLASS:
+ case T_MODULE:
+ {
+ int i;
+ VALUE _name = rb_class_path_no_cache(_klass);
+ const char *classname = !NIL_P(_name) ? StringValuePtr(_name) : "<unknown>";
+ const char *methodname = rb_id2name(_id);
+ const char *filename = rb_sourcefile();
+ fprintf(fp, "class=%s method=%s filename=%s line=%u argc=%u",
+ classname, methodname, filename, rb_sourceline(), argc);
+ fflush(fp);
+ for (i = 0; i < argc; i++) {
+ VALUE rstr;
+ fprintf(fp, " argv[%u](%lx)", i, argv[i]);
+ fflush(fp);
+ rstr = rb_inspect(argv[i]);
+ fprintf(fp, "=");
+ fflush(fp);
+ fprintf(fp, "%s", StringValueCStr(rstr));
+ fflush(fp);
+ }
+ fprintf(fp, "\n");
+ fflush(fp);
+ break;
+ }
+ }
+ dump_recurse = 0;
+}
+
static inline VALUE
vm_call_iseq_setup_normal(rb_thread_t *th, rb_control_frame_t *cfp, rb_call_info_t *ci)
{
@@ -1313,6 +1365,7 @@ vm_call_iseq_setup_normal(rb_thread_t *t
vm_push_frame(th, iseq, VM_FRAME_MAGIC_METHOD, ci->recv, ci->defined_class,
VM_ENVVAL_BLOCK_PTR(ci->blockptr),
iseq->iseq_encoded + ci->aux.opt_pc, sp, 0, ci->me);
+ dump_function_entry(th, ci->argc, argv);
cfp->sp = argv - 1 /* recv */;
return Qundef;
@@ -1352,6 +1405,7 @@ vm_call_iseq_setup_tailcall(rb_thread_t
vm_push_frame(th, iseq, VM_FRAME_MAGIC_METHOD | finish_flag,
ci->recv, ci->defined_class, VM_ENVVAL_BLOCK_PTR(ci->blockptr),
iseq->iseq_encoded + ci->aux.opt_pc, sp, 0, ci->me);
+ dump_function_entry(th, ci->argc, argv);
cfp->sp = sp_orig;
return Qundef;
(ここまでコピペしたら Ctrl-D を押します。)
patching file vm_insnhelper.c
# make
(中略)
Generating RDoc documentation
Parsing sources...
Before reporting this, could you check that the file you're documenting
has proper syntax:
/usr/bin/ruby -c prelude.c
RDoc is not a full Ruby parser and will fail when fed invalid ruby programs.
The internal error was:
(TypeError) no implicit conversion of nil into String
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/top_level.rb:111:in `basename'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/top_level.rb:111:in `base_name'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/top_level.rb:175:in `inspect'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/context/section.rb:41:in `initialize'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/context.rb:128:in `new'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/context.rb:128:in `initialize'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/top_level.rb:43:in `initialize'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/store.rb:181:in `new'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/store.rb:181:in `add_file'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/rdoc.rb:358:in `parse_file'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/rdoc.rb:417:in `block in parse_files'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/rdoc.rb:415:in `map'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/rdoc.rb:415:in `parse_files'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/rdoc.rb:485:in `document'
./bin/rdoc:20:in `<main>'
no implicit conversion of nil into String
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/top_level.rb:111:in `basename'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/top_level.rb:111:in `base_name'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/top_level.rb:175:in `inspect'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/context/section.rb:41:in `initialize'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/context.rb:128:in `new'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/context.rb:128:in `initialize'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/top_level.rb:43:in `initialize'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/store.rb:181:in `new'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/store.rb:181:in `add_file'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/rdoc.rb:358:in `parse_file'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/rdoc.rb:417:in `block in parse_files'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/rdoc.rb:415:in `map'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/rdoc.rb:415:in `parse_files'
/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/rdoc.rb:485:in `document'
./bin/rdoc:20:in `<main>'
make: *** [rdoc] Error 1
----------------------------------------
ログを確認すると、 = の前で終了していることから、 rb_inspect(argv[0]) の
呼び出しの中でプロセスが終了していると判断できます。
----------------------------------------
# tail /tmp/ruby.log
class=Pathname method=chop_basename filename=/root/rpmbuild/BUILD/ruby-2.0.0-p648/.ext/common/pathname.rb line=43 argc=1 argv[0](182b8c8)="/root/rpmbuild/BUILD/"
class=Pathname method=chop_basename filename=/root/rpmbuild/BUILD/ruby-2.0.0-p648/.ext/common/pathname.rb line=43 argc=1 argv[0](182b710)="/root/rpmbuild/"
class=Pathname method=chop_basename filename=/root/rpmbuild/BUILD/ruby-2.0.0-p648/.ext/common/pathname.rb line=43 argc=1 argv[0](182b580)="/root/"
class=Pathname method=chop_basename filename=/root/rpmbuild/BUILD/ruby-2.0.0-p648/.ext/common/pathname.rb line=43 argc=1 argv[0](182b440)="/"
class=RDoc::Store method=add_file filename=/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/store.rb line=179 argc=2 argv[0](180c3b0)="prelude.c" argv[1](182b148)="prelude.c"
class=RDoc::TopLevel method=initialize filename=/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/top_level.rb line=42 argc=2 argv[0](180c3b0)="prelude.c" argv[1](182b148)="prelude.c"
class=RDoc::Context method=initialize filename=/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/context.rb line=119 argc=0
class=RDoc::CodeObject method=initialize filename=/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/code_object.rb line=107 argc=0
class=RDoc::CodeObject method=initialize_visibility filename=/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/code_object.rb line=125 argc=0
class=RDoc::Context::Section method=initialize filename=/root/rpmbuild/BUILD/ruby-2.0.0-p648/lib/rdoc/context/section.rb line=41 argc=3 argv[0](182b0a8)
----------------------------------------
lib/rdoc/context/section.rb の 41 行目は以下のメソッド呼び出しです。
----------------------------------------
##
# Creates a new section with +title+ and +comment+
def initialize parent, title, comment
@parent = parent
@title = title ? title.strip : title
@@sequence.succ!
@sequence = @@sequence.dup
@comments = []
add_comment comment
end
----------------------------------------
182b0a8 という argv[0] の VALUE は、直前の呼び出しで渡されている VALUE と
比べて不自然な感じはしないため、何故コケるのか判断できないでいます。
パッチに問題がある(排他制御が必要? argc として渡している変数または
argv として渡しているポインタが間違っている?)ということでしょうか?
よろしくお願いします。