Merge branch 'georgekoltsov/add-timing-logs-to-project-export-worker' into 'master'

Add Project Export granular exporter timings

See merge request gitlab-org/gitlab!83875

app/services/projects/import_export/export_service.rb

@@ -23,6 +23,13 @@ module Projects
         cleanup
       end
 
+      def exporters
+        [
+          version_saver, avatar_saver, project_tree_saver, uploads_saver,
+          repo_saver, wiki_repo_saver, lfs_saver, snippets_repo_saver, design_repo_saver
+        ]
+      end
+
       protected
 
       def extra_attributes_for_measurement
@@ -59,30 +66,23 @@ module Projects
       end
 
       def save_export_archive
-        Gitlab::ImportExport::Saver.save(exportable: project, shared: shared)
-      end
-
-      def exporters
-        [
-          version_saver, avatar_saver, project_tree_saver, uploads_saver,
-          repo_saver, wiki_repo_saver, lfs_saver, snippets_repo_saver, design_repo_saver
-        ]
+        @export_saver ||= Gitlab::ImportExport::Saver.save(exportable: project, shared: shared)
       end
 
       def version_saver
-        Gitlab::ImportExport::VersionSaver.new(shared: shared)
+        @version_saver ||= Gitlab::ImportExport::VersionSaver.new(shared: shared)
       end
 
       def avatar_saver
-        Gitlab::ImportExport::AvatarSaver.new(project: project, shared: shared)
+        @avatar_saver ||= Gitlab::ImportExport::AvatarSaver.new(project: project, shared: shared)
       end
 
       def project_tree_saver
-        tree_saver_class.new(project: project,
-                             current_user: current_user,
-                             shared: shared,
-                             params: params,
-                             logger: logger)
+        @project_tree_saver ||= tree_saver_class.new(project: project,
+                                  current_user: current_user,
+                                  shared: shared,
+                                  params: params,
+                                  logger: logger)
       end
 
       def tree_saver_class
@@ -90,27 +90,31 @@ module Projects
       end
 
       def uploads_saver
-        Gitlab::ImportExport::UploadsSaver.new(project: project, shared: shared)
+        @uploads_saver ||= Gitlab::ImportExport::UploadsSaver.new(project: project, shared: shared)
       end
 
       def repo_saver
-        Gitlab::ImportExport::RepoSaver.new(exportable: project, shared: shared)
+        @repo_saver ||= Gitlab::ImportExport::RepoSaver.new(exportable: project, shared: shared)
       end
 
       def wiki_repo_saver
-        Gitlab::ImportExport::WikiRepoSaver.new(exportable: project, shared: shared)
+        @wiki_repo_saver ||= Gitlab::ImportExport::WikiRepoSaver.new(exportable: project, shared: shared)
       end
 
       def lfs_saver
-        Gitlab::ImportExport::LfsSaver.new(project: project, shared: shared)
+        @lfs_saver ||= Gitlab::ImportExport::LfsSaver.new(project: project, shared: shared)
       end
 
       def snippets_repo_saver
-        Gitlab::ImportExport::SnippetsRepoSaver.new(current_user: current_user, project: project, shared: shared)
+        @snippets_repo_saver ||= Gitlab::ImportExport::SnippetsRepoSaver.new(
+          current_user: current_user,
+          project: project,
+          shared: shared
+        )
       end
 
       def design_repo_saver
-        Gitlab::ImportExport::DesignRepoSaver.new(exportable: project, shared: shared)
+        @design_repo_saver ||= Gitlab::ImportExport::DesignRepoSaver.new(exportable: project, shared: shared)
       end
 
       def cleanup

app/workers/project_export_worker.rb

@@ -21,7 +21,10 @@ class ProjectExportWorker # rubocop:disable Scalability/IdempotentWorker
 
     export_job&.start
 
-    ::Projects::ImportExport::ExportService.new(project, current_user, params).execute(after_export)
+    export_service = ::Projects::ImportExport::ExportService.new(project, current_user, params)
+    export_service.execute(after_export)
+
+    log_exporters_duration(export_service)
 
     export_job&.finish
   rescue ActiveRecord::RecordNotFound => e
@@ -46,4 +49,13 @@ class ProjectExportWorker # rubocop:disable Scalability/IdempotentWorker
   def log_failure(project_id, ex)
     logger.error("Failed to export project #{project_id}: #{ex.message}")
   end
