Merge pull request #1767 from newrelic/enable_thread_tracing_default

Enable `instrumentation.thread.tracing` by default

CHANGELOG.md

@@ -1,5 +1,15 @@
 # New Relic Ruby Agent Release Notes
 
+## v9.0.0
+
+  Version 9.0.0 of the agent enables thread tracing.
+
+- **Enable Thread Instrumentation by default**
+
+  The configuration option `instrumentation.thread.tracing` is now enabled by default. This will allow the agent to properly monitor code that occurs inside of threads. If you are currently using custom instrumentation to start a new transaction inside of threads, this may be a breaking change, as it will no longer start a new transaction if one already exists.
+
+
+
 ## 8.16.0
 
 Version 8.16.0 of the agent introduces additional Ruby on Rails instrumentation (especially for Rails 6 and 7) for various Action\*/Active\* libraries whose actions produce [Active Support notifications events](https://guides.rubyonrails.org/active_support_instrumentation.html).

infinite_tracing/lib/infinite_tracing/client.rb

@@ -133,9 +133,11 @@ def transfer_buffer
       end
 
       def restart
-        reset_connection
-        transfer_buffer
-        start_streaming
+        NewRelic::Agent.disable_all_tracing do
+          reset_connection
+          transfer_buffer
+          start_streaming
+        end
       end
 
       def stop
@@ -150,8 +152,10 @@ def stop
       def start_streaming(exponential_backoff = true)
         return if suspended?
 
-        Connection.instance.wait_for_agent_connect
-        @lock.synchronize { response_handler(exponential_backoff) }
+        NewRelic::Agent.disable_all_tracing do
+          Connection.instance.wait_for_agent_connect
+          @lock.synchronize { response_handler(exponential_backoff) }
+        end
       end
 
       def record_spans(exponential_backoff)

lib/new_relic/agent/configuration/default_source.rb

@@ -1835,7 +1835,7 @@ def self.enforce_fallback(allowed_values: nil, fallback: nil)
           :description => "Controls auto-instrumentation of the Thread class at start up to allow the agent to correctly nest spans inside of an asynchronous transaction. This does not enable the agent to automatically trace all threads created (see `instrumentation.thread.tracing`). May be one of [auto|prepend|chain|disabled]."
         },
         :'instrumentation.thread.tracing' => {
-          :default => false,
+          :default => true,
           :public => true,
           :type => Boolean,
           :allowed_from_server => false,

lib/new_relic/agent/instrumentation/rake/instrumentation.rb

@@ -73,10 +73,6 @@ def instrument_invoke_prerequisites_concurrently(task)
           task.instance_eval do
             def invoke_prerequisites_concurrently(*_)
               NewRelic::Agent::MethodTracer.trace_execution_scoped("Rake/execute/multitask") do
-                prereqs = self.prerequisite_tasks.map(&:name).join(", ")
-                if txn = ::NewRelic::Agent::Tracer.current_transaction
-                  txn.current_segment.params[:statement] = NewRelic::Agent::Database.truncate_query("Couldn't trace concurrent prereq tasks: #{prereqs}")
-                end
                 super
               end
             end
@@ -86,12 +82,9 @@ def invoke_prerequisites_concurrently(*_)
         def before_invoke_transaction(task)
           ensure_at_exit
 
-          # We can't represent overlapping operations yet, so if multitask just
-          # make one node and annotate with prereq task names
+          instrument_execute_on_prereqs(task)
           if task.application.options.always_multitask
             instrument_invoke_prerequisites_concurrently(task)
-          else
-            instrument_execute_on_prereqs(task)
           end
         rescue => e
           NewRelic::Agent.logger.error("Error during Rake task invoke", e)

lib/new_relic/agent/tracer.rb

@@ -411,6 +411,7 @@ def clear_state
         alias_method :tl_clear, :clear_state
 
         def thread_block_with_current_transaction(*args, segment_name:, parent: nil, &block)
+          parent ||= current_segment
           current_txn = ::Thread.current[:newrelic_tracer_state].current_transaction if ::Thread.current[:newrelic_tracer_state] && ::Thread.current[:newrelic_tracer_state].is_execution_traced?
           proc do
             begin

newrelic.yml

@@ -447,7 +447,7 @@ common: &default_settings
   # instrumentation.thread: auto
 
   # Controls auto-instrumentation of the Thread class at start up to automatically add tracing to all Threads created in the application.
-  # instrumentation.thread.tracing: false
+  # instrumentation.thread.tracing: true
 
   # Controls auto-instrumentation of gRPC clients at start up.
   # May be one of [auto|prepend|chain|disabled].

test/multiverse/suites/concurrent_ruby/concurrent_ruby_instrumentation_test.rb

@@ -38,7 +38,11 @@ def test_promises_future_creates_segment_with_default_name
     txn = future_in_transaction { 'time keeps on slipping' }
     expected_segment = 'Concurrent/Task'
 
-    assert_equal(2, txn.segments.length)
+    # concurrent ruby sometimes reuses threads, so in that case there would be no segment for the thread being created.
+    # this removes any thread segment since it may or may not exist, depending on what concurrent ruby decided to do
+    non_thread_segments = txn.segments.select { |seg| seg.name != 'Ruby/Thread' }
+
+    assert_equal(2, non_thread_segments.length)
     assert_includes txn.segments.map(&:name), expected_segment
   end
 
@@ -99,12 +103,15 @@ def test_task_segment_has_correct_parent
   end
 
   def test_segment_not_created_if_tracing_disabled
-    NewRelic::Agent::Tracer.stub :tracing_enabled?, false do
-      txn = future_in_transaction { 'the revolution will not be televised' }
-
-      assert_predicate txn.segments, :one?
-      assert_equal txn.segments.first.name, txn.best_name
+    txn = in_transaction do
+      NewRelic::Agent.disable_all_tracing do
+        future = Concurrent::Promises.future { 'the revolution will not be televised' }
+        future.wait!
+      end
     end
+
+    assert_predicate txn.segments, :one?
+    assert_equal txn.segments.first.name, txn.best_name
   end
 
   def test_supportability_metric_recorded_once

test/multiverse/suites/rake/Rakefile

@@ -45,14 +45,20 @@ namespace :named do
   task :all => [:'named:before', :'named:during', :'named:after']
 
   task :before do
+    a = NewRelic::Agent::Tracer.start_segment(name: 'custom_before')
     puts "named:before"
+    a.finish
   end
 
   task :during do
+    a = NewRelic::Agent::Tracer.start_segment(name: 'custom_during')
     puts "named:during"
+    a.finish
   end
 
   task :after do
+    a = NewRelic::Agent::Tracer.start_segment(name: 'custom_after')
     puts "named:after"
+    a.finish
   end
 end

test/multiverse/suites/rake/instrumentation_test.rb

@@ -131,31 +131,18 @@ def test_instrument_execute_covers_super
     assert task.instance_variable_get(:@__newrelic_instrumented_execute)
   end
 
-  def test_before_invoke_transaction_with_concurrent_invocation_and_current_transaction
+  def test_before_invoke_transaction_with_concurrent_invocation
+    prereq = MiniTest::Mock.new
+    prereq.expect :instance_variable_get, nil, [:@__newrelic_instrumented_execute]
+    prereq.expect :instance_variable_set, nil, [:@__newrelic_instrumented_execute, true]
+    prereq.expect :instance_eval, nil, []
+    prereq.expect :prerequisite_tasks, [], []
     task = OpenStruct.new(application: OpenStruct.new(options: OpenStruct.new(always_multitask: true)),
-      prerequisite_tasks: [OpenStruct.new(name: 'prereq')])
+      prerequisite_tasks: [prereq])
     NewRelic::Agent::Instrumentation::Rake.class_eval do
       def ensure_at_exit; end
     end
     NewRelic::Agent::Instrumentation::Rake.before_invoke_transaction(task)
