Merge branch '21300-push-measurement-to-import-service' into 'master'

Move measurement to import service layer

See merge request gitlab-org/gitlab!29898

app/services/projects/gitlab_projects_import_service.rb

@@ -14,32 +14,56 @@ module Projects
       @current_user, @params, @override_params = user, import_params.dup, override_params
     end
 
-    def execute
+    def execute(options = {})
+      measurement_enabled = !!options[:measurement_enabled]
+      measurement_logger = options[:measurement_logger]
+
+      ::Gitlab::Utils::Measuring.execute_with(measurement_enabled, measurement_logger, base_log_data) do
         prepare_template_environment(template_file)
 
         prepare_import_params
 
         ::Projects::CreateService.new(current_user, params).execute
       end
+    end
 
     private
 
+    def base_log_data
+      base_log_data = {
+        class: self.class.name,
+        current_user: current_user.name,
+        project_full_path: project_path
+      }
+
+      if template_file
+        base_log_data[:import_type] = 'gitlab_project'
+        base_log_data[:file_path] = template_file.path
+      end
+
+      base_log_data
+    end
+
     def overwrite_project?
       overwrite? && project_with_same_full_path?
     end
 
     def project_with_same_full_path?
-      Project.find_by_full_path("#{current_namespace.full_path}/#{params[:path]}").present?
+      Project.find_by_full_path(project_path).present?
     end
 
     # rubocop: disable CodeReuse/ActiveRecord
     def current_namespace
       strong_memoize(:current_namespace) do
-        Namespace.find_by(id: params[:namespace_id])
+        Namespace.find_by(id: params[:namespace_id]) || current_user.namespace
       end
     end
     # rubocop: enable CodeReuse/ActiveRecord
 
+    def project_path
+      "#{current_namespace.full_path}/#{params[:path]}"
+    end
+
     def overwrite?
       strong_memoize(:overwrite) do
         params.delete(:overwrite)

ee/app/services/ee/projects/gitlab_projects_import_service.rb

@@ -7,7 +7,7 @@ module EE
       include ::Gitlab::Utils::StrongMemoize
 
       override :execute
