Log backtrace when SAVEPOINT is discovered

We have mostly eliminated using subtransactions from the code, but there
are a few places where they may be happening. Log the backtrace of the
caller to identify exactly where this is happening.

Changelog: added

lib/gitlab/database/transaction/context.rb

@@ -38,6 +38,11 @@ module Gitlab
           (@context[:queries] ||= []).push(sql)
         end
 
+        def track_backtrace(backtrace)
+          cleaned_backtrace = Gitlab::BacktraceCleaner.clean_backtrace(backtrace)
+          (@context[:backtraces] ||= []).push(cleaned_backtrace)
+        end
+
         def duration
           return unless @context[:start_time].present?
 
@@ -66,6 +71,10 @@ module Gitlab
           log(:rollback)
         end
 
+        def backtraces
+          @context[:backtraces].to_a
+        end
+
         private
 
         def queries
@@ -99,7 +108,8 @@ module Gitlab
             savepoints_count: @context[:savepoints].to_i,
             rollbacks_count: @context[:rollbacks].to_i,
             releases_count: @context[:releases].to_i,
-            sql: queries
+            sql: queries,
+            savepoint_backtraces: backtraces
           }
 
           application_info(attributes)

lib/gitlab/database/transaction/observer.rb

@@ -24,6 +24,7 @@ module Gitlab
           elsif cmd.start_with?('SAVEPOINT', 'EXCEPTION')
             context.set_depth(manager.open_transactions)
             context.increment_savepoints
+            context.track_backtrace(caller)
           elsif cmd.start_with?('ROLLBACK TO SAVEPOINT')
             context.increment_rollbacks
           elsif cmd.start_with?('RELEASE SAVEPOINT ')

spec/lib/gitlab/database/transaction/context_spec.rb

@@ -62,6 +62,26 @@ RSpec.describe Gitlab::Database::Transaction::Context do
     it { expect(data[:queries]).to eq(['SELECT 1', 'SELECT * FROM users']) }
   end
 
+  describe '#track_backtrace' do
+    before do
+      subject.track_backtrace(caller)
+    end
+
+    it { expect(data[:backtraces]).to be_a(Array) }
+    it { expect(data[:backtraces]).to all(be_a(Array)) }
+    it { expect(data[:backtraces].length).to eq(1) }
+    it { expect(data[:backtraces][0][0]).to be_a(String) }
+
+    it 'appends the backtrace' do
+      subject.track_backtrace(caller)
+
+      expect(data[:backtraces].length).to eq(2)
+      expect(subject.backtraces).to be_a(Array)
+      expect(subject.backtraces).to all(be_a(Array))
+      expect(subject.backtraces[1][0]).to be_a(String)
+    end
+  end
+
   describe '#duration' do
     before do
       subject.set_start_time

spec/lib/gitlab/database/transaction/observer_spec.rb

@@ -25,7 +25,7 @@ RSpec.describe Gitlab::Database::Transaction::Observer do
           User.first
 
           expect(transaction_context).to be_a(::Gitlab::Database::Transaction::Context)
-          expect(context.keys).to match_array(%i(start_time depth savepoints queries))
+          expect(context.keys).to match_array(%i(start_time depth savepoints queries backtraces))
           expect(context[:depth]).to eq(2)
           expect(context[:savepoints]).to eq(1)
           expect(context[:queries].length).to eq(1)
@@ -35,6 +35,7 @@ RSpec.describe Gitlab::Database::Transaction::Observer do
       expect(context[:depth]).to eq(2)
       expect(context[:savepoints]).to eq(1)
       expect(context[:releases]).to eq(1)
+      expect(context[:backtraces].length).to eq(1)
     end
 
     describe '.extract_sql_command' do