From dbb0e6f0735d86dc47a8e38b44dfe6f672997c7f Mon Sep 17 00:00:00 2001 From: Charlie Savage Date: Tue, 12 May 2020 19:43:40 -0700 Subject: [PATCH] Remove merge fiber functionality since it can result in crashes. Fixes #266. --- ext/ruby_prof/rp_profile.c | 23 +--- ext/ruby_prof/rp_profile.h | 1 - test/fiber_test.rb | 242 +++++++++---------------------------- 3 files changed, 59 insertions(+), 207 deletions(-) diff --git a/ext/ruby_prof/rp_profile.c b/ext/ruby_prof/rp_profile.c index aa23eb62..9510b2f0 100644 --- a/ext/ruby_prof/rp_profile.c +++ b/ext/ruby_prof/rp_profile.c @@ -70,20 +70,12 @@ static const char* get_event_name(rb_event_flag_t event) } } -VALUE get_fiber(prof_profile_t* profile) -{ - if (profile->merge_fibers) - return rb_thread_current(); - else - return rb_fiber_current(); -} - thread_data_t* check_fiber(prof_profile_t* profile, double measurement) { thread_data_t* result = NULL; - /* Get the current thread and fiber information. */ - VALUE fiber = get_fiber(profile); + // Get the current fiber + VALUE fiber = rb_fiber_current(); /* We need to switch the profiling context if we either had none before, we don't merge fibers and the fiber ids differ, or the thread ids differ. */ @@ -172,7 +164,7 @@ prof_method_t* check_method(VALUE profile, rb_trace_arg_t* trace_arg, rb_event_f static void prof_trace(prof_profile_t* profile, rb_trace_arg_t* trace_arg, double measurement) { static VALUE last_fiber = Qnil; - VALUE fiber = get_fiber(profile); + VALUE fiber = rb_fiber_current(); rb_event_flag_t event = rb_tracearg_event_flag(trace_arg); const char* event_name = get_event_name(event); @@ -487,7 +479,6 @@ static VALUE prof_allocate(VALUE klass) profile->include_threads_tbl = NULL; profile->running = Qfalse; profile->allow_exceptions = false; - profile->merge_fibers = false; profile->exclude_methods_tbl = method_table_create(); profile->running = Qfalse; profile->tracepoints = rb_ary_new(); @@ -529,9 +520,6 @@ prof_stop_threads(prof_profile_t* profile) If not specified, defaults to RubyProf::WALL_TIME. allow_exceptions: Whether to raise exceptions encountered during profiling, or to suppress all exceptions during profiling - merge_fibers: Whether profiling data for a given thread's fibers should all be - subsumed under a single entry. Basically only useful to produce - callgrind profiles. track_allocations: Whether to track object allocations while profiling. True or false. exclude_common: Exclude common methods from the profile. True or false. exclude_threads: Threads to exclude from the profiling results. @@ -546,7 +534,6 @@ static VALUE prof_initialize(int argc, VALUE* argv, VALUE self) VALUE include_threads = Qnil; VALUE exclude_common = Qnil; VALUE allow_exceptions = Qfalse; - VALUE merge_fibers = Qfalse; VALUE track_allocations = Qfalse; int i; @@ -566,7 +553,6 @@ static VALUE prof_initialize(int argc, VALUE* argv, VALUE self) mode = rb_hash_aref(mode_or_options, ID2SYM(rb_intern("measure_mode"))); track_allocations = rb_hash_aref(mode_or_options, ID2SYM(rb_intern("track_allocations"))); allow_exceptions = rb_hash_aref(mode_or_options, ID2SYM(rb_intern("allow_exceptions"))); - merge_fibers = rb_hash_aref(mode_or_options, ID2SYM(rb_intern("merge_fibers"))); exclude_common = rb_hash_aref(mode_or_options, ID2SYM(rb_intern("exclude_common"))); exclude_threads = rb_hash_aref(mode_or_options, ID2SYM(rb_intern("exclude_threads"))); include_threads = rb_hash_aref(mode_or_options, ID2SYM(rb_intern("include_threads"))); @@ -587,7 +573,6 @@ static VALUE prof_initialize(int argc, VALUE* argv, VALUE self) } profile->measurer = prof_get_measurer(NUM2INT(mode), track_allocations == Qtrue); profile->allow_exceptions = (allow_exceptions == Qtrue); - profile->merge_fibers = (merge_fibers == Qtrue); if (exclude_threads != Qnil) { @@ -679,7 +664,7 @@ static VALUE prof_start(VALUE self) profile->running = Qtrue; profile->paused = Qfalse; - profile->last_thread_data = threads_table_insert(profile, get_fiber(profile)); + profile->last_thread_data = threads_table_insert(profile, rb_fiber_current()); /* open trace file if environment wants it */ trace_file_name = getenv("RUBY_PROF_TRACE"); diff --git a/ext/ruby_prof/rp_profile.h b/ext/ruby_prof/rp_profile.h index 1b942dc2..b9018429 100644 --- a/ext/ruby_prof/rp_profile.h +++ b/ext/ruby_prof/rp_profile.h @@ -26,7 +26,6 @@ typedef struct prof_profile_t thread_data_t* last_thread_data; double measurement_at_pause_resume; bool allow_exceptions; - bool merge_fibers; } prof_profile_t; void rp_init_profile(void); diff --git a/test/fiber_test.rb b/test/fiber_test.rb index 344cccbc..7b0e50b3 100644 --- a/test/fiber_test.rb +++ b/test/fiber_test.rb @@ -8,254 +8,122 @@ # -- Tests ---- class FiberTest < TestCase + def enumerator_with_fibers - @fiber_ids << Fiber.current.object_id enum = Enumerator.new do |yielder| [1,2].each do |x| - @fiber_ids << Fiber.current.object_id - sleep 0.1 yielder.yield x end end - while true - begin - enum.next - rescue StopIteration - break - end - end - sleep 0.1 + + enum.next + enum.next + end + + def fiber_yield_resume + fiber = Fiber.new do + Fiber.yield 1 + Fiber.yield 2 + end + + fiber.resume + fiber.resume end def setup # Need to use wall time for this test due to the sleep calls RubyProf::measure_mode = RubyProf::WALL_TIME - @fiber_ids = Set.new - @root_fiber = Fiber.current.object_id - @thread_id = Thread.current.object_id end def test_fibers result = RubyProf.profile { enumerator_with_fibers } - profiled_fiber_ids = result.threads.map(&:fiber_id) - assert_equal(2, result.threads.length) - assert_equal([@thread_id], result.threads.map(&:id).uniq) - assert_equal(@fiber_ids, Set.new(profiled_fiber_ids)) + assert_equal(2, result.threads.size) - assert profiled_fiber_ids.include?(@root_fiber) - assert(root_fiber_profile = result.threads.detect{|t| t.fiber_id == @root_fiber}) - assert(enum_fiber_profile = result.threads.detect{|t| t.fiber_id != @root_fiber}) - assert_in_delta(0.33, root_fiber_profile.total_time, 0.05) - assert_in_delta(0.33, enum_fiber_profile.total_time, 0.05) - - methods = result.threads[0].methods.sort.reverse - assert_equal(12, methods.count) + thread1 = result.threads[0] + methods = thread1.methods.sort.reverse + assert_equal(5, methods.count) method = methods[0] assert_equal('FiberTest#test_fibers', method.full_name) assert_equal(1, method.called) - assert_in_delta(0.33, method.total_time, 0.05) - assert_in_delta(0, method.self_time, 0.05) - assert_in_delta(0, method.wait_time, 0.05) - assert_in_delta(0.33, method.children_time, 0.05) method = methods[1] assert_equal('FiberTest#enumerator_with_fibers', method.full_name) assert_equal(1, method.called) - assert_in_delta(0.33, method.total_time, 0.05) - assert_in_delta(0, method.self_time, 0.05) - assert_in_delta(0, method.wait_time, 0.05) - assert_in_delta(0.33, method.children_time, 0.05) method = methods[2] assert_equal('Enumerator#next', method.full_name) - assert_equal(3, method.called) - assert_in_delta(0.22, method.total_time, 0.05) - assert_in_delta(0, method.self_time, 0.05) - assert_in_delta(0.22, method.wait_time, 0.05) - assert_in_delta(0, method.children_time, 0.05) + assert_equal(2, method.called) method = methods[3] - assert_equal('Kernel#sleep', method.full_name) - assert_equal(1, method.called) - assert_in_delta(0.11, method.total_time, 0.05) - assert_in_delta(0.11, method.self_time, 0.05) - assert_in_delta(0, method.wait_time, 0.05) - assert_in_delta(0, method.children_time, 0.05) - - # Since these methods have such short times their order is a bit indeterminate - method = methods.detect {|a_method| a_method.full_name == 'Class#new'} assert_equal('Class#new', method.full_name) assert_equal(1, method.called) - assert_in_delta(0, method.total_time, 0.05) - assert_in_delta(0, method.self_time, 0.05) - assert_in_delta(0, method.wait_time, 0.05) - assert_in_delta(0, method.children_time, 0.05) - - if Gem::Version.new(RUBY_VERSION) >= Gem::Version.new('2.5.0') - method = methods.detect {|a_method| a_method.full_name == 'Set#<<'} - assert_equal('Set#<<', method.full_name) - assert_equal(1, method.called) - assert_in_delta(0, method.total_time, 0.05) - assert_in_delta(0, method.self_time, 0.05) - assert_in_delta(0, method.wait_time, 0.05) - assert_in_delta(0, method.children_time, 0.05) - end - method = methods.detect {|a_method| a_method.full_name == 'Module#==='} - assert_equal('Module#===', method.full_name) + method = methods[4] + assert_equal('Enumerator#initialize', method.full_name) assert_equal(1, method.called) - assert_in_delta(0, method.total_time, 0.05) - assert_in_delta(0, method.self_time, 0.05) - assert_in_delta(0, method.wait_time, 0.05) - assert_in_delta(0, method.children_time, 0.05) - method = methods.detect {|a_method| a_method.full_name == 'Kernel#object_id'} - assert_equal('Kernel#object_id', method.full_name) - assert_equal(1, method.called) - assert_in_delta(0, method.total_time, 0.05) - assert_in_delta(0, method.self_time, 0.05) - assert_in_delta(0, method.wait_time, 0.05) - assert_in_delta(0, method.children_time, 0.05) + thread2 = result.threads[1] + methods = thread2.methods.sort.reverse + assert_equal(4, methods.count) - method = methods.detect {|a_method| a_method.full_name == '#current'} - assert_equal('#current', method.full_name) + method = methods[0] + assert_equal('Enumerator#each', method.full_name) assert_equal(1, method.called) - assert_in_delta(0, method.total_time, 0.05) - assert_in_delta(0, method.self_time, 0.05) - assert_in_delta(0, method.wait_time, 0.05) - assert_in_delta(0, method.children_time, 0.05) - method = methods.detect {|a_method| a_method.full_name == 'Exception#exception'} - assert_equal('Exception#exception', method.full_name) + method = methods[1] + assert_equal('Enumerator::Generator#each', method.full_name) assert_equal(1, method.called) - assert_in_delta(0, method.total_time, 0.05) - assert_in_delta(0, method.self_time, 0.05) - assert_in_delta(0, method.wait_time, 0.05) - assert_in_delta(0, method.children_time, 0.05) - method = methods.detect {|a_method| a_method.full_name == 'Exception#backtrace'} - assert_equal('Exception#backtrace', method.full_name) + method = methods[2] + assert_equal('Array#each', method.full_name) assert_equal(1, method.called) - assert_in_delta(0, method.total_time, 0.05) - assert_in_delta(0, method.self_time, 0.05) - assert_in_delta(0, method.wait_time, 0.05) - assert_in_delta(0, method.children_time, 0.05) - method = methods.detect {|a_method| a_method.full_name == 'Enumerator#initialize'} - assert_equal('Enumerator#initialize', method.full_name) - assert_equal(1, method.called) - assert_in_delta(0, method.total_time, 0.05) - assert_in_delta(0, method.self_time, 0.05) - assert_in_delta(0, method.wait_time, 0.05) - assert_in_delta(0, method.children_time, 0.05) + method = methods[3] + assert_equal('Enumerator::Yielder#yield', method.full_name) + assert_equal(2, method.called) + end - methods = result.threads[1].methods.sort.reverse + def test_fiber_resume + result = RubyProf.profile { fiber_yield_resume } - if Gem::Version.new(RUBY_VERSION) >= Gem::Version.new('2.6.0') - assert_equal(10, methods.count) - else - assert_equal(11, methods.count) - end + assert_equal(2, result.threads.size) + + thread1 = result.threads[0] + methods = thread1.methods.sort.reverse + assert_equal(5, methods.count) method = methods[0] - assert_equal('RubyProf::Profile#_inserted_parent_', method.full_name) + assert_equal('FiberTest#test_fiber_resume', method.full_name) assert_equal(1, method.called) - assert_in_delta(0.33, method.total_time, 0.05) - assert_in_delta(0, method.self_time, 0.05) - assert_in_delta(0.11, method.wait_time, 0.05) - assert_in_delta(0.22, method.children_time, 0.05) method = methods[1] - assert_equal('Enumerator#each', method.full_name) + assert_equal('FiberTest#fiber_yield_resume', method.full_name) assert_equal(1, method.called) - assert_in_delta(0.22, method.total_time, 0.05) - assert_in_delta(0, method.self_time, 0.05) - assert_in_delta(0, method.wait_time, 0.05) - assert_in_delta(0.22, method.children_time, 0.05) method = methods[2] - assert_equal('Enumerator::Generator#each', method.full_name) - assert_equal(1, method.called) - assert_in_delta(0.22, method.total_time, 0.05) - assert_in_delta(0, method.self_time, 0.05) - assert_in_delta(0, method.wait_time, 0.05) - assert_in_delta(0.22, method.children_time, 0.05) + assert_equal('Fiber#resume', method.full_name) + assert_equal(2, method.called) method = methods[3] - assert_equal('Array#each', method.full_name) + assert_equal('Class#new', method.full_name) assert_equal(1, method.called) - assert_in_delta(0.22, method.total_time, 0.05) - assert_in_delta(0, method.self_time, 0.05) - assert_in_delta(0, method.wait_time, 0.05) - assert_in_delta(0.22, method.children_time, 0.05) method = methods[4] - assert_equal('Kernel#sleep', method.full_name) - assert_equal(2, method.called) - assert_in_delta(0.22, method.total_time, 0.05) - assert_in_delta(0.22, method.self_time, 0.05) - assert_in_delta(0, method.wait_time, 0.05) - assert_in_delta(0, method.children_time, 0.05) - - # Since these methods have such short times their order is a bit indeterminate - method = methods.detect {|a_method| a_method.full_name == 'Exception#initialize'} - assert_equal('Exception#initialize', method.full_name) + assert_equal('Fiber#initialize', method.full_name) assert_equal(1, method.called) - assert_in_delta(0, method.total_time, 0.05) - assert_in_delta(0, method.self_time, 0.05) - assert_in_delta(0, method.wait_time, 0.05) - assert_in_delta(0, method.children_time, 0.05) - - if Gem::Version.new(RUBY_VERSION) >= Gem::Version.new('2.5.0') - method = methods.detect {|a_method| a_method.full_name == 'Set#<<'} - assert_equal('Set#<<', method.full_name) - assert_equal(2, method.called) - assert_in_delta(0, method.total_time, 0.05) - assert_in_delta(0, method.self_time, 0.05) - assert_in_delta(0, method.wait_time, 0.05) - assert_in_delta(0, method.children_time, 0.05) - end - method = methods.detect {|a_method| a_method.full_name == 'Kernel#object_id'} - assert_equal('Kernel#object_id', method.full_name) - assert_equal(2, method.called) - assert_in_delta(0, method.total_time, 0.05) - assert_in_delta(0, method.self_time, 0.05) - assert_in_delta(0, method.wait_time, 0.05) - assert_in_delta(0, method.children_time, 0.05) + thread1 = result.threads[1] + methods = thread1.methods.sort.reverse + assert_equal(2, methods.count) - method = methods.detect {|a_method| a_method.full_name == 'Enumerator::Yielder#yield'} - assert_equal('Enumerator::Yielder#yield', method.full_name) - assert_equal(2, method.called) - assert_in_delta(0, method.total_time, 0.05) - assert_in_delta(0, method.self_time, 0.05) - assert_in_delta(0, method.wait_time, 0.05) - assert_in_delta(0, method.children_time, 0.05) + method = methods[0] + assert_equal('FiberTest#fiber_yield_resume', method.full_name) + assert_equal(1, method.called) - method = methods.detect {|a_method| a_method.full_name == '#current'} - assert_equal('#current', method.full_name) + method = methods[1] + assert_equal('#yield', method.full_name) assert_equal(2, method.called) - assert_in_delta(0, method.total_time, 0.05) - assert_in_delta(0, method.self_time, 0.05) - assert_in_delta(0, method.wait_time, 0.05) - assert_in_delta(0, method.children_time, 0.05) - end - - def test_merged_fibers - result = RubyProf.profile(merge_fibers: true) { enumerator_with_fibers } - - assert_equal(1, result.threads.length) - - thread = result.threads.first - assert_equal(thread.id, thread.fiber_id) - assert_in_delta(0.3, thread.total_time, 0.05) - - assert(method_next = thread.methods.detect{|m| m.full_name == "Enumerator#next"}) - assert(method_each = thread.methods.detect{|m| m.full_name == "Enumerator#each"}) - - assert_in_delta(0.2, method_next.total_time, 0.05) - assert_in_delta(0.2, method_each.total_time, 0.05) end end