-    txn = MiniTest::Mock.new
-    segment = MiniTest::Mock.new
-    txn.expect :current_segment, segment
-    segment.expect :params, {}
-    NewRelic::Agent::Tracer.stub :current_transaction, txn do
-      task.execute
-      task.invoke_prerequisites_concurrently
-      txn.verify
-      segment.verify
-    end
-  end
-
-  def test_before_invoke_transaction_with_concurrent_invocation_without_transaction
-    prereq = MiniTest::Mock.new
-    prereq.expect :name, 'name'
-    task = OpenStruct.new(application: OpenStruct.new(options: OpenStruct.new(always_multitask: true)),
-      prerequisite_tasks: [prereq])
-    NewRelic::Agent::Instrumentation::Rake.before_invoke_transaction(task)
     NewRelic::Agent::Tracer.stub :current_transaction, nil do
       task.execute
       task.invoke_prerequisites_concurrently

test/multiverse/suites/rake/multitask_test.rb

@@ -18,23 +18,30 @@ def test_generate_scoped_metrics_for_children_if_always_multitask_set
         assert_metric_names_posted "OtherTransaction/Rake/invoke/named:all",
           "OtherTransaction/Rake/all",
           "OtherTransaction/all",
-          "Rake/execute/multitask"
-
-        refute_metric_names_posted "Rake/execute/named:before",
+          "Rake/execute/multitask",
+          "Rake/execute/named:before",
           "Rake/execute/named:during",
           "Rake/execute/named:after"
       end
     end
 
-    def test_generate_transaction_trace_with_placeholder_node
+    def test_generate_transaction_trace_with_multitask
       with_tasks_traced("named:all") do
         run_rake("named:all --multitask")
 
-        expected = [{},
-          [{},
-            [{"statement" => "Couldn't trace concurrent prereq tasks: named:before, named:during, named:after"}]]]
+        expected_nodes = ["ROOT",
+          "OtherTransaction/Rake/invoke/named:all",
+          "Rake/execute/multitask",
+          "Rake/execute/named:before",
+          "custom_before",
+          "Rake/execute/named:during",
+          "custom_during",
+          "Rake/execute/named:after",
+          "custom_after"]
 
-        assert_equal expected, single_transaction_trace_posted.tree.node_params
+        actual_nodes = single_transaction_trace_posted.tree.nodes.flatten
+        # check to make sure all expected nodes are inside of actual
+        assert_empty expected_nodes - actual_nodes
       end
     end
   end

test/new_relic/agent/tracer_test.rb

@@ -359,10 +359,34 @@ def test_current_segment_in_nested_threads_auto
             segment.finish # finish thread segment
           end
 
+          assert_equal txn.initial_segment, Tracer.current_segment
+
+          threads.each(&:join)
+          txn.finish
+
+          assert_equal 2, txn.segments.count { |s| s.name == "Ruby/Thread" }
+          assert_nil Tracer.current_segment
+        end
+      end
+
+      def test_current_segment_in_nested_threads_disabled
+        with_config(:'instrumentation.thread.tracing' => false) do
+          assert_nil Tracer.current_segment
+
+          txn = Tracer.start_transaction(name: "Controller/blogs/index", category: :controller)
+
+          assert_equal txn.initial_segment, Tracer.current_segment
+          threads = []
+
+          threads << ::Thread.new do
+            # nothong
+          end
+
           assert_equal txn.initial_segment, Tracer.current_segment
           threads.each(&:join)
           txn.finish
 
+          assert_equal 0, txn.segments.count { |s| s.name == "Ruby/Thread" }
           assert_nil Tracer.current_segment
         end
       end