DEBUG-2334 dynamic instrumentation instrumenter component

benchmarks/di_instrument.rb

@@ -0,0 +1,258 @@
+=begin
+
+"Instrumentation" part of Dynamic Instrumentation benchmarks.
+
+Typical result:
+
+Comparison:
+  no instrumentation:   589490.0 i/s
+method instrumentation - cleared:   545807.2 i/s - 1.08x  slower
+line instrumentation - cleared:   539686.5 i/s - 1.09x  slower
+no instrumentation - again:   535761.0 i/s - 1.10x  slower
+method instrumentation:   129159.5 i/s - 4.56x  slower
+line instrumentation - targeted:   128848.6 i/s - 4.58x  slower
+line instrumentation:    10771.7 i/s - 54.73x  slower
+
+Targeted line and method instrumentations have similar performance at
+about 25% of baseline. Note that the instrumented method is fairly
+small and probably runs very quickly by itself, so while this is not the
+worst possible case for instrumentation (that would be an empty method),
+likely the vast majority of real world uses of DI would have way expensive
+target code and the relative overhead of instrumentation will be significantly
+lower than it is in this benchmark.
+
+Untargeted line instrumentation is extremely slow, too slow to be usable.
+
+In theory, after instrumentation is removed, performance should return to
+the baseline. We are currently observing about a 6-10% performance loss.
+Two theories for why this is so:
+1. Some overhead remains in the code - to be investigated.
+2. The benchmarks were run on a laptop, and during the benchmarking
+process the CPU is heating up and it can't turbo to the same speeds at
+the end of the run as it can at the beginning. Meaning the observed 6-10%
+slowdown at the end is an environmental issue and not an implementation
+problem.
+
+=end
+
+# Used to quickly run benchmark under RSpec as part of the usual test suite, to validate it didn't bitrot
+VALIDATE_BENCHMARK_MODE = ENV['VALIDATE_BENCHMARK'] == 'true'
+
+return unless __FILE__ == $PROGRAM_NAME || VALIDATE_BENCHMARK_MODE
+
+require 'benchmark/ips'
+require 'datadog'
+
+class DIInstrumentBenchmark
+  class Target
+    def test_method
+      # Perform some work to take up time
+      SecureRandom.uuid
+    end
+
+    def not_instrumented
+      SecureRandom.uuid
+    end
+
+    # This method must have an executable line as its first line,
+    # otherwise line instrumentation won't work.
+    # The code in this method should be identical to test_method above.
+    # The two methods are separate so that instrumentation targets are
+    # different, to avoid a false positive if line instrumemntation fails
+    # to work and method instrumentation isn't cleared and continues to
+    # invoke the callback.
+    def test_method_for_line_probe
+      SecureRandom.uuid
+    end
+  end
+
+  def run_benchmark
+    settings = Datadog.configuration
+    # We benchmark untargeted and targeted trace points; untargeted ones
+    # are prohibited by default, permit them.
+    settings.dynamic_instrumentation.untargeted_trace_points = true
+    redactor = Datadog::DI::Redactor.new(settings)
+    serializer = Datadog::DI::Serializer.new(settings, redactor)
+    instrumenter = Datadog::DI::Instrumenter.new(settings, serializer)
+
+    m = Target.instance_method(:test_method_for_line_probe)
+    file, line = m.source_location
+
+    Benchmark.ips do |x|
+      benchmark_time = VALIDATE_BENCHMARK_MODE ? { time: 0.01, warmup: 0 } : { time: 10, warmup: 2 }
+      x.config(
+        **benchmark_time,
+      )
+
+      x.report('no instrumentation') do
+        Target.new.test_method
+      end
+
+      x.save! 'di-instrument-results.json' unless VALIDATE_BENCHMARK_MODE
+      x.compare!
+    end
+
+    calls = 0
+    instrumenter.hook_method('DIInstrumentBenchmark::Target', 'test_method') do
+      calls += 1
+    end
+
+    Benchmark.ips do |x|
+      benchmark_time = VALIDATE_BENCHMARK_MODE ? { time: 0.01, warmup: 0 } : { time: 10, warmup: 2 }
+      x.config(
+        **benchmark_time,
+      )
+
+      x.report('method instrumentation') do
+        Target.new.test_method
+      end
+
+      x.save! 'di-instrument-results.json' unless VALIDATE_BENCHMARK_MODE
+      x.compare!
+    end
+
+    if calls < 1
+      raise "Method instrumentation did not work - callback was never invoked"
+    end
+
+    if calls < 1000 && !VALIDATE_BENCHMARK_MODE
+      raise "Expected at least 1000 calls to the method, got #{calls}"
+    end
+
+    instrumenter.clear_hooks
+    calls = 0
+    instrumenter.hook_line_now(file, line + 1) do
+      calls += 1
+    end
+
+    Benchmark.ips do |x|
+      benchmark_time = VALIDATE_BENCHMARK_MODE ? { time: 0.01, warmup: 0 } : { time: 10, warmup: 2 }
+      x.config(
+        **benchmark_time,
+      )
+
+      x.report('line instrumentation') do
+        Target.new.test_method_for_line_probe
+      end
+
+      x.save! 'di-instrument-results.json' unless VALIDATE_BENCHMARK_MODE
+      x.compare!
+    end
+
+    if calls < 1
+      raise "Line instrumentation did not work - callback was never invoked"
+    end
+
+    if calls < 1000 && !VALIDATE_BENCHMARK_MODE
+      raise "Expected at least 1000 calls to the method, got #{calls}"
+    end
+
+    require 'datadog/di/init'
+    if defined?(DITarget)
+      raise "DITarget is already defined, this should not happen"
+    end
+    require_relative 'di_target'
+    unless defined?(DITarget)
+      raise "DITarget is not defined, this should not happen"
+    end
+
+    m = DITarget.instance_method(:test_method_for_line_probe)
+    targeted_file, targeted_line = m.source_location
+
+    instrumenter.clear_hooks
+    calls = 0
+    instrumenter.hook_line_now(targeted_file, targeted_line + 1) do
+      calls += 1
+    end
+
+    Benchmark.ips do |x|
+      benchmark_time = VALIDATE_BENCHMARK_MODE ? { time: 0.01, warmup: 0 } : { time: 10, warmup: 2 }
+      x.config(
+        **benchmark_time,
+      )
+
+      x.report('line instrumentation - targeted') do
+        DITarget.new.test_method_for_line_probe
+      end
+
+      x.save! 'di-instrument-results.json' unless VALIDATE_BENCHMARK_MODE
+      x.compare!
+    end
+
+    if calls < 1
+      raise "Targeted line instrumentation did not work - callback was never invoked"
+    end
+
+    if calls < 1000 && !VALIDATE_BENCHMARK_MODE
+      raise "Expected at least 1000 calls to the method, got #{calls}"
+    end
+
+    # Now, remove all installed hooks and check that the performance of
+    # target code is approximately what it was prior to hook installation.
+
+    instrumenter.clear_hooks
+    calls = 0
+
+    Benchmark.ips do |x|
+      benchmark_time = VALIDATE_BENCHMARK_MODE ? { time: 0.01, warmup: 0 } : { time: 10, warmup: 2 }
+      x.config(
+        **benchmark_time,
+      )
+
+      # This benchmark should produce identical results to the
+      # "no instrumentation" benchmark.
+      x.report('method instrumentation - cleared') do
+        Target.new.test_method
+      end
+
+      x.save! 'di-instrument-results.json' unless VALIDATE_BENCHMARK_MODE
+      x.compare!
+    end
+
+    if calls != 0
+      raise "Method instrumentation was not cleared (#{calls} calls recorded)"
+    end
+
+    Benchmark.ips do |x|
+      benchmark_time = VALIDATE_BENCHMARK_MODE ? { time: 0.01, warmup: 0 } : { time: 10, warmup: 2 }
+      x.config(
+        **benchmark_time,
+      )
+
+      # This benchmark should produce identical results to the
+      # "no instrumentation" benchmark.
+      x.report('line instrumentation - cleared') do
+        Target.new.test_method_for_line_probe
+      end
+
+      x.save! 'di-instrument-results.json' unless VALIDATE_BENCHMARK_MODE
+      x.compare!
+    end
+
+    if calls != 0
+      raise "Line instrumentation was not cleared (#{calls} calls recorded)"
+    end
+
+    Benchmark.ips do |x|
+      benchmark_time = VALIDATE_BENCHMARK_MODE ? { time: 0.01, warmup: 0 } : { time: 10, warmup: 2 }
+      x.config(
+        **benchmark_time,
+      )
+
+      x.report('no instrumentation - again') do
+        Target.new.not_instrumented
+      end
+
+      x.save! 'di-instrument-results.json' unless VALIDATE_BENCHMARK_MODE
+      x.compare!
+    end
+
+  end
+
+end
+
+puts "Current pid is #{Process.pid}"
+
+DIInstrumentBenchmark.new.instance_exec do
+  run_benchmark
+end

