Allow tracing of optimized methods

jeremyevans · k0kubun · web-flow · commit 48c8df9e0eb2 · 2021-08-21T10:15:01.000-07:00
This updates the trace instructions to directly dispatch to
opt_send_without_block.  So this should cause no slowdown in
non-trace mode.

To enable the tracing of the optimized methods, RUBY_EVENT_C_CALL
and RUBY_EVENT_C_RETURN are added as events to the specialized
instructions.

Fixes [Bug #14870]

Co-authored-by: Takashi Kokubun &lt;takashikkbn@gmail.com&gt;
diff --git a/compile.c b/compile.c
@@ -3441,6 +3441,7 @@ insn_set_specialized_instruction(rb_iseq_t *iseq, INSN *iobj, int insn_id)
 {
     iobj->insn_id = insn_id;
     iobj->operand_size = insn_len(insn_id) - 1;
+    iobj->insn_info.events |= RUBY_EVENT_C_CALL | RUBY_EVENT_C_RETURN;
 
     if (insn_id == BIN(opt_neq)) {
         VALUE original_ci = iobj->operands[0];
diff --git a/iseq.h b/iseq.h
@@ -74,6 +74,8 @@ ISEQ_ORIGINAL_ISEQ_ALLOC(const rb_iseq_t *iseq, long size)
 			   RUBY_EVENT_END   | \
 			   RUBY_EVENT_CALL  | \
 			   RUBY_EVENT_RETURN| \
+                           RUBY_EVENT_C_CALL| \
+                           RUBY_EVENT_C_RETURN| \
 			   RUBY_EVENT_B_CALL| \
 			   RUBY_EVENT_B_RETURN| \
                            RUBY_EVENT_COVERAGE_LINE| \
diff --git a/spec/ruby/core/tracepoint/inspect_spec.rb b/spec/ruby/core/tracepoint/inspect_spec.rb
@@ -65,11 +65,12 @@ def trace_point_spec_test_return
   it 'returns a String showing the event, method, path and line for a :c_call event' do
     inspect = nil
     line = nil
-    TracePoint.new(:c_call) { |tp|
+    tp = TracePoint.new(:c_call) { |tp|
       next unless TracePointSpec.target_thread?
       inspect ||= tp.inspect
-    }.enable do
-      line = __LINE__ + 1
+    }
+    line = __LINE__ + 2
+    tp.enable do
       [0, 1].max
     end
 
diff --git a/test/ruby/test_optimization.rb b/test/ruby/test_optimization.rb
@@ -150,6 +150,51 @@ def test_string_uminus
     assert_redefine_method('String', '-@', 'assert_nil(-"foo")')
   end
 
+  def test_trace_optimized_methods
+    bug14870 = "[ruby-core:87638]"
+    expected = [:-@, :max, :min, :+, :-, :*, :/, :%, :==, :<, :<=, :>, :>=, :<<,
+                :&, :|, :[], :[]=, :length, :empty?, :nil?, :succ, :!, :=~]
+    [:c_call, :c_return].each do |type|
+      methods = []
+      tp = TracePoint.new(type) { |tp| methods << tp.method_id }
+      tp.enable do
+        x = "a"; -x
+        [1].max
+        [1].min
+        x = 42 + 2
+        x = 42 - 2
+        x = 42 * 2
+        x = 42 / 2
+        x = 42 % 2
+        x == 42
+        x < 42
+        x <= 42
+        x > 42
+        x >= 42
+        x = x << 1
+        x = x & 1
+        x = x | 1
+        x = []; x[1]
+        x[1] = 2
+        x.length
+        x.empty?
+        x.nil?
+        x = 1; x.succ
+        !x
+        x = 'a'; x =~ /a/
+      end
+      assert_equal(expected, methods, bug14870)
+    end
+
+    methods = []
+    tp = TracePoint.new(:c_call, :c_return) { |tp| methods << tp.method_id }
+    tp.enable do
+      x = 1
+      x != 42
+    end
+    assert_equal([:!=, :==, :==, :!=], methods, bug14870)
+  end
+
   def test_string_freeze_saves_memory
     n = 16384
     data = '.'.freeze
diff --git a/tool/ruby_vm/views/_trace_instruction.erb b/tool/ruby_vm/views/_trace_instruction.erb
@@ -11,6 +11,11 @@
 INSN_ENTRY(<%= insn.name %>)
 {
     vm_trace(ec, GET_CFP());
-    DISPATCH_ORIGINAL_INSN(<%= insn.jump_destination %>);
+%   if insn.name =~
+%   /\Atrace_opt_(plus|minus|mult|div|mod|eq|neq|lt|le|gt|ge|ltlt|and|or|aref|aset|length|size|empty_p|nil_p|succ|not|regexpmatch2)\z/
+%     jump_dest = "opt_send_without_block"
+%   end
+    <%= 'ADD_PC(1);' if insn.name == 'trace_opt_neq' %>
+    DISPATCH_ORIGINAL_INSN(<%= jump_dest || insn.jump_destination %>);
     END_INSN(<%= insn.name %>);
 }

Original file line number	Diff line number	Diff line change
`@@ -3441,6 +3441,7 @@ insn_set_specialized_instruction(rb_iseq_t iseq, INSN iobj, int insn_id)`
`3441`	`3441`	`{`
`3442`	`3442`	`iobj->insn_id = insn_id;`
`3443`	`3443`	`iobj->operand_size = insn_len(insn_id) - 1;`
	`3444`	`+ iobj->insn_info.events \|= RUBY_EVENT_C_CALL \| RUBY_EVENT_C_RETURN;`
`3444`	`3445`
`3445`	`3446`	`if (insn_id == BIN(opt_neq)) {`
`3446`	`3447`	`VALUE original_ci = iobj->operands[0];`
Original file line number	Diff line number	Diff line change
`@@ -11,6 +11,11 @@`
`11`	`11`	`INSN_ENTRY(<%= insn.name %>)`
`12`	`12`	`{`
`13`	`13`	`vm_trace(ec, GET_CFP());`
`14`		`- DISPATCH_ORIGINAL_INSN(<%= insn.jump_destination %>);`
	`14`	`+% if insn.name =~`
	`15`	`+% /\Atrace_opt_(plus\|minus\|mult\|div\|mod\|eq\|neq\|lt\|le\|gt\|ge\|ltlt\|and\|or\|aref\|aset\|length\|size\|empty_p\|nil_p\|succ\|not\|regexpmatch2)\z/`
	`16`	`+% jump_dest = "opt_send_without_block"`
	`17`	`+% end`
	`18`	`+ <%= 'ADD_PC(1);' if insn.name == 'trace_opt_neq' %>`
	`19`	`+ DISPATCH_ORIGINAL_INSN(<%= jump_dest \|\| insn.jump_destination %>);`
`15`	`20`	`END_INSN(<%= insn.name %>);`
`16`	`21`	`}`