feat: Enhancing hook logging and profiling

Author: kgilpin

.gitignore

@@ -8,6 +8,7 @@
 /pkg/
 /spec/reports/
 tmp/
+appmap_hook.log
 vendor
 node_modules
 Gemfile.lock

lib/appmap/hook.rb

@@ -1,17 +1,15 @@
 # frozen_string_literal: true
 
 require 'English'
+require_relative './hook_log'
 
 module AppMap
   class Hook
-    LOG = (ENV['APPMAP_DEBUG'] == 'true' || ENV['DEBUG'] == 'true')
-    LOG_HOOK = (ENV['DEBUG_HOOK'] == 'true')
-
     OBJECT_INSTANCE_METHODS = %i[! != !~ <=> == === =~ __id__ __send__ class clone define_singleton_method display dup
                                  enum_for eql? equal? extend freeze frozen? hash inspect instance_eval instance_exec instance_of? instance_variable_defined? instance_variable_get instance_variable_set instance_variables is_a? itself kind_of? method methods nil? object_id private_methods protected_methods public_method public_methods public_send remove_instance_variable respond_to? send singleton_class singleton_method singleton_methods taint tainted? tap then to_enum to_s to_h to_a trust untaint untrust untrusted? yield_self].freeze
     OBJECT_STATIC_METHODS = %i[! != !~ < <= <=> == === =~ > >= __id__ __send__ alias_method allocate ancestors attr
                                attr_accessor attr_reader attr_writer autoload autoload? class class_eval class_exec class_variable_defined? class_variable_get class_variable_set class_variables clone const_defined? const_get const_missing const_set constants define_method define_singleton_method deprecate_constant display dup enum_for eql? equal? extend freeze frozen? hash include include? included_modules inspect instance_eval instance_exec instance_method instance_methods instance_of? instance_variable_defined? instance_variable_get instance_variable_set instance_variables is_a? itself kind_of? method method_defined? methods module_eval module_exec name new nil? object_id prepend private_class_method private_constant private_instance_methods private_method_defined? private_methods protected_instance_methods protected_method_defined? protected_methods public_class_method public_constant public_instance_method public_instance_methods public_method public_method_defined? public_methods public_send remove_class_variable remove_instance_variable remove_method respond_to? send singleton_class singleton_class? singleton_method singleton_methods superclass taint tainted? tap then to_enum to_s trust undef_method untaint untrust untrusted? yield_self].freeze
-    SLOW_PACKAGE_THRESHOLD = 0.05
+    SLOW_PACKAGE_THRESHOLD = 0.001
 
     @unbound_method_arity = ::UnboundMethod.instance_method(:arity)
     @method_arity = ::Method.instance_method(:arity)
@@ -41,9 +39,9 @@ def already_hooked?(method)
       def qualify_method_name(method)
         if method.owner.singleton_class?
           class_name = singleton_method_owner_name(method)
-          [ class_name, '.', method.name ]
+          [class_name, '.', method.name]
         else
-          [ method.owner.name, '#', method.name ]
+          [method.owner.name, '#', method.name]
         end
       end
     end
@@ -69,19 +67,23 @@ def enable(&block)
       @slow_packages = Set.new
 
       if ENV['APPMAP_PROFILE_HOOK'] == 'true'
+        dump_times = lambda do
+          @module_load_times
+            .keys
+            .select { |key| !@slow_packages.member?(key) }
+            .each do |key|
+            elapsed = @module_load_times[key]
+            if elapsed >= SLOW_PACKAGE_THRESHOLD
+              @slow_packages.add(key)
+              warn "AppMap: Package #{key} took #{@module_load_times[key]} seconds to hook"
+            end
+          end
+        end
+
+        at_exit &dump_times
         Thread.new do
-          sleep 1
           while true
-            @module_load_times
-              .keys
-              .select { |key| !@slow_packages.member?(key) }
-              .each do |key|
-              elapsed = @module_load_times[key]
-              if elapsed >= SLOW_PACKAGE_THRESHOLD
-                @slow_packages.add(key)
-                warn "AppMap: Package #{key} took #{@module_load_times[key]} seconds to hook"
-              end
-            end
+            dump_times.call
             sleep 5
           end
         end