benchmarks/di_target.rb

@@ -0,0 +1,15 @@
+# This class must live in a separate file so that it can be loaded
+# after code tracking for dynamic instrumentation is enabled.
+class DITarget
+  # This method must have an executable line as its first line,
+  # otherwise line instrumentation won't work.
+  # The code in this method should be identical to
+  # DIInstrumentMethodBenchmark#test_method.
+  # The two methods are separate so that instrumentation targets are
+  # different, to avoid a false positive if line instrumemntation fails
+  # to work and method instrumentation isn't cleared and continues to
+  # invoke the callback.
+  def test_method_for_line_probe
+    SecureRandom.uuid
+  end
+end

lib/datadog/di/code_tracker.rb

@@ -109,25 +109,15 @@ def active?
       # to be an absolute path), only the exactly matching path is returned.
       # Otherwise all known paths that end in the suffix are returned.
       # If no paths match, an empty array is returned.
-      def iseqs_for_path(suffix)
+      def iseqs_for_path_suffix(suffix)
         registry_lock.synchronize do
           exact = registry[suffix]
           return [exact] if exact
 
           inexact = []
           registry.each do |path, iseq|
-            # Exact match is not possible here, meaning any matching path
-            # has to be longer than the suffix. Require full component matches,
-            # meaning either the first character of the suffix is a slash
-            # or the previous character in the path is a slash.
-            # For now only check for forward slashes for Unix-like OSes;
-            # backslash is a legitimate character of a file name in Unix
-            # therefore simply permitting forward or back slash is not
-            # sufficient, we need to perform an OS check to know which
-            # path separator to use.
-            if path.length > suffix.length && path.end_with?(suffix)
-              previous_char = path[path.length - suffix.length - 1]
-              inexact << iseq if previous_char == "/" || suffix[0] == "/"
+            if Utils.path_matches_suffix?(path, suffix)
+              inexact << iseq
             end
           end
           inexact