From: "ioquatix (Samuel Williams)" Date: 2022-06-29T03:23:22+00:00 Subject: [ruby-core:109084] [Ruby master Bug#18886] Struct aref and aset don't trigger any tracepoints. Issue #18886 has been updated by ioquatix (Samuel Williams). Here is my performance comparison: Firstly, with no changes (should be identical, shows some variance). ``` > make benchmark ITEM=vm_struct COMPARE_RUBY=(which ruby) /home/samuel/.rubies/ruby-head/bin/ruby --disable=gems -rrubygems -I../benchmark/lib ../benchmark/benchmark-driver/exe/benchmark-driver \ --executables="compare-ruby::/home/samuel/.rubies/ruby-head/bin/ruby -I.ext/common --disable-gem" \ --executables="built-ruby::./miniruby -I../lib -I. -I.ext/common ../tool/runruby.rb --extout=.ext -- --disable-gems --disable-gem" \ --output=markdown --output-compare -v $(find ../benchmark -maxdepth 1 -name 'vm_struct' -o -name '*vm_struct*.yml' -o -name '*vm_struct*.rb' | sort) compare-ruby: ruby 3.2.0dev (2022-06-29T00:53:14Z master 3051d4bc2a) [x86_64-linux] built-ruby: ruby 3.2.0dev (2022-06-29T02:51:15Z struct-tracepoints 12e97af1d2) [x86_64-linux] # Iteration per second (i/s) | |compare-ruby|built-ruby| |:----------------------|-----------:|---------:| |vm_struct_big_aref_hi | 149.515M| 147.470M| | | 1.01x| -| |vm_struct_big_aref_lo | 148.916M| 147.628M| | | 1.01x| -| |vm_struct_big_aset | 7.006| 7.080| | | -| 1.01x| |vm_struct_big_href_hi | 27.652M| 27.382M| | | 1.01x| -| |vm_struct_big_href_lo | 27.547M| 27.725M| | | -| 1.01x| |vm_struct_big_hset | 3.049| 3.094| | | -| 1.01x| |vm_struct_small_aref | 144.031M| 136.167M| | | 1.06x| -| |vm_struct_small_aset | 7.032| 7.063| | | -| 1.00x| |vm_struct_small_href | 30.694M| 30.432M| | | 1.01x| -| |vm_struct_small_hset | 28.590M| 28.083M| | | 1.02x| -| ``` Now with my PR: ``` > make benchmark ITEM=vm_struct COMPARE_RUBY=(which ruby) /home/samuel/.rubies/ruby-head/bin/ruby --disable=gems -rrubygems -I../benchmark/lib ../benchmark/benchmark-driver/exe/benchmark-driver \ --executables="compare-ruby::/home/samuel/.rubies/ruby-head/bin/ruby -I.ext/common --disable-gem" \ --executables="built-ruby::./miniruby -I../lib -I. -I.ext/common ../tool/runruby.rb --extout=.ext -- --disable-gems --disable-gem" \ --output=markdown --output-compare -v $(find ../benchmark -maxdepth 1 -name 'vm_struct' -o -name '*vm_struct*.yml' -o -name '*vm_struct*.rb' | sort) compare-ruby: ruby 3.2.0dev (2022-06-29T00:53:14Z master 3051d4bc2a) [x86_64-linux] built-ruby: ruby 3.2.0dev (2022-06-29T02:51:15Z struct-tracepoints 12e97af1d2) [x86_64-linux] # Iteration per second (i/s) | |compare-ruby|built-ruby| |:----------------------|-----------:|---------:| |vm_struct_big_aref_hi | 147.665M| 115.510M| | | 1.28x| -| |vm_struct_big_aref_lo | 146.666M| 116.298M| | | 1.26x| -| |vm_struct_big_aset | 7.098| 6.801| | | 1.04x| -| |vm_struct_big_href_hi | 27.608M| 27.957M| | | -| 1.01x| |vm_struct_big_href_lo | 27.521M| 27.937M| | | -| 1.02x| |vm_struct_big_hset | 3.092| 3.113| | | -| 1.01x| |vm_struct_small_aref | 147.494M| 113.729M| | | 1.30x| -| |vm_struct_small_aset | 6.898| 6.840| | | 1.01x| -| |vm_struct_small_href | 31.004M| 31.547M| | | -| 1.02x| |vm_struct_small_hset | 28.433M| 28.527M| | | -| 1.00x| ``` With changes suggested by @ko1: ``` > make benchmark ITEM=vm_struct COMPARE_RUBY=(which ruby) /home/samuel/.rubies/ruby-head/bin/ruby --disable=gems -rrubygems -I../benchmark/lib ../benchmark/benchmark-driver/exe/benchmark-driver \ --executables="compare-ruby::/home/samuel/.rubies/ruby-head/bin/ruby -I.ext/common --disable-gem" \ --executables="built-ruby::./miniruby -I../lib -I. -I.ext/common ../tool/runruby.rb --extout=.ext -- --disable-gems --disable-gem" \ --output=markdown --output-compare -v $(find ../benchmark -maxdepth 1 -name 'vm_struct' -o -name '*vm_struct*.yml' -o -name '*vm_struct*.rb' | sort) compare-ruby: ruby 3.2.0dev (2022-06-29T00:53:14Z master 3051d4bc2a) [x86_64-linux] built-ruby: ruby 3.2.0dev (2022-06-29T02:51:15Z struct-tracepoints 12e97af1d2) [x86_64-linux] # Iteration per second (i/s) | |compare-ruby|built-ruby| |:----------------------|-----------:|---------:| |vm_struct_big_aref_hi | 146.836M| 115.141M| | | 1.28x| -| |vm_struct_big_aref_lo | 147.929M| 115.918M| | | 1.28x| -| |vm_struct_big_aset | 7.079| 6.802| | | 1.04x| -| |vm_struct_big_href_hi | 27.495M| 27.933M| | | -| 1.02x| |vm_struct_big_href_lo | 27.396M| 27.584M| | | -| 1.01x| |vm_struct_big_hset | 3.128| 3.095| | | 1.01x| -| |vm_struct_small_aref | 142.123M| 113.700M| | | 1.25x| -| |vm_struct_small_aset | 6.995| 6.755| | | 1.04x| -| |vm_struct_small_href | 30.561M| 31.424M| | | -| 1.03x| |vm_struct_small_hset | 28.353M| 28.650M| | | -| 1.01x| ``` It seems like 25-30% performance impact, but this is still a very fast operation. Is there any way we can make this faster? Could we have tracing and non-tracing op-codes which call different functions? e.g. `vm_call_opt_struct_aref` and `vm_call_opt_struct_aref_trace` for example. ---------------------------------------- Bug #18886: Struct aref and aset don't trigger any tracepoints. https://bugs.ruby-lang.org/issues/18886#change-98229 * Author: ioquatix (Samuel Williams) * Status: Open * Priority: Normal * Assignee: ko1 (Koichi Sasada) * Backport: 2.7: UNKNOWN, 3.0: UNKNOWN, 3.1: UNKNOWN ---------------------------------------- Given the following program, `thing.name` and `thing.shape` don't trigger `c_call` trace points (or any trace points actually). ```ruby pp RUBY_VERSION trace_point = TracePoint.new(:line, :call, :c_call, :a_call) do |trace| puts trace.event if trace.event == :call # Ruby doesn't always mark call-sites in sub-expressions, so we use this approach to compute a call site and mark it: if location = caller_locations(2, 1).first and path = location.path puts "> #{path}:#{location.lineno}:#{trace.event}" end end if path = trace.path puts "= #{path}:#{trace.lineno}:#{trace.event}" end end trace_point.enable # This will trigger call trace points class Thing def name :cat end def shape :square end end thing = Thing.new # Thing = Struct.new(:name, :shape) # thing = Thing.new(:cat, :rectangle) [ name: thing.name, shape: thing.shape, ] ``` ## Current HEAD ``` = ../test.rb:30:line: = ../test.rb:30:c_call:new = ../test.rb:30:c_call:inherited = ../test.rb:30:c_call:singleton_method_added = ../test.rb:30:c_call:singleton_method_added = ../test.rb:30:c_call:singleton_method_added = ../test.rb:30:c_call:singleton_method_added = ../test.rb:30:c_call:singleton_method_added = ../test.rb:30:c_call:method_added = ../test.rb:30:c_call:method_added = ../test.rb:30:c_call:method_added = ../test.rb:30:c_call:method_added = ../test.rb:30:c_call:const_added = ../test.rb:31:line: = ../test.rb:31:c_call:new = ../test.rb:31:c_call:initialize = ../test.rb:34:line: ``` ## Proposed PR ``` = ../test.rb:30:line: = ../test.rb:30:c_call:new = ../test.rb:30:c_call:inherited = ../test.rb:30:c_call:singleton_method_added = ../test.rb:30:c_call:singleton_method_added = ../test.rb:30:c_call:singleton_method_added = ../test.rb:30:c_call:singleton_method_added = ../test.rb:30:c_call:singleton_method_added = ../test.rb:30:c_call:method_added = ../test.rb:30:c_call:method_added = ../test.rb:30:c_call:method_added = ../test.rb:30:c_call:method_added = ../test.rb:30:c_call:const_added = ../test.rb:31:line: = ../test.rb:31:c_call:new = ../test.rb:31:c_call:initialize = ../test.rb:34:line: = ../test.rb:34:c_call:name = ../test.rb:35:c_call:shape ``` The reason is the internal implementation of struct doesn't have trace point instrumentation in `vm_call_opt_struct_aset` or `vm_call_opt_struct_aref`. Proposed fix: https://github.com/ruby/ruby/pull/6071 but this would need a review, maybe @jeremyevans0 and @ko1 can help. -- https://bugs.ruby-lang.org/ Unsubscribe: