Custom Method Tracers for Ruby 3.0 and beyond

[mwlang]

The current implementation of add_method_tracer is a meta-programming quagmire that is hard to extend and support across all the Ruby versions. In particular, Ruby is separating positional and keyword arguments in Ruby 2.7 and behavior is changing with Ruby 3.0. This presents a number of issues with how add_method_tracer wraps a method and delegates calls to the wrapped method.

This proposal seeks to radically simplify the current implementation in favor of a more robust solution that also leverages the current best practices for Ruby meta-programming techniques. However, the path forward with this proposal breaks current API, so this proposal is a call to action for all community members to review and weigh in on the subject prior to it's release in the next major version of the Agent (slated to be 7.0.0 at the time of this writing).

NOTE: This is draft proposal with multiple possible solutions. If you make use of add_method_tracers beyond the simplest scenarios, especially, if you generate dynamic metric names based on method arguments or pass code_header and code_footer or are moving to Ruby 3.0 rapidly, then please do weigh in to help us produce the best possible outcome.

Background

The Driver for this Change:

In Ruby 3.0, positional arguments and keyword arguments will be separated. Ruby 2.7 will warn for behaviors that will change in Ruby 3.0. If you see the following warnings, you need to update your code:

• Using the last argument as keyword parameters is deprecated, or
• Passing the keyword argument as the last hash parameter is deprecated, or
• Splitting the last argument into positional and keyword parameters is deprecated

In most cases, you can avoid the incompatibility by adding the double splat operator. It explicitly specifies passing keyword arguments instead of a Hash object. Likewise, you may add braces {} to explicitly pass a Hash object, instead of keyword arguments. Read the section “Typical cases” below for more details.

The add_method_tracer

Add a method tracer to the specified method.

By default, this will cause invocations of the traced method to be recorded in transaction traces, and in a metric named after the class and method. It will also make the method show up in transaction-level breakdown charts and tables.

Overriding the metric name

metric_name_code is a string that is eval'd to get the name of the metric associated with the call, so if you want to use interpolation evaluated at call time, then single quote the value like this:

 add_method_tracer :foo, 'Custom/#{self.class.name}/foo'

This would name the metric according to the class of the runtime instance, as opposed to the class where foo is defined.

If not provided, the metric name will be Custom/ClassName/method_name

• @param [Symbol] method_name the name of the method to trace
• @param [String] metric_name_code the metric name to record calls to
  the traced method under. This may be either a static string, or Ruby
  code to be evaluated at call-time in order to determine the metric
  name dynamically.
• @param [Hash] options additional options controlling how the method is
  traced.
  • :push_scope (true) If false, the traced method will
    not appear in transaction traces or breakdown charts, and it will
    only be visible in custom dashboards.
  • :metric (true) If false, the traced method will
    only appear in transaction traces, but no metrics will be recorded
    for it.
  • :code_header ('') Ruby code to be inserted and run
    before the tracer begins timing.
  • :code_footer ('') Ruby code to be inserted and run
    after the tracer stops timing.

Examples

add_method_tracer :foo

# With a custom metric name
add_method_tracer :foo, 'Custom/#{self.class.name}/foo'

# Instrument foo only for custom dashboards (not in transaction
# traces or breakdown charts) 
add_method_tracer :foo, 'Custom/foo', :push_scope => false

# Instrument foo in transaction traces only
add_method_tracer :foo, 'Custom/foo', :metric => false

The Problem: Part 1 -- Ruby Language Syntax/Behavior Changes

One of the best treatments on the topic comes from Benoit Daloze in his blog post, The Delegation Challenge of Ruby 2.7 and I cite verbatim the most relevant examples below. Please refer to his blog post for more in-depth details of the many case scenarios around method delegation. For all intents and purposes, his mention of the delegate method is the same role played by the add_method_tracer, the main difference being that add_method_tracer wrapped additional tracing code around the original method we're delegating to.

