Merge branch '332891-improve-pipeline-creation-instrumentation' into 'master'

Observe duration of each pipeline creation step

See merge request gitlab-org/gitlab!68485

config/feature_flags/development/ci_pipeline_creation_step_duration_tracking.yml

+---
+name: ci_pipeline_creation_step_duration_tracking
+introduced_by_url: https://gitlab.com/gitlab-org/gitlab/-/merge_requests/68485
+rollout_issue_url: https://gitlab.com/gitlab-org/gitlab/-/issues/339486
+milestone: '14.2'
+type: development
+group: group::pipeline execution
+default_enabled: true

lib/gitlab/ci/pipeline/chain/command.rb

@@ -87,6 +87,13 @@ module Gitlab
             @metrics ||= ::Gitlab::Ci::Pipeline::Metrics
           end
 
+          def observe_step_duration(step_class, duration)
+            if Feature.enabled?(:ci_pipeline_creation_step_duration_tracking, default_enabled: :yaml)
+              metrics.pipeline_creation_step_duration_histogram
+                .observe({ step: step_class.name }, duration.seconds)
+            end
+          end
+
           def observe_creation_duration(duration)
             metrics.pipeline_creation_duration_histogram
               .observe({}, duration.seconds)

lib/gitlab/ci/pipeline/chain/sequence.rb

@@ -14,9 +14,16 @@ module Gitlab
 
           def build!
             @sequence.each do |step_class|
+              step_start = ::Gitlab::Metrics::System.monotonic_time
               step = step_class.new(@pipeline, @command)
 
               step.perform!
+
+              @command.observe_step_duration(
+                step_class,
+                ::Gitlab::Metrics::System.monotonic_time - step_start
+              )
+
               break if step.break?
             end
 

lib/gitlab/ci/pipeline/metrics.rb

@@ -4,6 +4,8 @@ module Gitlab
   module Ci
     module Pipeline
       class Metrics
+        extend Gitlab::Utils::StrongMemoize
+
         def self.pipeline_creation_duration_histogram
           name = :gitlab_ci_pipeline_creation_duration_seconds
           comment = 'Pipeline creation duration'
@@ -13,6 +15,17 @@ module Gitlab
           ::Gitlab::Metrics.histogram(name, comment, labels, buckets)
         end
 
+        def self.pipeline_creation_step_duration_histogram
+          strong_memoize(:pipeline_creation_step_histogram) do
+            name = :gitlab_ci_pipeline_creation_step_duration_seconds
+            comment = 'Duration of each pipeline creation step'
+            labels = { step: nil }
+            buckets = [0.01, 0.05, 0.1, 0.5, 1.0, 2.0, 5.0, 10.0, 15.0, 20.0, 50.0, 240.0]
+
+            ::Gitlab::Metrics.histogram(name, comment, labels, buckets)
+          end
+        end
+
         def self.pipeline_security_orchestration_policy_processing_duration_histogram
           name = :gitlab_ci_pipeline_security_orchestration_policy_processing_duration_seconds
           comment = 'Pipeline security orchestration policy processing duration'

spec/lib/gitlab/ci/pipeline/chain/command_spec.rb

@@ -341,4 +341,40 @@ RSpec.describe Gitlab::Ci::Pipeline::Chain::Command do
       end
     end
   end
+
+  describe '#observe_step_duration' do
+    context 'when ci_pipeline_creation_step_duration_tracking is enabled' do
+      it 'adds the duration to the step duration histogram' do
+        histogram = double(:histogram)
+        duration = 1.hour
+
+        expect(::Gitlab::Ci::Pipeline::Metrics).to receive(:pipeline_creation_step_duration_histogram)
+          .and_return(histogram)
+        expect(histogram).to receive(:observe)
+          .with({ step: 'Gitlab::Ci::Pipeline::Chain::Build' }, duration.seconds)
+
+        described_class.new.observe_step_duration(
+          Gitlab::Ci::Pipeline::Chain::Build,
+          duration
+        )
+      end
+    end
+
+    context 'when ci_pipeline_creation_step_duration_tracking is disabled' do
+      before do
+        stub_feature_flags(ci_pipeline_creation_step_duration_tracking: false)
+      end
+
+      it 'does nothing' do
+        duration = 1.hour
+
+        expect(::Gitlab::Ci::Pipeline::Metrics).not_to receive(:pipeline_creation_step_duration_histogram)
+
+        described_class.new.observe_step_duration(
+          Gitlab::Ci::Pipeline::Chain::Build,
+          duration
+        )
+      end
+    end
+  end
 end

spec/lib/gitlab/ci/pipeline/chain/sequence_spec.rb

@@ -8,8 +8,8 @@ RSpec.describe Gitlab::Ci::Pipeline::Chain::Sequence do
 
   let(:pipeline) { build_stubbed(:ci_pipeline) }
   let(:command) { Gitlab::Ci::Pipeline::Chain::Command.new(project: project) }
-  let(:first_step) { spy('first step') }
-  let(:second_step) { spy('second step') }
+  let(:first_step) { spy('first step', name: 'FirstStep') }
+  let(:second_step) { spy('second step', name: 'SecondStep') }
   let(:sequence) { [first_step, second_step] }
   let(:histogram) { spy('prometheus metric') }
 
@@ -61,6 +61,17 @@ RSpec.describe Gitlab::Ci::Pipeline::Chain::Sequence do
       expect(histogram).to have_received(:observe)
     end
 
+    it 'adds step sequence duration to duration histogram' do
+      expect(command.metrics)
+        .to receive(:pipeline_creation_step_duration_histogram)
+        .twice
+        .and_return(histogram)
+      expect(histogram).to receive(:observe).with({ step: 'FirstStep' }, any_args).ordered
+      expect(histogram).to receive(:observe).with({ step: 'SecondStep' }, any_args).ordered
+
+      subject.build!
+    end
+
     it 'records pipeline size by pipeline source in a histogram' do
       allow(command.metrics)
         .to receive(:pipeline_size_histogram)

spec/lib/gitlab/ci/pipeline/metrics_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+RSpec.describe ::Gitlab::Ci::Pipeline::Metrics do
+  describe '.pipeline_creation_step_duration_histogram' do
+    it 'adds the step to the step duration histogram' do
+      described_class.clear_memoization(:pipeline_creation_step_histogram)
+
+      expect(::Gitlab::Metrics).to receive(:histogram)
+        .with(
+          :gitlab_ci_pipeline_creation_step_duration_seconds,
+          'Duration of each pipeline creation step',
+          { step: nil },
+          [0.01, 0.05, 0.1, 0.5, 1.0, 2.0, 5.0, 10.0, 15.0, 20.0, 50.0, 240.0]
+        )
+
+      described_class.pipeline_creation_step_duration_histogram
+    end
+  end
+end