+
+  def log_exporters_duration(export_service)
+    export_service.exporters.each do |exporter|
+      exporter_key = "#{exporter.class.name.demodulize.underscore}_duration_s".to_sym # e.g. uploads_saver_duration_s
+      exporter_duration = exporter.duration_s&.round(6)
+
+      log_extra_metadata_on_done(exporter_key, exporter_duration)
+    end
+  end
 end

lib/gitlab/import_export/avatar_saver.rb

@@ -3,19 +3,23 @@
 module Gitlab
   module ImportExport
     class AvatarSaver
+      include DurationMeasuring
+
       def initialize(project:, shared:)
         @project = project
         @shared = shared
       end
 
       def save
-        return true unless @project.avatar.exists?
+        with_duration_measuring do
+          break true unless @project.avatar.exists?
 
-        Gitlab::ImportExport::UploadsManager.new(
-          project: @project,
-          shared: @shared,
-          relative_export_path: 'avatar'
-        ).save
+          Gitlab::ImportExport::UploadsManager.new(
+            project: @project,
+            shared: @shared,
+            relative_export_path: 'avatar'
+          ).save
+        end
       rescue StandardError => e
         @shared.error(e)
         false

lib/gitlab/import_export/duration_measuring.rb

+# frozen_string_literal: true
+
+module Gitlab
+  module ImportExport
+    module DurationMeasuring
+      extend ActiveSupport::Concern
+
+      included do
+        attr_reader :duration_s
+
+        def with_duration_measuring
+          result = nil
+
+          @duration_s = Benchmark.realtime do
+            result = yield
+          end
+
+          result
+        end
+      end
+    end
+  end
+end

lib/gitlab/import_export/lfs_saver.rb

@@ -4,6 +4,7 @@ module Gitlab
   module ImportExport
     class LfsSaver
       include Gitlab::ImportExport::CommandLineUtil
+      include DurationMeasuring
 
       attr_accessor :lfs_json, :project, :shared
 
@@ -16,17 +17,19 @@ module Gitlab
       end
 
       def save
-        project.lfs_objects.find_in_batches(batch_size: BATCH_SIZE) do |batch|
-          batch.each do |lfs_object|
-            save_lfs_object(lfs_object)
-          end
+        with_duration_measuring do
+          project.lfs_objects.find_in_batches(batch_size: BATCH_SIZE) do |batch|
+            batch.each do |lfs_object|
+              save_lfs_object(lfs_object)
+            end
 
-          append_lfs_json_for_batch(batch)
-        end
+            append_lfs_json_for_batch(batch)
+          end
 
-        write_lfs_json
+          write_lfs_json
 
-        true
+          true
+        end
       rescue StandardError => e
         shared.error(e)
 

lib/gitlab/import_export/project/tree_saver.rb

@@ -4,6 +4,8 @@ module Gitlab
   module ImportExport
     module Project
       class TreeSaver
+        include DurationMeasuring
+
         attr_reader :full_path
 
         def initialize(project:, current_user:, shared:, params: {}, logger: Gitlab::Import::Logger)
@@ -15,9 +17,11 @@ module Gitlab
         end
 
         def save
-          stream_export
+          with_duration_measuring do
+            stream_export
 
-          true
+            true
+          end
         rescue StandardError => e
           @shared.error(e)
           false

lib/gitlab/import_export/repo_saver.rb

@@ -4,6 +4,7 @@ module Gitlab
   module ImportExport
     class RepoSaver
       include Gitlab::ImportExport::CommandLineUtil
+      include DurationMeasuring
 
       attr_reader :exportable, :shared
 
@@ -13,9 +14,12 @@ module Gitlab
       end
 
       def save
-        return true unless repository_exists? # it's ok to have no repo
+        with_duration_measuring do
+          # it's ok to have no repo
+          break true unless repository_exists?
 
-        bundle_to_disk
+          bundle_to_disk
+        end
       end
 
       def repository

lib/gitlab/import_export/snippets_repo_saver.rb

@@ -4,6 +4,7 @@ module Gitlab
   module ImportExport
     class SnippetsRepoSaver
       include Gitlab::ImportExport::CommandLineUtil
+      include DurationMeasuring
 
       def initialize(current_user:, project:, shared:)
         @project = project
@@ -12,13 +13,15 @@ module Gitlab
       end
 
       def save
-        create_snippets_repo_directory
+        with_duration_measuring do
+          create_snippets_repo_directory
 