Up until Ruby 2.6, delegation had always been rather simple:

def delegate(*args, &block)
  target(*args, &block)
end

And this was enough for perfect forwarding, i.e., pass whatever arguments are passed to delegate to target, as if target had been called directly.

However this doesn’t quite work in Ruby 3:

def target(*args, **kwargs)
  [args, kwargs]
end

target(1, b: 2) # => [[1], {b: 2}] in Ruby 2 & 3
delegate(1, b: 2) # => [[1], {b: 2}] in Ruby 2, [[1, {:b=>2}], {}] in Ruby 3
# Ruby 2.7:
# warning: The last argument is used as the keyword parameter
# warning: for `target' defined here
# => [[1], {:b=>2}]

Because delegate does not take keyword arguments, b: 2 is passed as positional. In Ruby 3, it remains as positional and therefore results in different behavior than calling the method directly. In Ruby 2.7, it warns because the behavior changes in Ruby 3.

Here are some basics on what passes keyword arguments and what passes positional arguments:

def m(*args, **kwargs)
end

h = { a: 1 }

m(a: 1) # passes kwargs in Ruby 2 and 3
m(**h)  # passes kwargs in Ruby 2 and 3

m({a: 1}) # passes kwargs in Ruby 2 and positional in Ruby 3
m(h)      # passes kwargs in Ruby 2 and positional in Ruby 3

The new ... operator of Ruby 2.7 passes all arguments (positional, keywords, block):

def delegate(...)
  target(...)
end

This works in Ruby 2.7 and 3+, but it’s a SyntaxError in 2.6! So we’d need something like this if we still want to run on 2.6:

all_args = RUBY_VERSION < "2.7" ? "*args, &block" : "..."

