diff --git a/CHANGELOG.md b/CHANGELOG.md index 37fdf78779..377feb6198 100644 --- a/CHANGELOG.md +++ b/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). diff --git a/infinite_tracing/lib/infinite_tracing/client.rb b/infinite_tracing/lib/infinite_tracing/client.rb index 64c949fd03..2a8585d55a 100644 --- a/infinite_tracing/lib/infinite_tracing/client.rb +++ b/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) diff --git a/lib/new_relic/agent/configuration/default_source.rb b/lib/new_relic/agent/configuration/default_source.rb index 182af4fd4d..7843cdda31 100644 --- a/lib/new_relic/agent/configuration/default_source.rb +++ b/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, diff --git a/lib/new_relic/agent/instrumentation/rake/instrumentation.rb b/lib/new_relic/agent/instrumentation/rake/instrumentation.rb index f559d77ed2..d18477210e 100644 --- a/lib/new_relic/agent/instrumentation/rake/instrumentation.rb +++ b/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) diff --git a/lib/new_relic/agent/tracer.rb b/lib/new_relic/agent/tracer.rb index 1fbe5d8c47..98710e2403 100644 --- a/lib/new_relic/agent/tracer.rb +++ b/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 diff --git a/newrelic.yml b/newrelic.yml index 2bfc3b2d5e..51506fa8de 100644 --- a/newrelic.yml +++ b/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]. diff --git a/test/multiverse/suites/concurrent_ruby/concurrent_ruby_instrumentation_test.rb b/test/multiverse/suites/concurrent_ruby/concurrent_ruby_instrumentation_test.rb index 432cbab38d..f189b5fa0f 100644 --- a/test/multiverse/suites/concurrent_ruby/concurrent_ruby_instrumentation_test.rb +++ b/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 diff --git a/test/multiverse/suites/rake/Rakefile b/test/multiverse/suites/rake/Rakefile index d6a4782a32..265baded0c 100644 --- a/test/multiverse/suites/rake/Rakefile +++ b/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 diff --git a/test/multiverse/suites/rake/instrumentation_test.rb b/test/multiverse/suites/rake/instrumentation_test.rb index cbc5e81fe3..47550bd89e 100644 --- a/test/multiverse/suites/rake/instrumentation_test.rb +++ b/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 diff --git a/test/multiverse/suites/rake/multitask_test.rb b/test/multiverse/suites/rake/multitask_test.rb index a2f28c5303..9de4efb691 100644 --- a/test/multiverse/suites/rake/multitask_test.rb +++ b/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 diff --git a/test/new_relic/agent/tracer_test.rb b/test/new_relic/agent/tracer_test.rb index 8718be2b50..9a6e8b0211 100644 --- a/test/new_relic/agent/tracer_test.rb +++ b/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