From a58d0d4f51d78b8c6d02acbd7dd6060b27c9312a Mon Sep 17 00:00:00 2001 From: Charlie Savage Date: Sat, 6 Jan 2024 22:07:14 -0800 Subject: [PATCH] More test fixes. --- test/measure_process_time_test.rb | 827 +++++++++++++++++++++++++++++- test/measure_wall_time_test.rb | 2 +- 2 files changed, 827 insertions(+), 2 deletions(-) diff --git a/test/measure_process_time_test.rb b/test/measure_process_time_test.rb index aaa36adf..ae75157a 100644 --- a/test/measure_process_time_test.rb +++ b/test/measure_process_time_test.rb @@ -780,7 +780,7 @@ def test_module_instance_methods_busy assert_in_delta(0.0, method.self_time, 0.05) assert_in_delta(0.0, method.children_time, 0.05) end - else # Ruby 3.1 and higher + elsif Gem::Version.new(RUBY_VERSION) < Gem::Version.new('3.3') def test_class_methods_sleep result = RubyProf::Profile.profile(measure_mode: RubyProf::PROCESS_TIME) do RubyProf::C1.sleep_wait @@ -1544,6 +1544,831 @@ def test_module_instance_methods_sleep assert_in_delta(0.0, method.children_time, 0.05) end + def test_module_instance_methods_busy + result = RubyProf::Profile.profile(measure_mode: RubyProf::PROCESS_TIME) do + RubyProf::C2.new.busy_wait + end + + thread = result.threads.first + assert_in_delta(0.3, thread.total_time, 0.05) + + methods = result.threads.first.methods.sort.reverse + assert_equal(7, methods.length) + + # Check times + method = methods[0] + assert_equal('MeasureProcessTimeTest#test_module_instance_methods_busy', method.full_name) + assert_in_delta(0.3, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.3, method.children_time, 0.05) + + method = methods[1] + assert_equal('RubyProf::M1#busy_wait', method.full_name) + assert_in_delta(0.3, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.15, method.self_time, 0.05) + assert_in_delta(0.15, method.children_time, 0.05) + + method = methods[2] + assert_equal('#clock_gettime', method.full_name) + assert_in_delta(0.05, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.05, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[3] + assert_includes(['Float#<', 'Float#-'], method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[4] + assert_includes(['Float#<', 'Float#-'], method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[5] + assert_equal('Class#new', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[6] + assert_equal('BasicObject#initialize', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + end + else + def test_class_methods_sleep + result = RubyProf::Profile.profile(measure_mode: RubyProf::PROCESS_TIME) do + RubyProf::C1.sleep_wait + end + + thread = result.threads.first + assert_in_delta(0.0, thread.total_time, 0.05) + + methods = result.threads.first.methods.sort.reverse + assert_equal(3, methods.length) + + # Check times + method = methods[0] + assert_equal('MeasureProcessTimeTest#test_class_methods_sleep', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[1] + assert_equal('#sleep_wait', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[2] + assert_equal('Kernel#sleep', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + end + + def test_class_methods_sleep_threaded + result = RubyProf::Profile.profile(measure_mode: RubyProf::PROCESS_TIME) do + background_thread = Thread.new do + RubyProf::C1.sleep_wait + end + background_thread.join + end + + assert_equal(2, result.threads.count) + + thread = result.threads.first + assert_in_delta(0.0, thread.total_time, 0.05) + + methods = result.threads.first.methods.sort.reverse + assert_equal(4, methods.length) + + # Check times + method = methods[0] + assert_equal('MeasureProcessTimeTest#test_class_methods_sleep_threaded', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[1] + assert_equal('Thread#join', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[2] + assert_equal('#new', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[3] + assert_equal('Thread#initialize', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + thread = result.threads.last + assert_in_delta(0.0, thread.total_time, 0.05) + + methods = result.threads.first.methods.sort.reverse + assert_equal(4, methods.length) + + methods = result.threads.last.methods.sort.reverse + assert_equal(3, methods.length) + + # Check times + method = methods[0] + assert_equal('MeasureProcessTimeTest#test_class_methods_sleep_threaded', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[1] + assert_equal('#sleep_wait', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[2] + assert_equal('Kernel#sleep', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + end + + def test_class_methods_busy + result = RubyProf::Profile.profile(measure_mode: RubyProf::PROCESS_TIME) do + RubyProf::C1.busy_wait + end + + thread = result.threads.first + assert_in_delta(0.08, thread.total_time, 0.05) + + methods = result.threads.first.methods.sort.reverse + assert_equal(5, methods.length) + + # Check times + method = methods[0] + assert_equal('MeasureProcessTimeTest#test_class_methods_busy', method.full_name) + assert_in_delta(0.1, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.1, method.children_time, 0.05) + + method = methods[1] + assert_equal('#busy_wait', method.full_name) + assert_in_delta(0.1, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.06, method.self_time, 0.05) + assert_in_delta(0.07, method.children_time, 0.05) + + method = methods[2] + assert_equal('#clock_gettime', method.full_name) + assert_in_delta(0.05, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.05, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + end + + def test_class_methods_busy_threaded + result = RubyProf::Profile.profile(measure_mode: RubyProf::PROCESS_TIME) do + background_thread = Thread.new do + RubyProf::C1.busy_wait + end + background_thread.join + end + + assert_equal(2, result.threads.count) + + thread = result.threads.first + assert_in_delta(0.1, thread.total_time, 0.05) + + methods = result.threads.first.methods.sort.reverse + assert_equal(4, methods.length) + + # Check times + method = methods[0] + assert_equal('MeasureProcessTimeTest#test_class_methods_busy_threaded', method.full_name) + assert_in_delta(0.1, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.1, method.children_time, 0.05) + + method = methods[1] + assert_equal('Thread#join', method.full_name) + assert_in_delta(0.1, method.total_time, 0.05) + assert_in_delta(0.1, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[2] + assert_equal('#new', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[3] + assert_equal('Thread#initialize', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + thread = result.threads.last + assert_in_delta(0.1, thread.total_time, 0.05) + + methods = result.threads.first.methods.sort.reverse + assert_equal(4, methods.length) + + methods = result.threads.last.methods.sort.reverse + assert_equal(5, methods.length) + + # Check times + method = methods[0] + assert_equal('MeasureProcessTimeTest#test_class_methods_busy_threaded', method.full_name) + assert_in_delta(0.1, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.1, method.children_time, 0.05) + + method = methods[1] + assert_equal('#busy_wait', method.full_name) + assert_in_delta(0.1, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.05, method.self_time, 0.05) + assert_in_delta(0.05, method.children_time, 0.05) + + method = methods[2] + assert('#clock_gettime' == method.full_name || + 'Float#<' == method.full_name) + assert_in_delta(0.05, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.05, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + end + + def test_instance_methods_sleep + result = RubyProf::Profile.profile(measure_mode: RubyProf::PROCESS_TIME) do + RubyProf::C1.new.sleep_wait + end + + thread = result.threads.first + assert_in_delta(0.0, thread.total_time, 0.05) + + methods = result.threads.first.methods.sort.reverse + assert_equal(5, methods.length) + + # Check times + method = methods[0] + assert_equal('MeasureProcessTimeTest#test_instance_methods_sleep', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[1] + assert_equal('RubyProf::C1#sleep_wait', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[2] + assert_equal('Kernel#sleep', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[3] + assert_equal('Class#new', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[4] + assert_equal('BasicObject#initialize', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + end + + def test_instance_methods_sleep_block + result = RubyProf::Profile.profile(measure_mode: RubyProf::PROCESS_TIME) do + 1.times { RubyProf::C1.new.sleep_wait } + end + + methods = result.threads.first.methods.sort.reverse + assert_equal(6, methods.length) + + # Check times + method = methods[0] + assert_equal("MeasureProcessTimeTest#test_instance_methods_sleep_block", method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[1] + assert_equal('Integer#times', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[2] + assert_equal('RubyProf::C1#sleep_wait', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[3] + assert_equal('Kernel#sleep', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[4] + assert_equal('Class#new', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[5] + assert_equal('BasicObject#initialize', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + end + + def test_instance_methods_sleep_threaded + result = RubyProf::Profile.profile(measure_mode: RubyProf::PROCESS_TIME) do + background_thread = Thread.new do + RubyProf::C1.new.sleep_wait + end + background_thread.join + end + + assert_equal(2, result.threads.count) + + thread = result.threads.first + assert_in_delta(0.0, thread.total_time, 0.05) + + methods = result.threads.first.methods.sort.reverse + assert_equal(4, methods.length) + + # Check times + method = methods[0] + assert_equal('MeasureProcessTimeTest#test_instance_methods_sleep_threaded', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[1] + assert_equal('Thread#join', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[2] + assert_equal('#new', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[3] + assert_equal('Thread#initialize', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + thread = result.threads.last + assert_in_delta(0.0, thread.total_time, 0.05) + + methods = result.threads.first.methods.sort.reverse + assert_equal(4, methods.length) + + methods = result.threads.last.methods.sort.reverse + assert_equal(5, methods.length) + + # Check times + method = methods[0] + assert_equal('MeasureProcessTimeTest#test_instance_methods_sleep_threaded', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[1] + assert_equal('RubyProf::C1#sleep_wait', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[2] + assert_equal('Kernel#sleep', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[3] + assert_equal('Class#new', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[4] + assert_equal('BasicObject#initialize', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + end + + def test_instance_methods_busy + result = RubyProf::Profile.profile(measure_mode: RubyProf::PROCESS_TIME) do + RubyProf::C1.new.busy_wait + end + + thread = result.threads.first + assert_in_delta(0.2, thread.total_time, 0.05) + + methods = result.threads.first.methods.sort.reverse + assert_equal(7, methods.length) + + # Check times + method = methods[0] + assert_equal('MeasureProcessTimeTest#test_instance_methods_busy', method.full_name) + assert_in_delta(0.2, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.2, method.children_time, 0.05) + + method = methods[1] + assert_equal('RubyProf::C1#busy_wait', method.full_name) + assert_in_delta(0.2, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.09, method.self_time, 0.05) + assert_in_delta(0.11, method.children_time, 0.05) + + method = methods[2] + assert_equal('#clock_gettime', method.full_name) + assert_in_delta(0.033, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.033, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[3] + assert_includes(['Float#<', 'Float#-'], method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[4] + assert_includes(['Float#<', 'Float#-'], method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[5] + assert_equal('Class#new', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[6] + assert_equal('BasicObject#initialize', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + end + + def test_instance_methods_busy_block + result = RubyProf::Profile.profile(measure_mode: RubyProf::PROCESS_TIME) do + 1.times { RubyProf::C1.new.busy_wait } + end + + methods = result.threads.first.methods.sort.reverse + assert_equal(8, methods.length) + + # Check times + method = methods[0] + assert_equal("MeasureProcessTimeTest#test_instance_methods_busy_block", method.full_name) + assert_in_delta(0.2, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.2, method.children_time, 0.05) + + method = methods[1] + assert_equal('Integer#times', method.full_name) + assert_in_delta(0.2, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.2, method.children_time, 0.05) + + method = methods[2] + assert_equal('RubyProf::C1#busy_wait', method.full_name) + assert_in_delta(0.2, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.09, method.self_time, 0.05) + assert_in_delta(0.11, method.children_time, 0.05) + + method = methods[3] + assert_equal('#clock_gettime', method.full_name) + assert_in_delta(0.033, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.033, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[4] + assert_includes(['Float#<', 'Float#-'], method.full_name) + assert_in_delta(0.03, method.total_time, 0.03) + assert_in_delta(0.03, method.wait_time, 0.03) + assert_in_delta(0.03, method.self_time, 0.03) + assert_in_delta(0.03, method.children_time, 0.03) + + method = methods[5] + assert_includes(['Float#<', 'Float#-'], method.full_name) + assert_in_delta(0.03, method.total_time, 0.03) + assert_in_delta(0.03, method.wait_time, 0.03) + assert_in_delta(0.03, method.self_time, 0.03) + assert_in_delta(0.03, method.children_time, 0.03) + + method = methods[6] + assert_equal('Class#new', method.full_name) + assert_in_delta(0.0, method.total_time, 0.01) + assert_in_delta(0.0, method.wait_time, 0.01) + assert_in_delta(0.0, method.self_time, 0.01) + assert_in_delta(0.0, method.children_time, 0.01) + + method = methods[7] + assert_equal('BasicObject#initialize', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + end + + def test_instance_methods_busy_threaded + result = RubyProf::Profile.profile(measure_mode: RubyProf::PROCESS_TIME) do + background_thread = Thread.new do + RubyProf::C1.new.busy_wait + end + background_thread.join + end + + assert_equal(2, result.threads.count) + + thread = result.threads.first + assert_in_delta(0.2, thread.total_time, 0.05) + + methods = result.threads.first.methods.sort.reverse + assert_equal(4, methods.length) + + # Check times + method = methods[0] + assert_equal('MeasureProcessTimeTest#test_instance_methods_busy_threaded', method.full_name) + assert_in_delta(0.2, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.2, method.children_time, 0.05) + + method = methods[1] + assert_equal('Thread#join', method.full_name) + assert_in_delta(0.2, method.total_time, 0.05) + assert_in_delta(0.2, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[2] + assert_equal('#new', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[3] + assert_equal('Thread#initialize', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + thread = result.threads.last + assert_in_delta(0.2, thread.total_time, 0.05) + + methods = result.threads.first.methods.sort.reverse + assert_equal(4, methods.length) + + methods = result.threads.last.methods.sort.reverse + assert_equal(7, methods.length) + + # Check times + method = methods[0] + assert_equal('MeasureProcessTimeTest#test_instance_methods_busy_threaded', method.full_name) + assert_in_delta(0.2, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.2, method.children_time, 0.05) + + method = methods[1] + assert_equal('RubyProf::C1#busy_wait', method.full_name) + assert_in_delta(0.2, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.1, method.self_time, 0.05) + assert_in_delta(0.1, method.children_time, 0.05) + + method = methods[2] + assert_equal('#clock_gettime', method.full_name) + assert_in_delta(0.03, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.03, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[3] + assert_includes(['Float#<', 'Float#-'], method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[4] + assert_includes(['Float#<', 'Float#-'], method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[5] + assert_equal('Class#new', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[6] + assert_equal('BasicObject#initialize', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + end + + def test_module_methods_sleep + result = RubyProf::Profile.profile(measure_mode: RubyProf::PROCESS_TIME) do + RubyProf::C2.sleep_wait + end + + thread = result.threads.first + assert_in_delta(0.0, thread.total_time, 0.05) + + methods = result.threads.first.methods.sort.reverse + assert_equal(3, methods.length) + + # Check times + method = methods[0] + assert_equal('MeasureProcessTimeTest#test_module_methods_sleep', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[1] + assert_equal('RubyProf::M1#sleep_wait', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[2] + assert_equal('Kernel#sleep', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + end + + def test_module_methods_busy + result = RubyProf::Profile.profile(measure_mode: RubyProf::PROCESS_TIME) do + RubyProf::C2.busy_wait + end + + thread = result.threads.first + assert_in_delta(0.3, thread.total_time, 0.05) + + methods = result.threads.first.methods.sort.reverse + assert_equal(5, methods.length) + + # Check times + method = methods[0] + assert_equal('MeasureProcessTimeTest#test_module_methods_busy', method.full_name) + assert_in_delta(0.3, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.3, method.children_time, 0.05) + + method = methods[1] + assert_equal('RubyProf::M1#busy_wait', method.full_name) + assert_in_delta(0.3, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.15, method.self_time, 0.05) + assert_in_delta(0.15, method.children_time, 0.05) + + method = methods[2] + assert_equal('#clock_gettime', method.full_name) + assert_in_delta(0.05, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.05, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + end + + def test_module_instance_methods_sleep + result = RubyProf::Profile.profile(measure_mode: RubyProf::PROCESS_TIME) do + RubyProf::C2.new.sleep_wait + end + + thread = result.threads.first + assert_in_delta(0.0, thread.total_time, 0.05) + + methods = result.threads.first.methods.sort.reverse + assert_equal(5, methods.length) + + # Check times + method = methods[0] + assert_equal('MeasureProcessTimeTest#test_module_instance_methods_sleep', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[1] + assert_equal('RubyProf::M1#sleep_wait', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[2] + assert_equal('Kernel#sleep', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[3] + assert_equal('Class#new', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + + method = methods[4] + assert_equal('BasicObject#initialize', method.full_name) + assert_in_delta(0.0, method.total_time, 0.05) + assert_in_delta(0.0, method.wait_time, 0.05) + assert_in_delta(0.0, method.self_time, 0.05) + assert_in_delta(0.0, method.children_time, 0.05) + end + def test_module_instance_methods_busy result = RubyProf::Profile.profile(measure_mode: RubyProf::PROCESS_TIME) do RubyProf::C2.new.busy_wait diff --git a/test/measure_wall_time_test.rb b/test/measure_wall_time_test.rb index 567a9dd5..f3fd2ca6 100644 --- a/test/measure_wall_time_test.rb +++ b/test/measure_wall_time_test.rb @@ -157,7 +157,7 @@ def test_instance_methods assert_in_delta(0, method.self_time, 0.03 * @delta_multiplier) end - if Gem::Version.new(RUBY_VERSION) < Gem::Version.new('3.2') + if Gem::Version.new(RUBY_VERSION) < Gem::Version.new('3.3') def test_instance_methods_block result = RubyProf::Profile.profile(measure_mode: RubyProf::WALL_TIME) do 1.times { RubyProf::C1.new.sleep_wait }