@@ -106,14 +108,14 @@ def hook_builtins
             Array(hook.method_names).each do |method_name|
               method_name = method_name.to_sym
 
-              warn "AppMap: Initiating hook for builtin #{class_name} #{method_name}" if LOG
-
               begin
                 base_cls = Object.const_get class_name
               rescue NameError
                 next
               end
 
+              HookLog.builtin_begin class_name, method_name if HookLog.enabled?
+
               hook_method = lambda do |entry|
                 cls, method = entry
                 next if config.never_hook?(cls, method)
@@ -125,20 +127,22 @@ def hook_builtins
               # irb(main):001:0> Kernel.public_instance_method(:system)
               # (irb):1:in `public_instance_method': method `system' for module `Kernel' is  private (NameError)
               if base_cls == Kernel
-                methods << [ base_cls, base_cls.instance_method(method_name) ] rescue nil
+                methods << [base_cls, base_cls.instance_method(method_name)] rescue nil
               end
-              methods << [ base_cls, base_cls.public_instance_method(method_name) ] rescue nil
-              methods << [ base_cls, base_cls.protected_instance_method(method_name) ] rescue nil
+              methods << [base_cls, base_cls.public_instance_method(method_name)] rescue nil
+              methods << [base_cls, base_cls.protected_instance_method(method_name)] rescue nil
               if base_cls.respond_to?(:singleton_class)
-                methods << [ base_cls.singleton_class, base_cls.singleton_class.public_instance_method(method_name) ] rescue nil
-                methods << [ base_cls.singleton_class, base_cls.singleton_class.protected_instance_method(method_name) ] rescue nil
+                methods << [base_cls.singleton_class, base_cls.singleton_class.public_instance_method(method_name)] rescue nil
+                methods << [base_cls.singleton_class, base_cls.singleton_class.protected_instance_method(method_name)] rescue nil
               end
               methods.compact!
               if methods.empty?
-                warn "Method #{method_name} not found on #{base_cls.name}" if LOG
+                HookLog.log "Method #{method_name} not found on #{base_cls.name}" if HookLog.enabled?
               else
                 methods.each(&hook_method)
               end
+
+              HookLog.builtin_end class_name, method_name if HookLog.enabled?
             end
           end
         end
@@ -151,83 +155,93 @@ def hook_builtins
     protected
 
     def trace_location(trace_point)
-      [ trace_point.path, trace_point.lineno ].join(':')
+      [trace_point.path, trace_point.lineno].join(':')
     end
 
     def trace_end(trace_point)
       location = trace_location(trace_point)
-      warn "Class or module ends at location #{location}" if Hook::LOG || Hook::LOG_HOOK
-      return unless @trace_locations.add?(location)
-
-      path = trace_point.path
-      enabled = !@notrace_paths.member?(path) && config.path_enabled?(path)
-      unless enabled
-        warn 'Not hooking - path is not enabled' if Hook::LOG || Hook::LOG_HOOK
-        @notrace_paths << path
-        return
-      end
+      begin
+        HookLog.usercode_begin location if HookLog.enabled?
 
-      cls = trace_point.self
+        return unless @trace_locations.add?(location)
 
-      instance_methods = cls.public_instance_methods(false) + cls.protected_instance_methods(false) - OBJECT_INSTANCE_METHODS
-      # NoMethodError: private method `singleton_class' called for Rack::MiniProfiler:Class
-      class_methods = begin
-        if cls.respond_to?(:singleton_class)
-          cls.singleton_class.public_instance_methods(false) + cls.singleton_class.protected_instance_methods(false) - instance_methods - OBJECT_STATIC_METHODS
-        else
-          []
+        path = trace_point.path
+        enabled = !@notrace_paths.member?(path) && config.path_enabled?(path)
+        unless enabled
+          HookLog.log 'Not hooking - path is not enabled' if HookLog.enabled?
+          @notrace_paths << path
+          return
         end
-      rescue NameError
-        []
-      end
 
