diff --git a/ext/ruby_prof/rp_stack.c b/ext/ruby_prof/rp_stack.c index 72c0b3b2..cd157b35 100644 --- a/ext/ruby_prof/rp_stack.c +++ b/ext/ruby_prof/rp_stack.c @@ -5,6 +5,23 @@ #define INITIAL_STACK_SIZE 8 +void +prof_frame_pause(prof_frame_t *frame, double current_measurement) +{ + if (frame && prof_frame_is_unpaused(frame)) + frame->pause_time = current_measurement; +} + +void +prof_frame_unpause(prof_frame_t *frame, double current_measurement) +{ + if (frame && prof_frame_is_paused(frame)) { + frame->dead_time += (current_measurement - frame->pause_time); + frame->pause_time = -1; + } +} + + /* Creates a stack of prof_frame_t to keep track of timings for active methods. */ prof_stack_t * @@ -47,6 +64,7 @@ prof_stack_push(prof_stack_t *stack, double measurement) result->child_time = 0; result->switch_time = 0; result->wait_time = 0; + result->dead_time = 0; result->depth = (int)(stack->ptr - stack->start); // shortening of 64 bit into 32 result->start_time = measurement; @@ -66,6 +84,11 @@ prof_stack_pop(prof_stack_t *stack, double measurement) double total_time; double self_time; +#ifdef _MSC_VER + BOOL frame_paused; +#else + _Bool frame_paused; +#endif /* Frame can be null. This can happen if RubProf.start is called from a method that exits. And it can happen if an exception is raised @@ -77,7 +100,8 @@ prof_stack_pop(prof_stack_t *stack, double measurement) frame = --stack->ptr; /* Calculate the total time this method took */ - total_time = measurement - frame->start_time; + //prof_frame_unpause(frame, measurement); + total_time = measurement - frame->start_time - frame->dead_time; self_time = total_time - frame->child_time - frame->wait_time; /* Update information about the current method */ @@ -91,6 +115,8 @@ prof_stack_pop(prof_stack_t *stack, double measurement) if (parent_frame) { parent_frame->child_time += total_time; + parent_frame->dead_time += frame->dead_time; + call_info->line = parent_frame->line; } diff --git a/ext/ruby_prof/rp_stack.h b/ext/ruby_prof/rp_stack.h index 2e9aea13..b198a415 100644 --- a/ext/ruby_prof/rp_stack.h +++ b/ext/ruby_prof/rp_stack.h @@ -22,10 +22,18 @@ typedef struct double switch_time; /* Time at switch to different thread */ double wait_time; double child_time; + double pause_time; // Time pause() was initiated + double dead_time; // Time to ignore (i.e. total amount of time between pause/resume blocks) int depth; unsigned int line; } prof_frame_t; +#define prof_frame_is_paused(f) (f->pause_time >= 0) +#define prof_frame_is_unpaused(f) (f->pause_time < 0) +void prof_frame_pause(prof_frame_t*, double current_measurement); +void prof_frame_unpause(prof_frame_t*, double current_measurement); + + /* Current stack of active methods.*/ typedef struct { diff --git a/ext/ruby_prof/rp_thread.c b/ext/ruby_prof/rp_thread.c index b6e60000..16201366 100644 --- a/ext/ruby_prof/rp_thread.c +++ b/ext/ruby_prof/rp_thread.c @@ -179,6 +179,29 @@ switch_thread(void* prof, VALUE thread_id) return thread_data; } + +int pause_thread(st_data_t key, st_data_t value, st_data_t data) +{ + thread_data_t* thread_data = (thread_data_t *) value; + double measurement = (double) data; + + prof_frame_t* frame = prof_stack_peek(thread_data->stack); + prof_frame_pause(frame, measurement); + + return ST_CONTINUE; +} + +int unpause_thread(st_data_t key, st_data_t value, st_data_t data) +{ + thread_data_t* thread_data = (thread_data_t *) value; + double measurement = (double) data; + + prof_frame_t* frame = prof_stack_peek(thread_data->stack); + prof_frame_unpause(frame, measurement); + + return ST_CONTINUE; +} + static int collect_methods(st_data_t key, st_data_t value, st_data_t result) { diff --git a/ext/ruby_prof/rp_thread.h b/ext/ruby_prof/rp_thread.h index ab5eb44e..462330a4 100644 --- a/ext/ruby_prof/rp_thread.h +++ b/ext/ruby_prof/rp_thread.h @@ -20,5 +20,7 @@ thread_data_t* switch_thread(void* prof, VALUE thread_id); void threads_table_free(st_table *table); VALUE prof_thread_wrap(thread_data_t *thread); void prof_thread_mark(thread_data_t *thread); +int pause_thread(st_data_t key, st_data_t value, st_data_t data); +int unpause_thread(st_data_t key, st_data_t value, st_data_t data); #endif //__RP_THREAD__ diff --git a/ext/ruby_prof/ruby_prof.c b/ext/ruby_prof/ruby_prof.c index a3285e36..d329b9e5 100644 --- a/ext/ruby_prof/ruby_prof.c +++ b/ext/ruby_prof/ruby_prof.c @@ -291,12 +291,18 @@ prof_event_hook(rb_event_flag_t event, NODE *node, VALUE self, ID mid, VALUE kla call_info_table_insert(frame->call_info->call_infos, method->key, call_info); prof_add_call_info(method->call_infos, call_info); } + + // Unpause the parent frame. If currently paused then: + // 1) The child frame will begin paused. + // 2) The parent will inherit the child's dead time. + prof_frame_unpause(frame, measurement); } /* Push a new frame onto the stack for a new c-call or ruby call (into a method) */ frame = prof_stack_push(thread_data->stack, measurement); frame->call_info = call_info; frame->call_info->depth = frame->depth; + frame->pause_time = profile->paused == Qtrue ? measurement : -1; frame->line = rb_sourceline(); break; } @@ -454,6 +460,17 @@ prof_initialize(int argc, VALUE *argv, VALUE self) return self; } +/* call-seq: + paused? -> boolean + + Returns whether a profile is currently paused.*/ +static VALUE +prof_paused(VALUE self) +{ + prof_profile_t* profile = prof_get_profile(self); + return profile->paused; +} + /* call-seq: running? -> boolean @@ -489,9 +506,11 @@ prof_start(VALUE self) #endif profile->running = Qtrue; + profile->paused = Qfalse; profile->last_thread_data = NULL; - /* open trace file if environment wants it */ + + /* open trace file if environment wants it */ trace_file_name = getenv("RUBY_PROF_TRACE"); if (trace_file_name != NULL) { @@ -513,6 +532,52 @@ prof_start(VALUE self) return self; } +/* call-seq: + pause -> RubyProf + + Pauses collecting profile data. */ +static VALUE +prof_pause(VALUE self) +{ + prof_profile_t* profile = prof_get_profile(self); + if (profile->running == Qfalse) + { + rb_raise(rb_eRuntimeError, "RubyProf is not running."); + } + + if (profile->paused == Qfalse) + { + profile->paused = Qtrue; + profile->measurement_at_pause_resume = profile->measurer->measure(); + st_foreach(profile->threads_tbl, pause_thread, (st_data_t) profile); + } + + return self; +} + +/* call-seq: + resume {block} -> RubyProf + + Resumes recording profile data.*/ +static VALUE +prof_resume(VALUE self) +{ + prof_profile_t* profile = prof_get_profile(self); + if (profile->running == Qfalse) + { + rb_raise(rb_eRuntimeError, "RubyProf is not running."); + } + + if (profile->paused == Qtrue) + { + profile->paused = Qfalse; + profile->measurement_at_pause_resume = profile->measurer->measure(); + st_foreach(profile->threads_tbl, unpause_thread, (st_data_t) profile); + } + + return rb_block_given_p() ? rb_ensure(rb_yield, self, prof_pause, self) : self; +} + /* call-seq: stop -> self @@ -547,6 +612,7 @@ prof_stop(VALUE self) /* Unset the last_thread_data (very important!) and the threads table */ + profile->running = profile->paused = Qfalse; profile->last_thread_data = NULL; /* Post process result */ @@ -605,6 +671,9 @@ void Init_ruby_prof() rb_define_method(cProfile, "initialize", prof_initialize, -1); rb_define_method(cProfile, "start", prof_start, 0); rb_define_method(cProfile, "stop", prof_stop, 0); + rb_define_method(cProfile, "resume", prof_resume, 0); + rb_define_method(cProfile, "pause", prof_pause, 0); rb_define_method(cProfile, "running?", prof_running, 0); + rb_define_method(cProfile, "paused?", prof_paused, 0); rb_define_method(cProfile, "threads", prof_threads, 0); } diff --git a/ext/ruby_prof/ruby_prof.h b/ext/ruby_prof/ruby_prof.h index 90fa564b..bcbacca8 100644 --- a/ext/ruby_prof/ruby_prof.h +++ b/ext/ruby_prof/ruby_prof.h @@ -42,11 +42,13 @@ void method_key(prof_method_key_t* key, VALUE klass, ID mid); typedef struct { VALUE running; + VALUE paused; prof_measurer_t* measurer; VALUE threads; st_table* threads_tbl; st_table* exclude_threads_tbl; thread_data_t* last_thread_data; + double measurement_at_pause_resume; } prof_profile_t; diff --git a/lib/ruby-prof/compatibility.rb b/lib/ruby-prof/compatibility.rb index 9b1e91af..6dce3d05 100644 --- a/lib/ruby-prof/compatibility.rb +++ b/lib/ruby-prof/compatibility.rb @@ -103,6 +103,12 @@ def self.start @profile.start end + def self.pause + ensure_running! + disable_gc_stats_if_needed + @profile.pause + end + def self.running? if defined?(@profile) and @profile @profile.running? @@ -111,6 +117,12 @@ def self.running? end end + def self.resume + ensure_running! + enable_gc_stats_if_needed + @profile.resume + end + def self.stop ensure_running! result = @profile.stop diff --git a/test/pause_resume_test.rb b/test/pause_resume_test.rb new file mode 100755 index 00000000..f82a9441 --- /dev/null +++ b/test/pause_resume_test.rb @@ -0,0 +1,162 @@ +#!/usr/bin/env ruby +# encoding: UTF-8 + +require File.expand_path('../test_helper', __FILE__) + +class PauseResumeTest < Test::Unit::TestCase + def setup + # Need to use wall time for this test due to the sleep calls + RubyProf::measure_mode = RubyProf::WALL_TIME + end + + def test_pause_resume + # Measured + RubyProf.start + RubyProf::C1.hello + + # Not measured + RubyProf.pause + sleep 1 + RubyProf::C1.hello + + # Measured + RubyProf.resume + RubyProf::C1.hello + + result = RubyProf.stop + + # Length should be 3: + # PauseResumeTest#test_pause_resume + # #hello + # Kernel#sleep + + methods = result.threads.first.methods.sort_by {|method_info| method_info.full_name} + assert_equal(3, methods.length) + + # Check the names + assert_equal('#hello', methods[0].full_name) + assert_equal('Kernel#sleep', methods[1].full_name) + assert_equal('PauseResumeTest#test_pause_resume', methods[2].full_name) + + # Check times + assert_in_delta(0.2, methods[0].total_time, 0.01) + assert_in_delta(0, methods[0].wait_time, 0.01) + assert_in_delta(0, methods[0].self_time, 0.01) + + assert_in_delta(0.2, methods[1].total_time, 0.01) + assert_in_delta(0, methods[1].wait_time, 0.01) + assert_in_delta(0.2, methods[1].self_time, 0.01) + + assert_in_delta(0.2, methods[2].total_time, 0.01) + assert_in_delta(0, methods[2].wait_time, 0.01) + assert_in_delta(0, methods[2].self_time, 0.01) + end + + # pause/resume in the same frame + def test_pause_resume_1 + profile = RubyProf::Profile.new(RubyProf::WALL_TIME,[]) + + profile.start + method_1a + + profile.pause + method_1b + + profile.resume + method_1c + + result = profile.stop + assert_in_delta(0.6, result.threads[0].methods.select{|m| m.full_name =~ /test_pause_resume_1$/}[0].total_time, 0.05) + end + def method_1a; sleep 0.2 end + def method_1b; sleep 1 end + def method_1c; sleep 0.4 end + + # pause in parent frame, resume in child + def test_pause_resume_2 + profile = RubyProf::Profile.new(RubyProf::WALL_TIME,[]) + + profile.start + method_2a + + profile.pause + sleep 0.5 + method_2b(profile) + + result = profile.stop + assert_in_delta(0.6, result.threads[0].methods.select{|m| m.full_name =~ /test_pause_resume_2$/}[0].total_time, 0.05) + end + def method_2a; sleep 0.2 end + def method_2b(profile); sleep 0.5; profile.resume; sleep 0.4 end + + # pause in child frame, resume in parent + def test_pause_resume_3 + profile = RubyProf::Profile.new(RubyProf::WALL_TIME,[]) + + profile.start + method_3a(profile) + + sleep 0.5 + profile.resume + method_3b + + result = profile.stop + assert_in_delta(0.6, result.threads[0].methods.select{|m| m.full_name =~ /test_pause_resume_3$/}[0].total_time, 0.05) + end + def method_3a(profile); sleep 0.2; profile.pause; sleep 0.5 end + def method_3b; sleep 0.4 end + + def test_pause_seq + profile = RubyProf::Profile.new(RubyProf::WALL_TIME,[]) + profile.start ; assert !profile.paused? + profile.pause ; assert profile.paused? + profile.resume; assert !profile.paused? + profile.pause ; assert profile.paused? + profile.pause ; assert profile.paused? + profile.resume; assert !profile.paused? + profile.resume; assert !profile.paused? + profile.stop ; assert !profile.paused? + end + + def test_pause_block + profile = RubyProf::Profile.new(RubyProf::WALL_TIME,[]) + profile.start + profile.pause + assert profile.paused? + + times_block_invoked = 0 + retval= profile.resume{ + times_block_invoked += 1 + 120 + times_block_invoked + } + assert_equal 1, times_block_invoked + assert profile.paused? + + assert_equal 121, retval, "resume() should return the result of the given block." + + profile.stop + end + + def test_pause_block_with_error + profile = RubyProf::Profile.new(RubyProf::WALL_TIME,[]) + profile.start + profile.pause + assert profile.paused? + + begin + profile.resume{ raise } + flunk 'Exception expected.' + rescue + assert profile.paused? + end + + profile.stop + end + + def test_resume_when_not_paused + profile = RubyProf::Profile.new(RubyProf::WALL_TIME,[]) + profile.start ; assert !profile.paused? + profile.resume; assert !profile.paused? + profile.stop ; assert !profile.paused? + end +end \ No newline at end of file