feat: Record the time spent instrumentating a function, as opposed to only the time spend executing a function

Author: symwell

lib/appmap/event.rb

@@ -262,7 +262,7 @@ def to_h
     end
 
     class MethodReturnIgnoreValue < MethodEvent
-      attr_accessor :parent_id, :elapsed
+      attr_accessor :parent_id, :elapsed, :elapsed_instrumentation
 
       class << self
         def build_from_invocation(parent_id, elapsed: nil, event: MethodReturnIgnoreValue.new)
@@ -279,6 +279,7 @@ def to_h
         super.tap do |h|
           h[:parent_id] = parent_id
           h[:elapsed] = elapsed if elapsed
+          h[:elapsed_instrumentation] = elapsed_instrumentation if elapsed_instrumentation
         end
       end
     end

lib/appmap/hook/method.rb

@@ -102,8 +102,9 @@ def defined_class
         @defined_class ||= Hook.qualify_method_name(hook_method)&.first
       end
 
-      def after_hook(_receiver, call_event, elapsed, return_value, exception)
+      def after_hook(_receiver, call_event, elapsed_before, elapsed, after_start_time, return_value, exception)
         return_event = handle_return(call_event.id, elapsed, return_value, exception)
+        return_event.elapsed_instrumentation = elapsed_before + (gettime - after_start_time)
         AppMap.tracing.record_event(return_event) if return_event
       end
 

lib/appmap/hook/method/ruby2.rb

@@ -8,15 +8,19 @@ class Hook
     # cf. https://eregon.me/blog/2019/11/10/the-delegation-challenge-of-ruby27.html
     class Method
       ruby2_keywords def call(receiver, *args, &block)
-        call_event = trace? && with_disabled_hook { before_hook receiver, *args }
+        call_event = false
+        if trace?
+          call_event, elapsed_before = with_disabled_hook { before_hook receiver, *args }
+        end
         # note we can't short-circuit directly to do_call because then the call stack
         # depth changes and eval handler doesn't work correctly
-        trace_call call_event, receiver, *args, &block
+        trace_call call_event, elapsed_before, receiver, *args, &block
       end
 
       protected
 
       def before_hook(receiver, *args)
+        before_hook_start_time = gettime
         call_event = handle_call(receiver, args)
         if call_event
           AppMap.tracing.record_event \
@@ -25,15 +29,15 @@ def before_hook(receiver, *args)
             defined_class: defined_class,
             method: hook_method
         end
-        call_event
+        [call_event, gettime - before_hook_start_time]
       end
 
       ruby2_keywords def do_call(receiver, *args, &block)
         hook_method.bind(receiver).call(*args, &block)
       end
 
       # rubocop:disable Metrics/MethodLength
-      ruby2_keywords def trace_call(call_event, receiver, *args, &block)
+      ruby2_keywords def trace_call(call_event, elapsed_before, receiver, *args, &block)
         return do_call(receiver, *args, &block) unless call_event
 
         start_time = gettime
@@ -43,7 +47,8 @@ def before_hook(receiver, *args)
           exception = $ERROR_INFO
           raise
         ensure
-          with_disabled_hook { after_hook receiver, call_event, gettime - start_time, return_value, exception } \
+          after_start_time = gettime
+          with_disabled_hook { after_hook receiver, call_event, elapsed_before, after_start_time - start_time, after_start_time, return_value, exception } \
             if call_event
         end
       end

lib/appmap/hook/method/ruby3.rb

@@ -5,15 +5,19 @@ class Hook
     # Delegation methods for Ruby 3.
     class Method
       def call(receiver, *args, **kwargs, &block)
-        call_event = trace? && with_disabled_hook { before_hook receiver, *args, **kwargs }
+        call_event = false
+        if trace?
+          call_event, elapsed_before = with_disabled_hook { before_hook receiver, *args, **kwargs }
+        end
         # note we can't short-circuit directly to do_call because then the call stack
         # depth changes and eval handler doesn't work correctly
-        trace_call call_event, receiver, *args, **kwargs, &block
+        trace_call call_event, elapsed_before, receiver, *args, **kwargs, &block
       end
 
       protected
 
       def before_hook(receiver, *args, **kwargs)
+        before_hook_start_time = gettime
         args = [*args, kwargs] if !kwargs.empty? || keyrest?
         call_event = handle_call(receiver, args)
         if call_event
@@ -23,7 +27,7 @@ def before_hook(receiver, *args, **kwargs)
             defined_class: defined_class,
             method: hook_method
         end
-        call_event
+        [call_event, gettime - before_hook_start_time]
       end
 
       def keyrest?
@@ -35,7 +39,7 @@ def do_call(receiver, *args, **kwargs, &block)
       end
 
       # rubocop:disable Metrics/MethodLength
-      def trace_call(call_event, receiver, *args, **kwargs, &block)
+      def trace_call(call_event, elapsed_before, receiver, *args, **kwargs, &block)
         return do_call(receiver, *args, **kwargs, &block) unless call_event
 
         start_time = gettime
@@ -45,7 +49,8 @@ def trace_call(call_event, receiver, *args, **kwargs, &block)
           exception = $ERROR_INFO
           raise
         ensure
-          with_disabled_hook { after_hook receiver, call_event, gettime - start_time, return_value, exception } \
+          after_start_time = gettime
+          with_disabled_hook { after_hook receiver, call_event, elapsed_before, after_start_time - start_time, after_start_time, return_value, exception } \
             if call_event
         end
       end

lib/appmap/util.rb

@@ -86,6 +86,7 @@ def sanitize_paths(h)
       def sanitize_event(event, &block)
         event.delete(:thread_id)
         event.delete(:elapsed)
+        event.delete(:elapsed_instrumentation)
         delete_object_id = ->(obj) { (obj || {}).delete(:object_id) }
         delete_object_id.call(event[:receiver])
         delete_object_id.call(event[:return_value])