-      hook = lambda do |hook_cls|
-        lambda do |method_id|
-          method = \
-            begin
-              hook_cls.instance_method(method_id)
-            rescue NameError
-              warn "AppMap: Method #{hook_cls} #{fn} is not accessible: #{$!}" if LOG
-              next
+        cls = trace_point.self
+
+        instance_methods = cls.public_instance_methods(false) + cls.protected_instance_methods(false) - OBJECT_INSTANCE_METHODS
+        # NoMethodError: private method `singleton_class' called for Rack::MiniProfiler:Class
+        class_methods = begin
+            if cls.respond_to?(:singleton_class)
+              cls.singleton_class.public_instance_methods(false) + cls.singleton_class.protected_instance_methods(false) - instance_methods - OBJECT_STATIC_METHODS
+            else
+              []
             end
+          rescue NameError
+            []
+          end
+
+        hook = lambda do |hook_cls|
+          lambda do |method_id|
+            method = begin
+                hook_cls.instance_method(method_id)
+              rescue NameError
+                HookLog.log "Method #{hook_cls} #{fn} is not accessible: #{$!}" if HookLog.enabled?
+                next
+              end
 
-          package = config.lookup_package(hook_cls, method)
-          # doing this check first returned early in 98.7% of cases in sample_app_6th_ed
-          next unless package
+            package = config.lookup_package(hook_cls, method)
+            # doing this check first returned early in 98.7% of cases in sample_app_6th_ed
+            next unless package
 
-          # Don't try and trace the AppMap methods or there will be
-          # a stack overflow in the defined hook method.
-          next if %w[Marshal AppMap ActiveSupport].member?((hook_cls&.name || '').split('::')[0])
+            # Don't try and trace the AppMap methods or there will be
+            # a stack overflow in the defined hook method.
+            next if %w[Marshal AppMap ActiveSupport].member?((hook_cls&.name || '').split('::')[0])
 
-          next if method_id == :call
+            next if method_id == :call
 
-          next if self.class.already_hooked?(method)
+            next if self.class.already_hooked?(method)
 
-          warn "AppMap: Examining #{hook_cls} #{method.name}" if LOG
+            HookLog.log "Examining #{hook_cls} #{method.name}" if HookLog.enabled?
 
-          disasm = RubyVM::InstructionSequence.disasm(method)
-          # Skip methods that have no instruction sequence, as they are either have no body or they are or native.
-          # TODO: Figure out how to tell the difference?
-          next unless disasm
+            disasm = RubyVM::InstructionSequence.disasm(method)
+            # Skip methods that have no instruction sequence, as they are either have no body or they are or native.
+            # TODO: Figure out how to tell the difference?
+            next unless disasm
 
-          package.handler_class.new(package, hook_cls, method).activate
+            package.handler_class.new(package, hook_cls, method).activate
+          end
         end
-      end
 
-      start = Time.now
-      instance_methods.each(&hook.(cls))
-      begin
-        # NoMethodError: private method `singleton_class' called for Rack::MiniProfiler:Class
-        class_methods.each(&hook.(cls.singleton_class)) if cls.respond_to?(:singleton_class)
-      rescue NameError
-        # NameError:
-        #   uninitialized constant Faraday::Connection
-        warn "NameError in #{__FILE__}: #{$!.message}"
-      end
-      elapsed = Time.now - start
-      if location.index(Bundler.bundle_path.to_s) == 0
-        package_tokens = location[Bundler.bundle_path.to_s.length + 1..-1].split('/')
-        @module_load_times[package_tokens[1]] += elapsed
+        start = Time.now
+        instance_methods.each(&hook.(cls))
+        begin
+          # NoMethodError: private method `singleton_class' called for Rack::MiniProfiler:Class
+          class_methods.each(&hook.(cls.singleton_class)) if cls.respond_to?(:singleton_class)
+        rescue NameError
+          # NameError:
+          #   uninitialized constant Faraday::Connection
+          warn "NameError in #{__FILE__}: #{$!.message}"
+        end
+        elapsed = Time.now - start
+        if location.index(Bundler.bundle_path.to_s) == 0
+          package_tokens = location[Bundler.bundle_path.to_s.length + 1..-1].split('/')
+          @module_load_times[package_tokens[1]] += elapsed
+        else
+          file_path = location[Dir.pwd.length + 1..-1]
+          if file_path
+            location = file_path.split('/', 3)[0..1].join('/')
+            @module_load_times[location] += elapsed
+          end
+        end
+      ensure
+        HookLog.usercode_end(location) if HookLog.enabled?
       end
     end
   end

