Add latest changes from gitlab-org/gitlab@master

7 files changed, 164 insertions, 27 deletions

diff --git a/lib/gitlab/ci/pipeline/chain/base.rb b/lib/gitlab/ci/pipeline/chain/base.rb
index 9b494f3a7ec..28567437719 100644
--- a/lib/gitlab/ci/pipeline/chain/base.rb
+++ b/lib/gitlab/ci/pipeline/chain/base.rb
@@ -7,7 +7,7 @@ module Gitlab
         class Base
           attr_reader :pipeline, :command, :config
 
-          delegate :project, :current_user, :parent_pipeline, to: :command
+          delegate :project, :current_user, :parent_pipeline, :logger, to: :command
 
           def initialize(pipeline, command)
             @pipeline = pipeline
diff --git a/lib/gitlab/ci/pipeline/chain/command.rb b/lib/gitlab/ci/pipeline/chain/command.rb
index beb8801096b..c466b8b36d0 100644
--- a/lib/gitlab/ci/pipeline/chain/command.rb
+++ b/lib/gitlab/ci/pipeline/chain/command.rb
@@ -11,7 +11,7 @@ module Gitlab
           :trigger_request, :schedule, :merge_request, :external_pull_request,
           :ignore_skip_ci, :save_incompleted,
           :seeds_block, :variables_attributes, :push_options,
-          :chat_data, :allow_mirror_update, :bridge, :content, :dry_run,
+          :chat_data, :allow_mirror_update, :bridge, :content, :dry_run, :logger,
           # These attributes are set by Chains during processing:
           :config_content, :yaml_processor_result, :workflow_rules_result, :pipeline_seed
         ) do
@@ -88,7 +88,14 @@ module Gitlab
             @metrics ||= ::Gitlab::Ci::Pipeline::Metrics
           end
 
+          def logger
+            self[:logger] ||= ::Gitlab::Ci::Pipeline::Logger.new(project: project)
+          end
+
           def observe_step_duration(step_class, duration)
+            step = step_class.name.underscore.parameterize(separator: '_')
+            logger.observe("pipeline_step_#{step}_duration_s", duration)
+
             if Feature.enabled?(:ci_pipeline_creation_step_duration_tracking, type: :ops, default_enabled: :yaml)
               metrics.pipeline_creation_step_duration_histogram
                 .observe({ step: step_class.name }, duration.seconds)
@@ -96,11 +103,15 @@ module Gitlab
           end
 
           def observe_creation_duration(duration)
+            logger.observe(:pipeline_creation_duration_s, duration)
+
             metrics.pipeline_creation_duration_histogram
               .observe({}, duration.seconds)
           end
 
           def observe_pipeline_size(pipeline)
+            logger.observe(:pipeline_size_count, pipeline.total_size)
+
             metrics.pipeline_size_histogram
               .observe({ source: pipeline.source.to_s }, pipeline.total_size)
           end
diff --git a/lib/gitlab/ci/pipeline/chain/config/process.rb b/lib/gitlab/ci/pipeline/chain/config/process.rb
index f3c937ddd28..64d1b001e3c 100644
--- a/lib/gitlab/ci/pipeline/chain/config/process.rb
+++ b/lib/gitlab/ci/pipeline/chain/config/process.rb
@@ -11,16 +11,21 @@ module Gitlab
             def perform!
               raise ArgumentError, 'missing config content' unless @command.config_content
 
-              result = ::Gitlab::Ci::YamlProcessor.new(
-                @command.config_content, {
-                  project: project,
-                  pipeline: @pipeline,
-                  sha: @pipeline.sha,
-                  source: @pipeline.source,
-                  user: current_user,
-                  parent_pipeline: parent_pipeline
-                }
-              ).execute
+              result = logger.instrument(:pipeline_config_process) do
+                processor = ::Gitlab::Ci::YamlProcessor.new(
+                  @command.config_content, {
+                    project: project,
+                    pipeline: @pipeline,
+                    sha: @pipeline.sha,
+                    source: @pipeline.source,
+                    user: current_user,
+                    parent_pipeline: parent_pipeline,
+                    logger: logger
+                  }
+                )
+
+                processor.execute
+              end
 
               add_warnings_to_pipeline(result.warnings)
 
