Log project export timings

This commit adds logging to `exporter.log` to track how long it takes
to perform certain parts of `Gitlab::ImportExport::Saver`.

For Google Cloud Storage uploads, Labkit is not able to track the HTTP
timings because the underlying `httpclient` gem manages its own SSL
socket. This commit will make it possible to see which steps are
taking a long time:

1. Creating the .tar.gz file (`compress_duration_s`).
2. Assigning the file to the CarrierWave uploader
   (`assign_duration_s`).
3. Saving the file to object storage/local storage
   (`upload_duration_s`).
4. Number of bytes to upload (`upload_bytes`).

Relates to https://gitlab.com/gitlab-org/gitlab/-/issues/349425

Changelog: added

lib/gitlab/import_export/saver.rb

@@ -16,19 +16,20 @@ module Gitlab
 
       def save
         if compress_and_save
-          Gitlab::Export::Logger.info(
-            message: 'Export archive saved',
-            exportable_class: @exportable.class.to_s,
-            archive_file: archive_file
-          )
+          log_export_results('Export archive saved')
 
           save_upload
+
+          log_export_results('Export archive uploaded')
         else
           @shared.error(Gitlab::ImportExport::Error.new(error_message))
+
           false
         end
       rescue StandardError => e
         @shared.error(e)
+        log_export_results('Export archive saver failed')
+
         false
       ensure
         remove_archive_tmp_dir
@@ -36,8 +37,16 @@ module Gitlab
 
       private
 
+      attr_accessor :compress_duration_s, :assign_duration_s, :upload_duration_s, :upload_bytes
+
       def compress_and_save
-        tar_czf(archive: archive_file, dir: @shared.export_path)
+        result = nil
+
+        @compress_duration_s = Benchmark.realtime do
+          result = tar_czf(archive: archive_file, dir: @shared.export_path)
+        end
+
+        result
       end
 
       def remove_archive_tmp_dir
@@ -51,9 +60,12 @@ module Gitlab
       def save_upload
         upload = initialize_upload
 
-        File.open(archive_file) { |file| upload.export_file = file }
+        @upload_bytes = File.size(archive_file)
+        @assign_duration_s = Benchmark.realtime do
+          File.open(archive_file) { |file| upload.export_file = file }
+        end
 
-        upload.save!
+        @upload_duration_s = Benchmark.realtime { upload.save! }
 
         true
       end
@@ -67,6 +79,23 @@ module Gitlab
 
         ImportExportUpload.find_or_initialize_by(Hash[exportable_kind, @exportable])
       end
+
+      def log_export_results(message)
+        Gitlab::Export::Logger.info(message: message, **log_data)
+      end
+
+      def log_data
+        ApplicationContext.current.merge(
+          {
+            exportable_class: @exportable.class.to_s,
+            archive_file: archive_file,
+            compress_duration_s: compress_duration_s&.round(6),
+            assign_duration_s: assign_duration_s&.round(6),
+            upload_duration_s: upload_duration_s&.round(6),
+            upload_bytes: upload_bytes
+          }
+        ).compact
+      end
     end
   end
 end

spec/lib/gitlab/import_export/saver_spec.rb

@@ -36,6 +36,32 @@ RSpec.describe Gitlab::ImportExport::Saver do
       .to match(%r[\/uploads\/-\/system\/import_export_upload\/export_file.*])
   end
 
+  it 'logs metrics after saving' do
+    stub_uploads_object_storage(ImportExportUploader)
+    expect(Gitlab::Export::Logger).to receive(:info).with(
+      hash_including(
+        message: 'Export archive saved',
+        exportable_class: 'Project',
+        'correlation_id' => anything,
+        archive_file: anything,
+        compress_duration_s: anything
+      )).and_call_original
+
+    expect(Gitlab::Export::Logger).to receive(:info).with(
+      hash_including(
+        message: 'Export archive uploaded',
+        exportable_class: 'Project',
+        'correlation_id' => anything,
+        archive_file: anything,
+        compress_duration_s: anything,
+        assign_duration_s: anything,
+        upload_duration_s: anything,
+        upload_bytes: anything
+      )).and_call_original
+
+    subject.save
+  end
+
   it 'removes archive path and keeps base path untouched' do
     allow(shared).to receive(:archive_path).and_return(archive_path)
 
@@ -45,4 +71,22 @@ RSpec.describe Gitlab::ImportExport::Saver do
     expect(FileUtils).to have_received(:rm_rf).with(archive_path)
     expect(Dir.exist?(archive_path)).to eq(false)
   end
+
+  context 'when save throws an exception' do
+    before do
+      expect(subject).to receive(:save_upload).and_raise(SocketError.new)
+    end
+
+    it 'logs a saver error' do
+      allow(Gitlab::Export::Logger).to receive(:info).with(anything).and_call_original
+      expect(Gitlab::Export::Logger).to receive(:info).with(
+        hash_including(
+          message: 'Export archive saver failed',
+          exportable_class: 'Project',
+          'correlation_id' => anything
+        )).and_call_original
+
+      subject.save
+    end
+  end
 end