ruby_prof.c in ruby-prof-0.7.5

- old
+ new

@@ -46,12 +46,12 @@
   caller or callee method, thereby making it easy to navigate through the call 
   hierarchy in ruby - which is very helpful for creating call graphs.      
 */
 
 #include "ruby_prof.h"
+#include <stdio.h>
 
-
 /* ================  Helper Functions  =================*/
 static VALUE
 figure_singleton_name(VALUE klass)
 {
     VALUE result = Qnil;
@@ -376,11 +376,11 @@
 }
 
 /* call-seq:
    called -> int
 
-Returns the total amount of time this method was called. */
+Returns the total amount of times this method was called. */
 static VALUE
 prof_call_info_called(VALUE self)
 {
     prof_call_info_t *result = prof_get_call_info_result(self);
     return INT2NUM(result->called);
@@ -870,10 +870,16 @@
   return "c-call";
     case RUBY_EVENT_C_RETURN:
   return "c-return";
     case RUBY_EVENT_RAISE:
   return "raise";
+  
+#ifdef RUBY_VM
+    case RUBY_EVENT_SWITCH:
+  return "thread-interrupt";
+#endif
+  
     default:
   return "unknown";
   }
 }
 #endif
@@ -916,49 +922,53 @@
 update_result(prof_measure_t total_time,
               prof_frame_t *parent_frame, 
               prof_frame_t *frame)
 {
     prof_measure_t self_time = total_time - frame->child_time - frame->wait_time;
-
+    
     prof_call_info_t *call_info = frame->call_info;
     
     /* Update information about the current method */
     call_info->called++;
     call_info->total_time += total_time;
     call_info->self_time += self_time;
     call_info->wait_time += frame->wait_time;
-
+    
     /* Note where the current method was called from */
     if (parent_frame)
       call_info->line = parent_frame->line;
 }
 
 static thread_data_t *
 switch_thread(VALUE thread_id, prof_measure_t now)
 {
     prof_frame_t *frame = NULL;
     prof_measure_t wait_time = 0;
-    
     /* Get new thread information. */
     thread_data_t *thread_data = threads_table_lookup(threads_tbl, thread_id);
 
     /* How long has this thread been waiting? */
     wait_time = now - thread_data->last_switch;
+    
     thread_data->last_switch = 0;
 
     /* Get the frame at the top of the stack.  This may represent
        the current method (EVENT_LINE, EVENT_RETURN)  or the
        previous method (EVENT_CALL).*/
     frame = stack_peek(thread_data->stack);
   
-    if (frame)
+    if (frame) {
       frame->wait_time += wait_time;
+    }
+    
+    
       
     /* Save on the last thread the time of the context switch
        and reset this thread's last context switch to 0.*/
-    if (last_thread_data)
-      last_thread_data->last_switch = now;
+    if (last_thread_data) {
+      last_thread_data->last_switch = now;   
+    }
       
     last_thread_data = thread_data;
     return thread_data;
 }
 
@@ -967,15 +977,14 @@
 {
   prof_frame_t *frame = NULL;
   prof_frame_t* parent_frame = NULL;
   prof_measure_t total_time;
 
-  frame = stack_pop(thread_data->stack);
-    
+  frame = stack_pop(thread_data->stack); // only time it's called
   /* 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
-     in code that is being profiled and the stack unwinds (RubProf is
+     in code that is being profiled and the stack unwinds (RubyProf is
      not notified of that by the ruby runtime. */
   if (frame == NULL) return NULL;
 
   /* Calculate the total time this method took */
   total_time = now - frame->start_time;
@@ -987,11 +996,11 @@
   if (parent_frame)
   {
     parent_frame->child_time += total_time;
   }
     
-  update_result(total_time, parent_frame, frame);
+  update_result(total_time, parent_frame, frame); // only time it's called
   return frame;
 }
 
 static int 
 pop_frames(st_data_t key, st_data_t value, st_data_t now_arg)
@@ -1027,11 +1036,10 @@
 #else
 static void
 prof_event_hook(rb_event_flag_t event, NODE *node, VALUE self, ID mid, VALUE klass)
 #endif
 {
-    
     VALUE thread = Qnil;
     VALUE thread_id = Qnil;
     prof_measure_t now = 0;
     thread_data_t* thread_data = NULL;
     prof_frame_t *frame = NULL;
@@ -1064,12 +1072,13 @@
         if (klass != 0)
           klass = (BUILTIN_TYPE(klass) == T_ICLASS ? RBASIC(klass)->klass : klass);
 
         class_name = rb_class2name(klass);
 
-        if (last_thread_id != thread_id)
+        if (last_thread_id != thread_id) {
           printf("\n");
+        }
 
         printf("%2u: %-8s :%2d  %s#%s\n",
                thread_id, event_name, source_line, class_name, method_name);
         fflush(stdout);
         last_thread_id = thread_id;               
@@ -1180,10 +1189,11 @@
         break;
     }
     case RUBY_EVENT_RETURN:
     case RUBY_EVENT_C_RETURN:
     {
+        // this assumes that all C calls take 100% user cpu, I guess.
         pop_frame(thread_data, now);
         break;
       }
     }
 }
@@ -1236,11 +1246,11 @@
 {
     if (BUILTIN_TYPE(obj) != T_DATA ||
       RDATA(obj)->dfree != (RUBY_DATA_FUNC) prof_result_free)
     {
         /* Should never happen */
-      rb_raise(rb_eTypeError, "wrong result object");
+      rb_raise(rb_eTypeError, "wrong result object (%d %d) ", BUILTIN_TYPE(obj) != T_DATA, RDATA(obj)->dfree != (RUBY_DATA_FUNC) prof_result_free);
     }
     return (prof_result_t *) DATA_PTR(obj);
 }
 
 /* call-seq:
@@ -1400,10 +1410,10 @@
 {
 #ifdef RUBY_VM
     rb_add_event_hook(prof_event_hook,
           RUBY_EVENT_CALL | RUBY_EVENT_RETURN |
           RUBY_EVENT_C_CALL | RUBY_EVENT_C_RETURN 
-          | RUBY_EVENT_LINE, Qnil);
+          | RUBY_EVENT_LINE | RUBY_EVENT_SWITCH, Qnil);
 #else
     rb_add_event_hook(prof_event_hook,
           RUBY_EVENT_CALL | RUBY_EVENT_RETURN |
           RUBY_EVENT_C_CALL | RUBY_EVENT_C_RETURN 
           | RUBY_EVENT_LINE);