-        @project.snippets.find_each.all? do |snippet|
-          Gitlab::ImportExport::SnippetRepoSaver.new(project: @project,
-                                                     shared: @shared,
-                                                     repository: snippet.repository)
-                                                .save
+          @project.snippets.find_each.all? do |snippet|
+            Gitlab::ImportExport::SnippetRepoSaver.new(project: @project,
+                                                       shared: @shared,
+                                                       repository: snippet.repository)
+                                                  .save
+          end
         end
       end
 

lib/gitlab/import_export/uploads_saver.rb

@@ -3,16 +3,20 @@
 module Gitlab
   module ImportExport
     class UploadsSaver
+      include DurationMeasuring
+
       def initialize(project:, shared:)
         @project = project
         @shared = shared
       end
 
       def save
-        Gitlab::ImportExport::UploadsManager.new(
-          project: @project,
-          shared: @shared
-        ).save
+        with_duration_measuring do
+          Gitlab::ImportExport::UploadsManager.new(
+            project: @project,
+            shared: @shared
+          ).save
+        end
       rescue StandardError => e
         @shared.error(e)
         false

lib/gitlab/import_export/version_saver.rb

@@ -4,17 +4,20 @@ module Gitlab
   module ImportExport
     class VersionSaver
       include Gitlab::ImportExport::CommandLineUtil
+      include DurationMeasuring
 
       def initialize(shared:)
         @shared = shared
       end
 
       def save
-        mkdir_p(@shared.export_path)
+        with_duration_measuring do
+          mkdir_p(@shared.export_path)
 
-        File.write(version_file, Gitlab::ImportExport.version, mode: 'w')
-        File.write(gitlab_version_file, Gitlab::VERSION, mode: 'w')
-        File.write(gitlab_revision_file, Gitlab.revision, mode: 'w')
+          File.write(version_file, Gitlab::ImportExport.version, mode: 'w')
+          File.write(gitlab_version_file, Gitlab::VERSION, mode: 'w')
+          File.write(gitlab_revision_file, Gitlab.revision, mode: 'w')
+        end
       rescue StandardError => e
         @shared.error(e)
         false

spec/lib/gitlab/import_export/duration_measuring_spec.rb

+# frozen_string_literal: true
+
+require 'fast_spec_helper'
+
+RSpec.describe Gitlab::ImportExport::DurationMeasuring do
+  subject do
+    Class.new do
+      include Gitlab::ImportExport::DurationMeasuring
+
+      def test
+        with_duration_measuring do
+          'test'
+        end
+      end
+    end.new
+  end
+
+  it 'measures method execution duration' do
+    subject.test
+
+    expect(subject.duration_s).not_to be_nil
+  end
+
+  describe '#with_duration_measuring' do
+    it 'yields control' do
+      expect { |block| subject.with_duration_measuring(&block) }.to yield_control
+    end
+
+    it 'returns result of the yielded block' do
+      return_value = 'return_value'
+
+      expect(subject.with_duration_measuring { return_value }).to eq(return_value)
+    end
+  end
+end

spec/workers/project_export_worker_spec.rb

@@ -4,4 +4,30 @@ require 'spec_helper'
 
 RSpec.describe ProjectExportWorker do
   it_behaves_like 'export worker'
+
+  context 'exporters duration measuring' do
+    let(:user) { create(:user) }
+    let(:project) { create(:project) }
+    let(:worker) { described_class.new }
+
+    subject { worker.perform(user.id, project.id) }
+
+    before do
+      project.add_owner(user)
+    end
+
+    it 'logs exporters execution duration' do
+      expect(worker).to receive(:log_extra_metadata_on_done).with(:version_saver_duration_s, anything)
+      expect(worker).to receive(:log_extra_metadata_on_done).with(:avatar_saver_duration_s, anything)
+      expect(worker).to receive(:log_extra_metadata_on_done).with(:tree_saver_duration_s, anything)
+      expect(worker).to receive(:log_extra_metadata_on_done).with(:uploads_saver_duration_s, anything)
+      expect(worker).to receive(:log_extra_metadata_on_done).with(:repo_saver_duration_s, anything)
+      expect(worker).to receive(:log_extra_metadata_on_done).with(:wiki_repo_saver_duration_s, anything)
+      expect(worker).to receive(:log_extra_metadata_on_done).with(:lfs_saver_duration_s, anything)
+      expect(worker).to receive(:log_extra_metadata_on_done).with(:snippets_repo_saver_duration_s, anything)
+      expect(worker).to receive(:log_extra_metadata_on_done).with(:design_repo_saver_duration_s, anything)
+
+      subject
+    end
+  end
 end