diff --git a/lib/gitlab/ci/pipeline/chain/create.rb b/lib/gitlab/ci/pipeline/chain/create.rb
index 81ef3bb074d..9dba557eef6 100644
--- a/lib/gitlab/ci/pipeline/chain/create.rb
+++ b/lib/gitlab/ci/pipeline/chain/create.rb
@@ -8,8 +8,10 @@ module Gitlab
           include Chain::Helpers
 
           def perform!
-            BulkInsertableAssociations.with_bulk_insert do
-              pipeline.save!
+            logger.instrument(:pipeline_save) do
+              BulkInsertableAssociations.with_bulk_insert do
+                pipeline.save!
+              end
             end
           rescue ActiveRecord::RecordInvalid => e
             error("Failed to persist the pipeline: #{e}")
diff --git a/lib/gitlab/ci/pipeline/chain/seed.rb b/lib/gitlab/ci/pipeline/chain/seed.rb
index ef7447fa83d..356eeb76908 100644
--- a/lib/gitlab/ci/pipeline/chain/seed.rb
+++ b/lib/gitlab/ci/pipeline/chain/seed.rb
@@ -13,8 +13,10 @@ module Gitlab
             raise ArgumentError, 'missing workflow rules result' unless @command.workflow_rules_result
 
             # Allocate next IID. This operation must be outside of transactions of pipeline creations.
-            pipeline.ensure_project_iid!
-            pipeline.ensure_ci_ref!
+            logger.instrument(:pipeline_allocate_seed_attributes) do
+              pipeline.ensure_project_iid!
+              pipeline.ensure_ci_ref!
+            end
 
             # Protect the pipeline. This is assigned in Populate instead of
             # Build to prevent erroring out on ambiguous refs.
@@ -23,8 +25,12 @@ module Gitlab
             ##
             # Gather all runtime build/stage errors
             #
-            if pipeline_seed.errors
-              return error(pipeline_seed.errors.join("\n"), config_error: true)
+            seed_errors = logger.instrument(:pipeline_seed_evaluation) do
+              pipeline_seed.errors
+            end
+
+            if seed_errors
+              return error(seed_errors.join("\n"), config_error: true)
             end
 
             @command.pipeline_seed = pipeline_seed
@@ -38,8 +44,11 @@ module Gitlab
 
           def pipeline_seed
             strong_memoize(:pipeline_seed) do
-              stages_attributes = @command.yaml_processor_result.stages_attributes
-              Gitlab::Ci::Pipeline::Seed::Pipeline.new(context, stages_attributes)
+              logger.instrument(:pipeline_seed_initialization) do
+                stages_attributes = @command.yaml_processor_result.stages_attributes
+
+                Gitlab::Ci::Pipeline::Seed::Pipeline.new(context, stages_attributes)
+              end
             end
           end
 
@@ -48,9 +57,11 @@ module Gitlab
           end
 
           def root_variables
-            ::Gitlab::Ci::Variables::Helpers.merge_variables(
-              @command.yaml_processor_result.root_variables, @command.workflow_rules_result.variables
-            )
+            logger.instrument(:pipeline_seed_merge_variables) do
+              ::Gitlab::Ci::Variables::Helpers.merge_variables(
+                @command.yaml_processor_result.root_variables, @command.workflow_rules_result.variables
+              )
+            end
           end
         end
       end