-      def execute
+      def execute(options = {})
         super.tap do |project|
           if project.saved? && custom_template
             custom_template.add_export_job(current_user: current_user,

lib/gitlab/import_export/project/base_task.rb

@@ -30,6 +30,13 @@ module Gitlab
           true
         end
 
+        def measurement_options
+          {
+            measurement_enabled: measurement_enabled?,
+            measurement_logger: logger
+          }
+        end
+
         def error(message)
           logger.error(message)
 

lib/gitlab/import_export/project/import_task.rb

@@ -32,7 +32,7 @@ module Gitlab
               # https://gitlab.com/gitlab-org/gitlab/-/merge_requests/24475#note_283090635
               # For development setups, this code-path will be excluded from n+1 detection.
               ::Gitlab::GitalyClient.allow_n_plus_1_calls do
-                measurement_enabled? ? measurement.with_measuring { yield } : yield
+                yield
               end
             end
 
@@ -56,14 +56,10 @@ module Gitlab
           disable_upload_object_storage do
             service = Projects::GitlabProjectsImportService.new(
               current_user,
-              {
-                namespace_id: namespace.id,
-                path:         project_path,
-                file:         File.open(file_path)
-              }
+              import_params
             )
 
-            service.execute
+            service.execute(measurement_options)
           end
         end
 
@@ -99,6 +95,14 @@ module Gitlab
             " as #{current_user.name}"
         end
 
+        def import_params
+          {
+            namespace_id: namespace.id,
+            path:         project_path,
+            file:         File.open(file_path)
+          }
+        end
+
         def show_import_failures_count
           return unless project.import_failures.exists?
 

lib/gitlab/utils/measuring.rb

@@ -5,13 +5,25 @@ require 'prometheus/pid_provider'
 module Gitlab
   module Utils
     class Measuring
-      def initialize(logger: Logger.new($stdout))
-        @logger = logger
+      class << self
+        def execute_with(measurement_enabled, logger, base_log_data)
+          measurement_enabled ? measuring(logger, base_log_data).with_measuring { yield } : yield
+        end
+
+        private
+
+        def measuring(logger, base_log_data)
+          Gitlab::Utils::Measuring.new(logger: logger, base_log_data: base_log_data)
+        end
+      end
+
+      def initialize(logger: nil, base_log_data: {})
+        @logger = logger || Logger.new($stdout)
+        @base_log_data = base_log_data
       end
 
       def with_measuring
-        logger.info "Measuring enabled..."
-        with_gc_stats do
+        result = with_gc_stats do
           with_count_queries do
             with_measure_time do
               yield
@@ -19,45 +31,56 @@ module Gitlab
           end
         end
 
-        logger.info "Memory usage: #{Gitlab::Metrics::System.memory_usage.to_f / 1024 / 1024} MiB"
-        logger.info "Label: #{::Prometheus::PidProvider.worker_id}"
+        log_info(
+          gc_stats: gc_stats,
+          time_to_finish: time_to_finish,
+          number_of_sql_calls: sql_calls_count,
+          memory_usage: "#{Gitlab::Metrics::System.memory_usage.to_f / 1024 / 1024} MiB",
+          label: ::Prometheus::PidProvider.worker_id
+        )
+
+        result
       end
 
       private
 
-      attr_reader :logger
+      attr_reader :gc_stats, :time_to_finish, :sql_calls_count, :logger, :base_log_data
 
       def with_count_queries(&block)
-        count = 0
+        @sql_calls_count = 0
 
         counter_f = ->(_name, _started, _finished, _unique_id, payload) {
-          count += 1 unless payload[:name].in? %w[CACHE SCHEMA]
+          @sql_calls_count += 1 unless payload[:name].in? %w[CACHE SCHEMA]
         }
 
         ActiveSupport::Notifications.subscribed(counter_f, "sql.active_record", &block)
+      end
 
-        logger.info "Number of sql calls: #{count}"
+      def log_info(details)
+        details = base_log_data.merge(details)
+        details = details.to_yaml if ActiveSupport::Logger.logger_outputs_to?(logger, STDOUT)
+        logger.info(details)
       end
 
       def with_gc_stats
         GC.start # perform a full mark-and-sweep
         stats_before = GC.stat
-        yield
+        result = yield
         stats_after = GC.stat
-        stats_diff = stats_after.map do |key, after_value|
+        @gc_stats = stats_after.map do |key, after_value|
           before_value = stats_before[key]
           [key, before: before_value, after: after_value, diff: after_value - before_value]
         end.to_h
-        logger.info "GC stats:"
-        logger.info JSON.pretty_generate(stats_diff)
+        result
       end
 
       def with_measure_time
-        timing = Benchmark.realtime do
-          yield
+        result = nil
+        @time_to_finish = Benchmark.realtime do
+          result = yield
         end
 
-        logger.info "Time to finish: #{duration_in_numbers(timing)}"
+        result
       end
 
       def duration_in_numbers(duration_in_seconds)

spec/lib/gitlab/import_export/project/export_task_spec.rb

@@ -3,9 +3,9 @@
 require 'rake_helper'
 
 describe Gitlab::ImportExport::Project::ExportTask do
-  let(:username) { 'root' }
+  let_it_be(:username) { 'root' }
   let(:namespace_path) { username }
-  let!(:user) { create(:user, username: username) }
+  let_it_be(:user) { create(:user, username: username) }
   let(:measurement_enabled) { false }
   let(:file_path) { 'spec/fixtures/gitlab/import_export/test_project_export.tar.gz' }
   let(:project) { create(:project, creator: user, namespace: user.namespace) }

spec/lib/gitlab/utils/measuring_spec.rb

+# frozen_string_literal: true
+
+require 'fast_spec_helper'
+
+describe Gitlab::Utils::Measuring do
+  describe '#execute_with' do
+    let(:measurement_logger) { double(:logger) }
+    let(:base_log_data) do
+      {
+        class: described_class.name
+      }
+    end
+    let(:result_block) { 'result' }
+
+    subject { described_class.execute_with(measurement_enabled, measurement_logger, base_log_data) { result_block } }
+
+    context 'when measurement is enabled' do
+      let(:measurement_enabled) { true }
+      let!(:measurement) { described_class.new(logger: measurement_logger, base_log_data: base_log_data) }
+
+      before do
+        allow(measurement_logger).to receive(:info)
+      end
+
+      it 'measure execution with Gitlab::Utils::Measuring instance', :aggregate_failure do
+        expect(described_class).to receive(:new).with(logger: measurement_logger, base_log_data: base_log_data) { measurement }
+        expect(measurement).to receive(:with_measuring)
+
+        subject
+      end
+
+      it 'returns result from yielded block' do
+        is_expected.to eq(result_block)
+      end
+    end
+
+    context 'when measurement is disabled' do
+      let(:measurement_enabled) { false }
+
+      it 'does not measure service execution' do
+        expect(Gitlab::Utils::Measuring).not_to receive(:new)
+
+        subject
+      end
+
+      it 'returns result from yielded block' do
+        is_expected.to eq(result_block)
+      end
+    end
+  end
+
+  describe '#with_measuring' do
+    let(:logger) { double(:logger) }
+    let(:base_log_data) { {} }
+    let(:result) { "result" }
+
+    before do
+      allow(logger).to receive(:info)
+    end
+
+    let(:measurement) { described_class.new(logger: logger, base_log_data: base_log_data) }
+
+    subject do
+      measurement.with_measuring { result }
+    end
+
+    it 'measures and logs data', :aggregate_failure do
+      expect(measurement).to receive(:with_measure_time).and_call_original
+      expect(measurement).to receive(:with_count_queries).and_call_original
+      expect(measurement).to receive(:with_gc_stats).and_call_original
+
+      expect(logger).to receive(:info).with(including(:gc_stats, :time_to_finish, :number_of_sql_calls, :memory_usage, :label))
+
+      is_expected.to eq(result)
+    end
+
+    context 'with base_log_data provided' do
+      let(:base_log_data) { { test: "data" } }
+
+      it 'logs includes base data' do
+        expect(logger).to receive(:info).with(including(:test, :gc_stats, :time_to_finish, :number_of_sql_calls, :memory_usage, :label))
+
+        subject
+      end
+    end
+  end
+end

spec/support/shared_examples/services/gitlab_projects_import_service_shared_examples.rb

@@ -53,4 +53,56 @@ RSpec.shared_examples 'gitlab projects import validations' do
       end
     end
   end
+
+  context 'when measurable params are provided' do
+    let(:base_log_data) do
+      base_log_data = {
+        class: described_class.name,
+        current_user: namespace.owner.name,
+        project_full_path: "#{namespace.full_path}/#{path}"
+      }
+      base_log_data.merge!({ import_type: 'gitlab_project', file_path: import_params[:file].path }) if import_params[:file]
+
+      base_log_data
+    end
+
+    subject { described_class.new(namespace.owner, import_params) }
+
+    context 'when measurement is enabled' do
+      let(:logger) { double(:logger) }
+      let(:measurable_options) do
+        {
+          measurement_enabled: true,
+          measurement_logger: logger
+        }
+      end
+
+      before do
+        allow(logger).to receive(:info)
+      end
+
+      it 'measure service execution with Gitlab::Utils::Measuring' do
+        expect(Gitlab::Utils::Measuring).to receive(:execute_with).with(true, logger, base_log_data).and_call_original
+        expect_next_instance_of(Gitlab::Utils::Measuring) do |measuring|
+          expect(measuring).to receive(:with_measuring).and_call_original
+        end
+
+        subject.execute(measurable_options)
+      end
+    end
+    context 'when measurement is disabled' do
+      let(:measurable_options) do
+        {
+          measurement_enabled: false
+        }
+      end
+
+      it 'does not measure service execution' do
+        expect(Gitlab::Utils::Measuring).to receive(:execute_with).with(false, nil, base_log_data).and_call_original
+        expect(Gitlab::Utils::Measuring).not_to receive(:new)
+
+        subject.execute(measurable_options)
+      end
+    end
+  end
 end

spec/support/shared_examples/tasks/gitlab/import_export/measurable_shared_examples.rb

@@ -5,7 +5,7 @@ RSpec.shared_examples 'measurable' do
     let(:measurement_enabled) { true }
 
     it 'prints measurement results' do
-      expect { subject }.to output(including('Measuring enabled...', 'Number of sql calls:', 'GC stats:')).to_stdout
+      expect { subject }.to output(including('time_to_finish')).to_stdout
     end
   end
 
@@ -13,7 +13,7 @@ RSpec.shared_examples 'measurable' do
     let(:measurement_enabled) { false }
 
     it 'does not output measurement results' do
-      expect { subject }.not_to output(/Measuring enabled.../).to_stdout
+      expect { subject }.not_to output(/time_to_finish/).to_stdout
     end
   end
 
@@ -21,7 +21,7 @@ RSpec.shared_examples 'measurable' do
     let(:measurement_enabled) { nil }
 
     it 'does not output measurement results' do
-      expect { subject }.not_to output(/Measuring enabled.../).to_stdout
+      expect { subject }.not_to output(/time_to_finish/).to_stdout
     end
 
     it 'does not raise any exception' do