lib/appmap/hook/method.rb

@@ -38,13 +38,13 @@ def initialize(hook_package, hook_class, hook_method)
       end
 
       def activate
-        if Hook::LOG
+        if HookLog.enabled?
           msg = if method_display_name
-                  "#{method_display_name}"
-                else
-                  "#{hook_method.name} (class resolution deferred)"
-                end
-          warn "AppMap: Hooking #{msg} at line #{(hook_method.source_location || []).join(':')}"
+              "#{method_display_name}"
+            else
+              "#{hook_method.name} (class resolution deferred)"
+            end
+          HookLog.log "Hooking #{msg} at line #{(hook_method.source_location || []).join(':')}"
         end
 
         hook_method_parameters = hook_method.parameters.dup.freeze
@@ -65,8 +65,7 @@ def activate
       protected
 
       def defining_class(hook_class)
-        cls = \
-          if RUBY_MAJOR_VERSION == 2 && RUBY_MINOR_VERSION <= 5
+        cls = if RUBY_MAJOR_VERSION == 2 && RUBY_MINOR_VERSION <= 5
             hook_class
               .ancestors
               .select { |cls| cls.method_defined?(hook_method.name) }

lib/appmap/hook_log.rb

@@ -0,0 +1,76 @@
+module AppMap
+  class HookLog
+    LOG = (ENV['APPMAP_DEBUG'] == 'true' || ENV['DEBUG'] == 'true')
+    LOG_HOOK = (ENV['DEBUG_HOOK'] == 'true' || ENV['APPMAP_LOG_HOOK'] == 'true')
+    LOG_HOOK_FILE = (ENV['APPMAP_LOG_HOOK_FILE'] || 'appmap_hook.log')
+
+    def initialize
+      @file_handle = self.class.send :open_log_file
+      @elapsed = Hash.new { |h, k| h[k] = [] }
+
+      at_exit do
+        @file_handle.puts 'Elapsed time:'
+        @elapsed.keys.each do |k|
+          @file_handle.puts "#{k}:\t#{@elapsed[k].sum}"
+        end
+        @file_handle.flush
+        @file_handle.close
+      end
+    end
+
+    def start_time(timer)
+      @elapsed[timer] << [Time.now.to_f]
+    end
+
+    def end_time(timer)
+      @elapsed[timer][-1] = Time.now.to_f - @elapsed[timer].last[0]
+    end
+
+    class << self
+      def enabled?
+        LOG || LOG_HOOK
+      end
+
+      def builtin_begin(class_name, method_name)
+        log "builtin\tbegin\tInitiating hook for builtin #{class_name} #{method_name}"
+        @hook_log.start_time :builtin
+      end
+
+      def builtin_end(class_name, method_name)
+        @hook_log.end_time :builtin
+        log "builtin\tend\tCompleted hook for builtin #{class_name} #{method_name}"
+      end
+
+      def usercode_begin(location)
+        log "usercode\tbegin\tClass or module defined at location #{location}"
+        @hook_log.start_time :usercode
+      end
+
+      def usercode_end(location)
+        @hook_log.end_time :usercode
+        log "usercode\tend\tCompleted location #{location}"
+      end
+
+      def log(msg)
+        @hook_log ||= HookLog.new
+        @hook_log.log msg
+      end
+
+      protected def open_log_file
+        if LOG_HOOK_FILE == 'stderr'
+          $stderr
+        else
+          File.open(LOG_HOOK_FILE, 'w')
+        end
+      end
+    end
+
+    def log(msg)
+      if LOG_HOOK_FILE == 'stderr'
+        msg = "AppMap: #{msg}"
+      end
+      msg = "#{Time.new.to_f}\t#{msg}"
+      @file_handle.puts(msg)
+    end
+  end
+end