From ce49fa9b31cd4a21d43db39d0cea364bce28b51d Mon Sep 17 00:00:00 2001 From: Daniel Colson Date: Wed, 6 Sep 2023 19:30:30 -0400 Subject: [PATCH] Instrument Active Record transactions MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Tracking Active Record-managed transactions seems to be a common need, but there's currently not a great way to do it. Here's a few examples I've seen: * GitHub has custom transaction tracking that monkey patches the Active Record `TransactionManager` and `RealTransaction`. We use the tracking to prevent opening a transaction to one database cluster inside a transaction to a different database cluster, and to report slow transactions (we get slow transaction data directly from MySQL as well, but it's still helpful to report from the application with backtraces to help track them down). * https://github.com/palkan/isolator tracks transactions to prevent non-atomic interactions like external network calls inside a transaction. The gem works by subscribing to `sql.active_record`, then piecing together the transactions by looking for `BEGIN`, `COMMIT`, `SAVEPOINT`, etc., but this is unreliable: - https://github.com/palkan/isolator/issues/65 - https://github.com/palkan/isolator/issues/64 * It looks like GitLab patches `TransactionManager` and `RealTransaction` to track nested savepoints. See https://github.com/palkan/isolator/issues/46 This commit adds a new `transaction.active_record` event that should provide a more reliable solution for these various use cases. It includes the connection in the payload (useful, for example, in differentiating transactions to different databases), but if this change gets merged we're also planning to add details about what type of transaction it is (savepoint or real) and what the outcome is (commit, rollback, restarted, errored). This instrumentation needs to start and finish at fairly specific times: - start on materialize - finish after committing or rolling back, but before the after_commit or after_rollback callbacks - finish and start again when the transaction restarts (at least for real transactions—we've done it for savepoints as well but I'm not certain we should) - ensure it finishes if commit and rollback fail (e.g. if the connection goes away) To make all that work, this commit uses the lower-level `#build-handle` API instead of `#instrument`. Co-authored-by: Ian Candy --- activerecord/CHANGELOG.md | 14 + .../abstract/transaction.rb | 48 ++- .../cases/transaction_instrumentation_test.rb | 277 ++++++++++++++++++ 3 files changed, 337 insertions(+), 2 deletions(-) create mode 100644 activerecord/test/cases/transaction_instrumentation_test.rb diff --git a/activerecord/CHANGELOG.md b/activerecord/CHANGELOG.md index 21bf13bdfbe30..ad6183bdf55a5 100644 --- a/activerecord/CHANGELOG.md +++ b/activerecord/CHANGELOG.md @@ -1,3 +1,17 @@ +* Add instrumentation for Active Record transactions + + Allows subscribing to transaction events for tracking/instrumentation. The event payload contains the connection, as well as timing details. + + ```ruby + ActiveSupport::Notifications.subscribe("transaction.active_record") do |event| + puts "Transaction event occurred!" + connection = event.payload[:connection] + puts "Connection: #{connection.inspect}" + end + ``` + + *Daniel Colson*, *Ian Candy* + * Support composite foreign keys via migration helpers. ```ruby diff --git a/activerecord/lib/active_record/connection_adapters/abstract/transaction.rb b/activerecord/lib/active_record/connection_adapters/abstract/transaction.rb index cf00a9fb7cb0e..648dc38ed7af9 100644 --- a/activerecord/lib/active_record/connection_adapters/abstract/transaction.rb +++ b/activerecord/lib/active_record/connection_adapters/abstract/transaction.rb @@ -74,6 +74,29 @@ def nullify! end end + class TransactionInstrumenter + def initialize(payload = {}) + @handle = nil + @started = false + @payload = payload + end + + def start + return if @started + @started = true + + @handle = ActiveSupport::Notifications.instrumenter.build_handle("transaction.active_record", @payload) + @handle.start + end + + def finish + return unless @started + @started = false + + @handle.finish + end + end + class NullTransaction # :nodoc: def initialize; end def state; end @@ -104,6 +127,7 @@ def initialize(connection, isolation: nil, joinable: true, run_commit_callbacks: @run_commit_callbacks = run_commit_callbacks @lazy_enrollment_records = nil @dirty = false + @instrumenter = TransactionInstrumenter.new(connection: connection) end def dirty! @@ -138,8 +162,13 @@ def restartable? joinable? && !dirty? end + def incomplete! + @instrumenter.finish + end + def materialize! @materialized = true + @instrumenter.start end def materialized? @@ -303,7 +332,12 @@ def materialize! end def restart - connection.rollback_to_savepoint(savepoint_name) if materialized? + return unless materialized? + + @instrumenter.finish + @instrumenter.start + + connection.rollback_to_savepoint(savepoint_name) end def rollback @@ -311,11 +345,13 @@ def rollback connection.rollback_to_savepoint(savepoint_name) if materialized? end @state.rollback! + @instrumenter.finish end def commit connection.release_savepoint(savepoint_name) if materialized? @state.commit! + @instrumenter.finish end def full_rollback?; false; end @@ -336,7 +372,10 @@ def materialize! def restart return unless materialized? + @instrumenter.finish + if connection.supports_restart_db_transaction? + @instrumenter.start connection.restart_db_transaction else connection.rollback_db_transaction @@ -347,11 +386,13 @@ def restart def rollback connection.rollback_db_transaction if materialized? @state.full_rollback! + @instrumenter.finish end def commit connection.commit_db_transaction if materialized? @state.full_commit! + @instrumenter.finish end end @@ -526,7 +567,10 @@ def within_new_transaction(isolation: nil, joinable: true) end end ensure - @connection.throw_away! unless transaction&.state&.completed? + unless transaction&.state&.completed? + @connection.throw_away! + transaction&.incomplete! + end end end diff --git a/activerecord/test/cases/transaction_instrumentation_test.rb b/activerecord/test/cases/transaction_instrumentation_test.rb new file mode 100644 index 0000000000000..e80811d36ecc3 --- /dev/null +++ b/activerecord/test/cases/transaction_instrumentation_test.rb @@ -0,0 +1,277 @@ +# frozen_string_literal: true + +require "cases/helper" +require "models/topic" + +class TransactionInstrumentationTest < ActiveRecord::TestCase + self.use_transactional_tests = false + fixtures :topics + + def test_transaction_instrumentation_on_commit + topic = topics(:fifth) + + notified = false + subscriber = ActiveSupport::Notifications.subscribe("transaction.active_record") do |event| + assert event.payload[:connection] + notified = true + end + + ActiveRecord::Base.transaction do + topic.update(title: "Ruby on Rails") + end + + assert notified + ensure + ActiveSupport::Notifications.unsubscribe(subscriber) if subscriber + end + + def test_transaction_instrumentation_on_rollback + topic = topics(:fifth) + + notified = false + subscriber = ActiveSupport::Notifications.subscribe("transaction.active_record") do |event| + assert event.payload[:connection] + notified = true + end + + ActiveRecord::Base.transaction do + topic.update(title: "Ruby on Rails") + raise ActiveRecord::Rollback + end + + assert notified + ensure + ActiveSupport::Notifications.unsubscribe(subscriber) if subscriber + end + + def test_transaction_instrumentation_with_savepoints + topic = topics(:fifth) + + events = [] + subscriber = ActiveSupport::Notifications.subscribe("transaction.active_record") do |event| + events << event + end + + ActiveRecord::Base.transaction do + topic.update(title: "Sinatra") + ActiveRecord::Base.transaction(requires_new: true) do + topic.update(title: "Ruby on Rails") + end + end + + assert_equal 2, events.count + ensure + ActiveSupport::Notifications.unsubscribe(subscriber) if subscriber + end + + def test_transaction_instrumentation_with_restart_parent_transaction_on_commit + topic = topics(:fifth) + + events = [] + subscriber = ActiveSupport::Notifications.subscribe("transaction.active_record") do |event| + events << event + end + + ActiveRecord::Base.transaction do + ActiveRecord::Base.transaction(requires_new: true) do + topic.update(title: "Ruby on Rails") + end + end + + assert_equal 1, events.count + ensure + ActiveSupport::Notifications.unsubscribe(subscriber) if subscriber + end + + def test_transaction_instrumentation_with_restart_parent_transaction_on_rollback + topic = topics(:fifth) + + events = [] + subscriber = ActiveSupport::Notifications.subscribe("transaction.active_record") do |event| + events << event + end + + ActiveRecord::Base.transaction do + ActiveRecord::Base.transaction(requires_new: true) do + topic.update(title: "Ruby on Rails") + raise ActiveRecord::Rollback + end + raise ActiveRecord::Rollback + end + + assert_equal 2, events.count + ensure + ActiveSupport::Notifications.unsubscribe(subscriber) if subscriber + end + + def test_transaction_instrumentation_with_unmaterialized_restart_parent_transactions + events = [] + subscriber = ActiveSupport::Notifications.subscribe("transaction.active_record") do |event| + events << event + end + + ActiveRecord::Base.transaction do + ActiveRecord::Base.transaction(requires_new: true) do + raise ActiveRecord::Rollback + end + end + + assert_equal 0, events.count + ensure + ActiveSupport::Notifications.unsubscribe(subscriber) if subscriber + end + + def test_transaction_instrumentation_with_restart_savepoint_parent_transactions + topic = topics(:fifth) + + events = [] + subscriber = ActiveSupport::Notifications.subscribe("transaction.active_record") do |event| + events << event + end + + ActiveRecord::Base.transaction do + topic.update(title: "Sinatry") + ActiveRecord::Base.transaction(requires_new: true) do + ActiveRecord::Base.transaction(requires_new: true) do + topic.update(title: "Ruby on Rails") + raise ActiveRecord::Rollback + end + end + end + + assert_equal 3, events.count + ensure + ActiveSupport::Notifications.unsubscribe(subscriber) if subscriber + end + + def test_transaction_instrumentation_only_fires_if_materialized + notified = false + subscriber = ActiveSupport::Notifications.subscribe("transaction.active_record") do |event| + notified = true + end + + ActiveRecord::Base.transaction do + end + + assert_not notified + ensure + ActiveSupport::Notifications.unsubscribe(subscriber) if subscriber + end + + def test_transaction_instrumentation_fires_before_after_commit_callbacks + notified = false + after_commit_triggered = false + + topic_model = Class.new(ActiveRecord::Base) do + self.table_name = "topics" + + after_commit do + after_commit_triggered = true + end + end + + subscriber = ActiveSupport::Notifications.subscribe("transaction.active_record") do |event| + assert_not after_commit_triggered, "Transaction notification fired after the after_commit callback" + notified = true + end + + topic_model.create! + + assert notified + assert after_commit_triggered + ensure + ActiveSupport::Notifications.unsubscribe(subscriber) if subscriber + end + + def test_transaction_instrumentation_fires_before_after_rollback_callbacks + notified = false + after_rollback_triggered = false + + topic_model = Class.new(ActiveRecord::Base) do + self.table_name = "topics" + + after_rollback do + after_rollback_triggered = true + end + end + + subscriber = ActiveSupport::Notifications.subscribe("transaction.active_record") do |event| + assert_not after_rollback_triggered, "Transaction notification fired after the after_rollback callback" + notified = true + end + + topic_model.transaction do + topic_model.create! + raise ActiveRecord::Rollback + end + + assert notified + assert after_rollback_triggered + ensure + ActiveSupport::Notifications.unsubscribe(subscriber) if subscriber + end + + def test_transaction_instrumentation_on_failed_commit + topic = topics(:fifth) + + notified = false + subscriber = ActiveSupport::Notifications.subscribe("transaction.active_record") do |event| + notified = true + end + + error = Class.new(StandardError) + assert_raises error do + ActiveRecord::Base.connection.stub(:commit_db_transaction, -> (*) { raise error }) do + ActiveRecord::Base.transaction do + topic.update(title: "Ruby on Rails") + end + end + end + + assert notified + ensure + ActiveSupport::Notifications.unsubscribe(subscriber) if subscriber + end + + unless in_memory_db? + def test_transaction_instrumentation_on_failed_rollback + topic = topics(:fifth) + + notified = false + subscriber = ActiveSupport::Notifications.subscribe("transaction.active_record") do |event| + notified = true + end + + error = Class.new(StandardError) + assert_raises error do + ActiveRecord::Base.connection.stub(:rollback_db_transaction, -> (*) { raise error }) do + ActiveRecord::Base.transaction do + topic.update(title: "Ruby on Rails") + raise ActiveRecord::Rollback + end + end + end + + assert notified + ensure + ActiveSupport::Notifications.unsubscribe(subscriber) if subscriber + end + end + + def test_transaction_instrumentation_on_broken_subscription + topic = topics(:fifth) + + error = Class.new(StandardError) + subscriber = ActiveSupport::Notifications.subscribe("transaction.active_record") do |event| + raise error + end + + assert_raises(error) do + ActiveRecord::Base.transaction do + topic.update(title: "Ruby on Rails") + end + end + ensure + ActiveSupport::Notifications.unsubscribe(subscriber) if subscriber + end +end