diff --git a/lib/gitlab/ci/pipeline/chain/sequence.rb b/lib/gitlab/ci/pipeline/chain/sequence.rb
index 845eb6c7a42..de147914850 100644
--- a/lib/gitlab/ci/pipeline/chain/sequence.rb
+++ b/lib/gitlab/ci/pipeline/chain/sequence.rb
@@ -9,30 +9,36 @@ module Gitlab
             @pipeline = pipeline
             @command = command
             @sequence = sequence
-            @start = Time.now
+            @start = current_monotonic_time
           end
 
           def build!
             @sequence.each do |step_class|
-              step_start = ::Gitlab::Metrics::System.monotonic_time
+              step_start = current_monotonic_time
               step = step_class.new(@pipeline, @command)
 
               step.perform!
 
               @command.observe_step_duration(
                 step_class,
-                ::Gitlab::Metrics::System.monotonic_time - step_start
+                current_monotonic_time - step_start
               )
 
               break if step.break?
             end
 
-            @command.observe_creation_duration(Time.now - @start)
+            @command.observe_creation_duration(current_monotonic_time - @start)
             @command.observe_pipeline_size(@pipeline)
             @command.observe_jobs_count_in_alive_pipelines
 
             @pipeline
           end
+
+          private
+
+          def current_monotonic_time
+            ::Gitlab::Metrics::System.monotonic_time
+          end
         end
       end
     end
diff --git a/lib/gitlab/ci/pipeline/logger.rb b/lib/gitlab/ci/pipeline/logger.rb
new file mode 100644
index 00000000000..a3e7dda9be5
--- /dev/null
+++ b/lib/gitlab/ci/pipeline/logger.rb
@@ -0,0 +1,102 @@
+# frozen_string_literal: true
+
+module Gitlab
+  module Ci
+    module Pipeline
+      class Logger
+        include ::Gitlab::Utils::StrongMemoize
+
+        def self.current_monotonic_time
+          ::Gitlab::Metrics::System.monotonic_time
+        end
+
+        def initialize(project:, destination: Gitlab::AppJsonLogger)
+          @started_at = current_monotonic_time
+          @project = project
+          @destination = destination
+          @log_conditions = []
+
+          yield(self) if block_given?
+        end
+
+        def log_when(&block)
+          log_conditions.push(block)
+        end
+
+        def instrument(operation)
+          return yield unless enabled?
+
+          raise ArgumentError, 'block not given' unless block_given?
+
+          op_started_at = current_monotonic_time
+
+          result = yield
+
+          observe("#{operation}_duration_s", current_monotonic_time - op_started_at)
+
+          result
+        end
+
+        def observe(operation, value)
+          return unless enabled?
+
+          observations[operation.to_s].push(value)
+        end
+
+        def commit(pipeline:, caller:)
+          return unless log?
+
+          attributes = {
+            caller: caller,
+            project_id: project.id,
+            pipeline_id: pipeline.id,
+            persisted: pipeline.persisted?,
+            source: pipeline.source,
+            duration_s: age
+          }.stringify_keys.merge(observations_hash)
+
+          destination.info(attributes)
+        end
+
+        def observations_hash
+          observations.transform_values do |values|
+            next if values.empty?
+
+            {
+              'count' => values.size,
+              'min' => values.min,
+              'max' => values.max,
+              'avg' => values.sum / values.size
+            }
+          end.compact
+        end
+
+        private
+
+        attr_reader :project, :destination, :started_at, :log_conditions
+        delegate :current_monotonic_time, to: :class
+
+        def age
+          current_monotonic_time - started_at
+        end
+
+        def log?
+          return false unless enabled?
+          return true if log_conditions.empty?
+
+          log_conditions.any? { |cond| cond.call(observations) }
+        end
+
+        def enabled?
+          strong_memoize(:enabled) do
+            ::Feature.enabled?(:ci_pipeline_creation_logger, project, type: :ops, default_enabled: :yaml)
+          end
+        end
+
+        def observations
+          @observations ||= Hash.new { |hash, key| hash[key] = [] }
+        end
+      end
+    end
+  end
+end