ext/measure_gc_runs.h ext/measure_gc_time.h ext/version.h lib/ruby-prof/test.rb test/measurement_test.rb @@ -6,7 +6,7 @@ # # == Usage # -# ruby_prof [options] <script.rb> [options-for-script] +# ruby_prof [options] <script.rb> [--] [script-options]" # # Options: # -p, --printer=printer Select a printer: @@ -25,6 +25,12 @@ # (only supported on Pentium and PowerPCs). # allocations - Tracks object allocations # (requires a patched Ruby interpreter). +# memory - Tracks total memory size +# (requires a patched Ruby interpreter). +# gc_runs - Tracks number of garbage collection runs +# (requires a patched Ruby interpreter). +# gc_time - Tracks time spent doing garbage collection +# (requires a patched Ruby interpreter). # --replace-progname Replace $0 when loading the .rb files. # --specialized-instruction Turn on specialized instruction. # -h, --help Show help message @@ -48,7 +54,7 @@ options.specialized_instruction = false opts = OptionParser.new do |opts| opts.banner = "ruby_prof #{RubyProf::VERSION}\n" + - "Usage: ruby_prof [options] <script.rb> [--extra-options-for-script]" + "Usage: ruby_prof [options] <script.rb> [--] [script-options]" opts.separator "" opts.separator "Options:" @@ -87,12 +93,15 @@ opts = OptionParser.new do |opts| end opts.on('--mode=measure_mode', - [:process, :wall, :cpu, :allocations], + [:process, :wall, :cpu, :allocations, :memory, :gc_runs, :gc_time], 'Select what ruby-prof should measure:', ' process - Process time (default).', ' wall - Wall time.', ' cpu - CPU time (Pentium and PowerPCs only).', - ' allocations - Object allocations (requires patched Ruby interpreter).') do |measure_mode| + ' allocations - Object allocations (requires patched Ruby interpreter).', + ' memory - Allocated memory in KB (requires patched Ruby interpreter).', + ' gc_runs - Number of garbage collections (requires patched Ruby interpreter).', + ' gc_time - Time spent in garbage collection (requires patched Ruby interpreter).') do |measure_mode| case measure_mode when :process @@ -103,6 +112,12 @@ opts = OptionParser.new do |opts| options.measure_mode = RubyProf::CPU_TIME when :allocations options.measure_mode = RubyProf::ALLOCATIONS + when :memory + options.measure_mode = RubyProf::MEMORY + when :gc_runs + options.measure_mode = RubyProf::GC_RUNS + when :gc_time + options.measure_mode = RubyProf::GC_TIME end end bin/ruby-prof @@ -16,6 +16,19 @@ else end have_header("sys/times.h") + +# Stefan Kaes / Alexander Dymo GC patch have_func("rb_os_allocated_objects") have_func("rb_gc_allocated_size") +have_func("rb_gc_collections") +have_func("rb_gc_time") + +# Lloyd Hilaiel's heap info patch +have_func("rb_heap_total_mem") +have_func("rb_gc_heap_info") + +# Ruby 1.9 unexposed methods +have_func("rb_gc_malloc_allocations") +have_func("rb_gc_malloc_allocated_size") + create_makefile("ruby_prof") ext/extconf.rb @@ -24,6 +24,7 @@ * OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF * SUCH DAMAGE. */ +#include <ruby.h> #if defined(HAVE_RB_OS_ALLOCATED_OBJECTS) #define MEASURE_ALLOCATIONS 3 @@ -40,4 +41,19 @@ convert_allocations(prof_measure_t c) return c; } +/* Document-method: prof_measure_allocations + call-seq: + measure_allocations -> int + +Returns the total number of object allocations since Ruby started.*/ +static VALUE +prof_measure_allocations(VALUE self) +{ +#if defined(HAVE_LONG_LONG) + return ULL2NUM(rb_os_allocated_objects()); +#else + return ULONG2NUM(rb_os_allocated_objects()); +#endif +} #endif + ext/measure_allocations.h @@ -24,6 +24,7 @@ * OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF * SUCH DAMAGE. */ +#include <ruby.h> #if defined(_WIN32) || (defined(__GNUC__) && (defined(__i386__) || defined(__powerpc__) || defined(__ppc__))) #define MEASURE_CPU_TIME 2 @@ -110,6 +111,17 @@ convert_cpu_time(prof_measure_t c) return (double) c / cpu_frequency; } +/* Document-method: prof_measure_cpu_time + call-seq: + measure_cpu_time -> float + +Returns the cpu time.*/ +static VALUE +prof_measure_cpu_time(VALUE self) +{ + return rb_float_new(convert_cpu_time(measure_cpu_time())); +} + /* Document-method: prof_get_cpu_frequency call-seq: cpu_frequency -> int @@ -119,7 +131,7 @@ RubyProf::measure_mode is set to CPU_TIME. */ static VALUE prof_get_cpu_frequency(VALUE self) { - return LONG2NUM(cpu_frequency); + return ULL2NUM(cpu_frequency); } /* Document-method: prof_set_cpu_frequency @@ -131,7 +143,7 @@ RubyProf::measure_mode is set to CPU_TIME. */ static VALUE prof_set_cpu_frequency(VALUE self, VALUE val) { - cpu_frequency = NUM2LONG(val); + cpu_frequency = NUM2LL(val); return val; } ext/measure_cpu_time.h @@ -26,17 +26,79 @@ #if defined(HAVE_RB_GC_ALLOCATED_SIZE) #define MEASURE_MEMORY 4 +#define TOGGLE_GC_STATS 1 static prof_measure_t measure_memory() { - return rb_gc_allocated_size(); +#if defined(HAVE_LONG_LONG) + return NUM2LL(rb_gc_allocated_size()); +#else + return NUM2ULONG(rb_gc_allocated_size()); +#endif } static double convert_memory(prof_measure_t c) { - return c / 1024; + return (double) c / 1024; +} + +/* Document-method: prof_measure_memory + call-seq: + measure_memory -> int + +Returns total allocated memory in bytes.*/ +static VALUE +prof_measure_memory(VALUE self) +{ + return rb_gc_allocated_size(); +} + +#elif defined(HAVE_RB_GC_MALLOC_ALLOCATED_SIZE) +#define MEASURE_MEMORY 4 + +static prof_measure_t +measure_memory() +{ +#if defined(HAVE_LONG_LONG) + return NUM2LL(rb_gc_malloc_allocated_size()); +#else + return NUM2ULONG(rb_gc_malloc_allocated_size()); +#endif +} + +static double +convert_memory(prof_measure_t c) +{ + return (double) c / 1024; +} + +static VALUE +prof_measure_memory(VALUE self) +{ + return rb_gc_malloc_allocated_size(); +} + +#elif defined(HAVE_RB_HEAP_TOTAL_MEM) +#define MEASURE_MEMORY 4 + +static prof_measure_t +measure_memory() +{ + return rb_heap_total_mem(); +} + +static double +convert_memory(prof_measure_t c) +{ + return (double) c / 1024; +} + +static VALUE +prof_measure_memory(VALUE self) +{ + return ULONG2NUM(rb_heap_total_mem()); } #endif ext/measure_memory.h @@ -39,3 +39,14 @@ convert_process_time(prof_measure_t c) { return (double) c / CLOCKS_PER_SEC; } + +/* Document-method: prof_measure_process_time + call-seq: + measure_process_time -> float + +Returns the process time.*/ +static VALUE +prof_measure_process_time(VALUE self) +{ + return rb_float_new(convert_process_time(measure_process_time())); +} ext/measure_process_time.h @@ -40,3 +40,14 @@ convert_wall_time(prof_measure_t c) { return (double) c / 1000000; } + +/* Document-method: prof_measure_wall_time + call-seq: + measure_wall_time -> float + +Returns the wall time.*/ +static VALUE +prof_measure_wall_time(VALUE self) +{ + return rb_float_new(convert_wall_time(measure_wall_time())); +} ext/measure_wall_time.h @@ -59,15 +59,15 @@ typedef rb_event_t rb_event_flag_t; #define rb_sourceline() (node ? nd_line(node) : 0) #endif +#include "version.h" /* ================ Constants =================*/ #define INITIAL_STACK_SIZE 8 -#define PROF_VERSION "0.6.1" /* ================ Measurement =================*/ #ifdef HAVE_LONG_LONG -typedef LONG_LONG prof_measure_t; +typedef unsigned LONG_LONG prof_measure_t; #else typedef unsigned long prof_measure_t; #endif @@ -77,6 +77,8 @@ typedef unsigned long prof_measure_t; #include "measure_cpu_time.h" #include "measure_allocations.h" #include "measure_memory.h" +#include "measure_gc_runs.h" +#include "measure_gc_time.h" static prof_measure_t (*get_measurement)() = measure_process_time; static double (*convert_measurement)(prof_measure_t) = convert_process_time; @@ -1011,7 +1013,7 @@ get_event_name(rb_event_flag_t event) return "raise"; default: return "unknown"; - } + } } static void @@ -1111,8 +1113,10 @@ prof_event_hook(rb_event_flag_t event, NODE *node, VALUE self, ID mid, VALUE kla unsigned long thread_id = get_thread_id(thread); char* class_name = rb_obj_classname(klass); char* method_name = rb_id2name(mid); - char* source_file = node ? node->nd_file : 0; - unsigned int source_line = node ? nd_line(node) : 0; + + char* source_file = rb_sourcefile(); + unsigned int source_line = rb_sourceline(); + char* event_name = get_event_name(event); if (last_thread_id != thread_id) @@ -1374,7 +1378,9 @@ prof_result_threads(VALUE self) *RubyProf::WALL_TIME - Measure wall time using gettimeofday on Linx and GetLocalTime on Windows *RubyProf::CPU_TIME - Measure time using the CPU clock counter. This mode is only supported on Pentium or PowerPC platforms. *RubyProf::ALLOCATIONS - Measure object allocations. This requires a patched Ruby interpreter. - *RubyProf::MEMORY - Measure memory size. This requires a patched Ruby interpreter.*/ + *RubyProf::MEMORY - Measure memory size. This requires a patched Ruby interpreter. + *RubyProf::GC_RUNS - Measure number of garbage collections. This requires a patched Ruby interpreter. + *RubyProf::GC_TIME - Measure time spent doing garbage collection. This requires a patched Ruby interpreter.*/ static VALUE prof_get_measure_mode(VALUE self) { @@ -1390,7 +1396,9 @@ prof_get_measure_mode(VALUE self) *RubyProf::WALL_TIME - Measure wall time using gettimeofday on Linx and GetLocalTime on Windows *RubyProf::CPU_TIME - Measure time using the CPU clock counter. This mode is only supported on Pentium or PowerPC platforms. *RubyProf::ALLOCATIONS - Measure object allocations. This requires a patched Ruby interpreter. - *RubyProf::MEMORY - Measure memory size. This requires a patched Ruby interpreter.*/ + *RubyProf::MEMORY - Measure memory size. This requires a patched Ruby interpreter. + *RubyProf::GC_RUNS - Measure number of garbage collections. This requires a patched Ruby interpreter. + *RubyProf::GC_TIME - Measure time spent doing garbage collection. This requires a patched Ruby interpreter.*/ static VALUE prof_set_measure_mode(VALUE self, VALUE val) { @@ -1434,7 +1442,21 @@ prof_set_measure_mode(VALUE self, VALUE val) convert_measurement = convert_memory; break; #endif - + + #if defined(MEASURE_GC_RUNS) + case MEASURE_GC_RUNS: + get_measurement = measure_gc_runs; + convert_measurement = convert_gc_runs; + break; + #endif + + #if defined(MEASURE_GC_TIME) + case MEASURE_GC_TIME: + get_measurement = measure_gc_time; + convert_measurement = convert_gc_time; + break; + #endif + default: rb_raise(rb_eArgError, "invalid mode: %d", mode); break; @@ -1460,7 +1482,7 @@ prof_install_hook() | RUBY_EVENT_LINE); #endif -#if defined(MEASURE_MEMORY) +#if defined(TOGGLE_GC_STATS) rb_gc_enable_stats(); #endif } @@ -1468,7 +1490,7 @@ prof_install_hook() void prof_remove_hook() { -#if defined(MEASURE_MEMORY) +#if defined(TOGGLE_GC_STATS) rb_gc_disable_stats(); #endif @@ -1601,7 +1623,7 @@ void Init_ruby_prof() { mProf = rb_define_module("RubyProf"); - rb_define_const(mProf, "VERSION", rb_str_new2(PROF_VERSION)); + rb_define_const(mProf, "VERSION", rb_str_new2(RUBY_PROF_VERSION)); rb_define_module_function(mProf, "start", prof_start, 0); rb_define_module_function(mProf, "stop", prof_stop, 0); rb_define_module_function(mProf, "resume", prof_resume, 0); @@ -1614,12 +1636,15 @@ Init_ruby_prof() rb_define_const(mProf, "CLOCKS_PER_SEC", INT2NUM(CLOCKS_PER_SEC)); rb_define_const(mProf, "PROCESS_TIME", INT2NUM(MEASURE_PROCESS_TIME)); + rb_define_singleton_method(mProf, "measure_process_time", prof_measure_process_time, 0); /* in measure_process_time.h */ rb_define_const(mProf, "WALL_TIME", INT2NUM(MEASURE_WALL_TIME)); + rb_define_singleton_method(mProf, "measure_wall_time", prof_measure_wall_time, 0); /* in measure_wall_time.h */ #ifndef MEASURE_CPU_TIME rb_define_const(mProf, "CPU_TIME", Qnil); #else rb_define_const(mProf, "CPU_TIME", INT2NUM(MEASURE_CPU_TIME)); + rb_define_singleton_method(mProf, "measure_cpu_time", prof_measure_cpu_time, 0); /* in measure_cpu_time.h */ rb_define_singleton_method(mProf, "cpu_frequency", prof_get_cpu_frequency, 0); /* in measure_cpu_time.h */ rb_define_singleton_method(mProf, "cpu_frequency=", prof_set_cpu_frequency, 1); /* in measure_cpu_time.h */ #endif @@ -1628,14 +1653,30 @@ Init_ruby_prof() rb_define_const(mProf, "ALLOCATIONS", Qnil); #else rb_define_const(mProf, "ALLOCATIONS", INT2NUM(MEASURE_ALLOCATIONS)); + rb_define_singleton_method(mProf, "measure_allocations", prof_measure_allocations, 0); /* in measure_allocations.h */ #endif #ifndef MEASURE_MEMORY rb_define_const(mProf, "MEMORY", Qnil); #else rb_define_const(mProf, "MEMORY", INT2NUM(MEASURE_MEMORY)); + rb_define_singleton_method(mProf, "measure_memory", prof_measure_memory, 0); /* in measure_memory.h */ #endif - + + #ifndef MEASURE_GC_RUNS + rb_define_const(mProf, "GC_RUNS", Qnil); + #else + rb_define_const(mProf, "GC_RUNS", INT2NUM(MEASURE_GC_RUNS)); + rb_define_singleton_method(mProf, "measure_gc_runs", prof_measure_gc_runs, 0); /* in measure_gc_runs.h */ + #endif + + #ifndef MEASURE_GC_TIME + rb_define_const(mProf, "GC_TIME", Qnil); + #else + rb_define_const(mProf, "GC_TIME", INT2NUM(MEASURE_GC_TIME)); + rb_define_singleton_method(mProf, "measure_gc_time", prof_measure_gc_time, 0); /* in measure_gc_time.h */ + #endif + cResult = rb_define_class_under(mProf, "Result", rb_cObject); rb_undef_method(CLASS_OF(cMethodInfo), "new"); rb_define_method(cResult, "threads", prof_result_threads, 0); ext/ruby_prof.c @@ -5,7 +5,7 @@ require "ruby-prof/graph_printer" require "ruby-prof/graph_html_printer" require "ruby-prof/call_tree_printer" -require "ruby-prof/profile_test" +require "ruby-prof/test" module RubyProf # See if the user specified the clock mode via lib/ruby-prof.rb @@ -27,8 +27,16 @@ module RubyProf when RubyProf.const_defined?(:MEMORY) && RubyProf::MEMORY @value_scale = 1 @output << 'memory' + when RubyProf.const_defined?(:GC_RUNS) && RubyProf::GC_RUNS + @value_scale = 1 + @output << 'gc_runs' + when RubyProf.const_defined?(:GC_TIME) && RubyProf::GC_TIME + @value_scale = 1000000 + @output << 'gc_time' + else + raise "Unknown measure mode: #{RubyProf.measure_mode}" end - @output << "\n\n" + @output << "\n\n" print_threads end lib/ruby-prof/call_tree_printer.rb mingw/ruby_prof.so @@ -110,9 +110,9 @@ class BasicTest < Test::Unit::TestCase assert_equal('<Class::C1>#hello', methods[3].full_name) # The last three methods have total times of zero - assert_equal(0, methods[4].total_time) - assert_equal(0, methods[5].total_time) - assert_equal(0, methods[6].total_time) + assert_in_delta(0, methods[4].total_time, 0.001) + assert_in_delta(0, methods[5].total_time, 0.001) + assert_in_delta(0, methods[6].total_time, 0.001) #assert_equal('Class#new', methods[4].full_name) #assert_equal('<Class::Object>#allocate', methods[5].full_name) test/basic_test.rb @@ -40,40 +40,52 @@ class MeasureModeTest < Test::Unit::TestCase end end end - - def test_cpu - return unless RubyProf.constants.include?('CPU_TIME') - - RubyProf::measure_mode = RubyProf::CPU_TIME - assert_equal(RubyProf::CPU_TIME, RubyProf::measure_mode) - result = RubyProf.profile do - run_primes + + if RubyProf::CPU_TIME + def test_cpu + RubyProf::measure_mode = RubyProf::CPU_TIME + assert_equal(RubyProf::CPU_TIME, RubyProf::measure_mode) + result = RubyProf.profile do + run_primes + end + + result.threads.values.each do |methods| + methods.each do |method| + check_parent_times(method) + check_parent_calls(method) + check_child_times(method) + end + end end - - result.threads.values.each do |methods| - methods.each do |method| - check_parent_times(method) - check_parent_calls(method) - check_child_times(method) + end + + if RubyProf::ALLOCATIONS + def test_allocated_objects + RubyProf::measure_mode = RubyProf::ALLOCATIONS + + assert_equal(RubyProf::ALLOCATIONS, RubyProf::measure_mode) + + result = RubyProf.profile do + Array.new end end end - - def test_allocated_objects - return if RubyProf::ALLOCATIONS.nil? - - RubyProf::measure_mode = RubyProf::ALLOCATIONS - - assert_equal(RubyProf::ALLOCATIONS, RubyProf::measure_mode) - - result = RubyProf.profile do - Array.new + + if RubyProf::MEMORY + def test_memory + RubyProf::measure_mode = RubyProf::MEMORY + + result = RubyProf.profile { Array.new } + total = result.threads.values.first.methods.inject(0) { |sum, m| sum + m.total_time } + + assert(total > 0, 'Should measure more than zero kilobytes of memory usage') + assert_not_equal(0, total % 1, 'Should not truncate fractional kilobyte measurements') end end - + def test_invalid assert_raise(ArgumentError) do RubyProf::measure_mode = 7777 end end -end \ No newline at end of file +end test/measure_mode_test.rb @@ -3,22 +3,23 @@ require 'test/unit' require 'ruby-prof' require 'test_helper' -require 'ruby-prof/profile_test_case' # Need to use wall time for this test due to the sleep calls RubyProf::measure_mode = RubyProf::WALL_TIME # -- Tests ---- class ProfileTest < Test::Unit::TestCase - def test_profile - sleep(2) - end - + include RubyProf::Test + def teardown - profile_dir = output_directory - assert(File.exists?(profile_dir)) + profile_dir = output_dir - file_path = File.join(profile_dir, 'test_profile_profile_test.html') - assert(File.exists?(file_path)) + + #file_path = File.join(profile_dir, 'test_profile_profile_test.html') + #assert(File.exists?(file_path)) + end + + def test_profile + sleep(1) end end test/profile_unit_test.rb @@ -193,6 +193,38 @@ Filter="h;hpp;hxx;hm;inl;inc;xsd" UniqueIdentifier="{93995380-89BD-4b04-88EB-625FBE52EBFB}" > + <File + RelativePath="..\ext\measure_allocations.h" + > + </File> + <File + RelativePath="..\ext\measure_cpu_time.h" + > + </File> + <File + RelativePath="..\ext\measure_gc_runs.h" + > + </File> + <File + RelativePath="..\ext\measure_gc_time.h" + > + </File> + <File + RelativePath="..\ext\measure_memory.h" + > + </File> + <File + RelativePath="..\ext\measure_process_time.h" + > + </File> + <File + RelativePath="..\ext\measure_wall_time.h" + > + </File> + <File + RelativePath="..\ext\version.h" + > + </File> </Filter> <Filter Name="Resource Files" vc/ruby_prof.vcproj lib/ruby-prof/profile_test.rb 8465a8107b279bb57be6ee4205a92eeecb7818c1 f494d15b72d8912a4fe0f404c516d7ac19299cfc Jeremy Kemper jeremy@bitsweat.net http://github.com/jeremy/ruby-prof/commit/89e2a4bc3f5881519a2fe1e5c5c05f7e1e0acf6e 89e2a4bc3f5881519a2fe1e5c5c05f7e1e0acf6e 2008-10-06T08:07:14-07:00 2008-10-06T08:07:14-07:00 Merge commit 'nitay/master' Conflicts: bin/ruby-prof ext/extconf.rb ext/measure_allocations.h ext/measure_cpu_time.h ext/measure_gc_runs.h ext/measure_memory.h ext/ruby_prof.c lib/ruby-prof/profile_test.rb test/measure_mode_test.rb test/measurement_test.rb 0e57ce0974a646609f192f0698558b159ae3f335 Jeremy Kemper jeremy@bitsweat.net