class_eval <<RUBY
def delegate(#{all_args})
  target(#{all_args})
end
RUBY

Without the new ... syntax, we can do something more like this and skip the class_eval altogether:

if RUBY_VERSION < "3"
  ruby2_keywords def delegate(*args, &block)
    target(*args, &block)
  end
else
  def delegate(*args, **kwargs, &block)
    target(*args, **kwargs, &block)
  end
end

This is becoming not so pretty, but I think is a good path forward. Using this, code will not break in the foreseeable future, and the ruby2_keywords workaround is only used on Ruby 2.7, which is the only version needing such a complicated workaround. Also, we use the Ruby 3-style delegation in Ruby 3 which is rather natural, and not some workaround with complicated semantics. The Ruby 2 branch can be removed as soon as Ruby 2 support is dropped for that code.

The Problem: Part 2 -- Metaprogramming Using class_eval

Currently, our add_method_tracer devolves to the two variations (one with tracing scope and one without):

# returns an eval-able string that contains the traced
# method code used if the agent is not creating a scope for
# use in scoped metrics.
def method_without_push_scope(method_name, metric_name_code, options)
  "def #{_traced_method_name(method_name, metric_name_code)}(#{ARGS_FOR_RUBY_VERSION})
    #{assemble_code_header(method_name, metric_name_code, options)}
    t0 = Time.now
    begin
      #{_untraced_method_name(method_name, metric_name_code)}(#{ARGS_FOR_RUBY_VERSION})\n
    ensure
      duration = (Time.now - t0).to_f
      NewRelic::Agent.record_metric(\"#{metric_name_code}\", duration)
      #{options[:code_footer]}
    end
  end"
end

# returns an eval-able string that contains the tracing code
# for a fully traced metric including scoping
def method_with_push_scope(method_name, metric_name_code, options)
  "def #{_traced_method_name(method_name, metric_name_code)}(#{ARGS_FOR_RUBY_VERSION})
    #{options[:code_header]}
    result = ::NewRelic::Agent::MethodTracerHelpers.trace_execution_scoped(\"#{metric_name_code}\",
              :metric => #{options[:metric]}) do
      #{_untraced_method_name(method_name, metric_name_code)}(#{ARGS_FOR_RUBY_VERSION})
    end
    #{options[:code_footer]}
    result
  end"
end

This is extremely difficult code to understand and it's also very poor practice to use eval and class_eval to dynamically construct and interpret Ruby code at run-time. When things break, where in the code base that breakage occurs is challenging to track down, since for all intent and purposes, it looks like it broken down in the agent itself.

Also note that one method adds the code_header preamble using assemble_code_header while the other does not:

# Returns a code snippet to be eval'd that skips tracing
# when the agent is not tracing execution. turns
# instrumentation into effectively one method call overhead
# when the agent is disabled
def assemble_code_header(method_name, metric_name_code, options)
  header = "return #{_untraced_method_name(method_name, metric_name_code)}(#{ARGS_FOR_RUBY_VERSION}) unless NewRelic::Agent.tl_is_execution_traced?\n"
  header += options[:code_header].to_s
  header
end

This additional logic allows tracing to skip when tracing is suspended for the current transaction. Why it was done for one but not the other is unknown, but is currently considered a bug.

Another Notable Pain Point:

The metric name itself can be dynamic as described by the API documentation for add_method_tracer but the way it works currently highly dependent on the arguments to the method being cast to *args. Ruby < 2.7 handles this in all cases perfectly, but Ruby 2.7+ potentially introduces **kwargs OR if we make use of (...) for delegation, the names of the arguments will be whatever their original names are as defined on the original traced method. All current user implementations that make use of the arguments passed to the traced method will be referencing those parameters as args[x] like so:

def test_add_tracer_with_dynamic_metric
  metric_code = '#{args[0]}.#{args[1]}'. # <=== NOTE THIS LINE
  expected_metric = "1.2"                # <=== produces dynamic metric name!

  @metric_name = metric_code

  self.class.add_method_tracer :method_to_be_traced, metric_code

  in_transaction do
    method_to_be_traced 1,2,3,true,expected_metric
  end
  assert_metrics_recorded expected_metric => {:call_count => 1, :total_call_time => 0.05}
end

Final Pain Point:

When method argument delegation fails in a corner-case, it is hard to diagnose just what went wrong. Recent examples:

• issue Ruby 2.7 deprecation warning tracks the method wrongly to new relic line #349
• issue add_method_tracer modifies object arguments #424

Feature Description

Implement add_method_tracer using modern meta-programming techniques that does not rely on eval or class_eval -- to do this well, we need to also change behavior of the API in a way that is a breaking change. Thus this Issue is slated for the next major release of the Ruby agent.

Proposed changes:

• Implement using prepend instead of eval and call super to invoke the original method that is wrapped.
• Change code_header and code_footer to accept Procs instead of Strings that is Ruby code. This will allow us to also avoid having to use eval
• Allow metric names to be String or Proc and no longer an embedded, interpolatable String.
  A clear and concise description of the feature you want or need.
• Handle method parameter delegation in a way that is future-proof and works from Ruby 2.0 through Ruby 3.2+ and does not cause compiler warnings that attribute syntax issues to the Ruby agent. That is, any such syntax errors are correctly surfacing at the call site or point of original method's definition rather than as side-effect of Ruby agent wrapping the original method.

Describe Alternatives

Alternative solution is to allow current implementations to live as-is and educate on case-by-case basis, write more extensive documentation explaining all the above and train technical support on the nuances of the use-cases likely to arise.

Additional context

• Separation of positional and keyword arguments in Ruby 3.0
• The Delegation Challenge of Ruby 2.7
• https://bugs.ruby-lang.org/issues/14183
• https://bugs.ruby-lang.org/issues/16253

Priority

Please help us better understand this feature request by choosing a priority from the following options:
[Nice to Have, Really Want, Must Have, Blocker]

[mwlang]

Bookmarking this for when we work on this feature: Correct Delegation with Ruby 2.6, 2.7 and 3.0