E2E: Track fabrication time in e2e tests

qa/qa/resource/base.rb

@@ -77,17 +77,24 @@ module QA
         def log_fabrication(method, resource, parents, args)
           start = Time.now
 
-          yield.tap do
+          Support::FabricationTracker.start_fabrication
+          result = yield.tap do
+            fabrication_time = Time.now - start
+
+            Support::FabricationTracker.save_fabrication(:"#{method}_fabrication", fabrication_time * 1000)
             Runtime::Logger.debug do
               msg = ["==#{'=' * parents.size}>"]
               msg << "Built a #{name}"
               msg << "as a dependency of #{parents.last}" if parents.any?
               msg << "via #{method}"
-              msg << "in #{Time.now - start} seconds"
+              msg << "in #{fabrication_time} seconds"
 
               msg.join(' ')
             end
           end
+          Support::FabricationTracker.finish_fabrication
+
+          result
         end
 
         # Define custom attribute

qa/qa/specs/features/api/1_manage/bulk_import_group_spec.rb

@@ -43,6 +43,12 @@ module QA
         sandbox.add_member(user, Resource::Members::AccessLevel::MAINTAINER)
       end
 
+      after do
+        user.remove_via_api!
+      ensure
+        Runtime::Feature.disable(:top_level_group_creation_enabled) if staging?
+      end
+
       context 'with subgroups and labels' do
         let(:subgroup) do
           Resource::Group.fabricate_via_api! do |group|
@@ -155,12 +161,6 @@ module QA
           expect(imported_member.access_level).to eq(Resource::Members::AccessLevel::DEVELOPER)
         end
       end
-
-      after do
-        user.remove_via_api!
-      ensure
-        Runtime::Feature.disable(:top_level_group_creation_enabled) if staging?
-      end
     end
   end
 end

qa/qa/support/fabrication_tracker.rb

+# frozen_string_literal: true
+
+module QA
+  module Support
+    # Threadsafe fabrication time tracker
+    #
+    # Ongoing fabrication is added to callstack by start_fabrication and taken out by finish_fabrication
+    #
+    # Fabrication runtime is saved only for the first fabrication in the stack to properly represent the real time
+    # fabrications might take as top level fabrication runtime will always include nested fabrications runtime
+    #
+    class FabricationTracker
+      class << self
+        # Start fabrication and increment ongoing fabrication count
+        #
+        # @return [void]
+        def start_fabrication
+          Thread.current[:fabrications_ongoing] = 0 unless Thread.current.key?(:fabrications_ongoing)
+
+          Thread.current[:fabrications_ongoing] += 1
+        end
+
+        # Finish fabrication and decrement ongoing fabrication count
+        #
+        # @return [void]
+        def finish_fabrication
+          Thread.current[:fabrications_ongoing] -= 1
+        end
+
+        # Save fabrication time if it's first in fabrication stack
+        #
+        # @param [Symbol] type
+        # @param [Symbol] time
+        # @return [void]
+        def save_fabrication(type, time)
+          return unless Thread.current.key?(type)
+          return unless top_level_fabrication?
+
+          Thread.current[type] += time
+        end
+
+        private
+
+        # Check if current fabrication is the only one in the stack
+        #
+        # @return [Boolean]
+        def top_level_fabrication?
+          Thread.current[:fabrications_ongoing] == 1
+        end
+      end
+    end
+  end
+end

qa/qa/support/formatters/test_stats_formatter.rb

@@ -57,6 +57,8 @@ module QA
         # @return [Hash]
         def test_stats(example)
           file_path = example.metadata[:file_path].gsub('./qa/specs/features', '')
+          api_fabrication = ((example.metadata[:api_fabrication] || 0) * 1000).round
+          ui_fabrication = ((example.metadata[:browser_ui_fabrication] || 0) * 1000).round
 
           {
             name: 'test-stats',
@@ -76,6 +78,9 @@ module QA
             fields: {
               id: example.id,
               run_time: (example.execution_result.run_time * 1000).round,
+              api_fabrication: api_fabrication,
+              ui_fabrication: ui_fabrication,
+              total_fabrication: api_fabrication + ui_fabrication,
               retry_attempts: example.metadata[:retry_attempts] || 0,
               job_url: QA::Runtime::Env.ci_job_url,
               pipeline_url: env('CI_PIPELINE_URL'),
@@ -98,14 +103,18 @@ module QA
         #
         # @return [String]
         def job_name
-          @job_name ||= QA::Runtime::Env.ci_job_name.gsub(%r{ \d{1,2}/\d{1,2}}, '')
+          @job_name ||= QA::Runtime::Env.ci_job_name&.gsub(%r{ \d{1,2}/\d{1,2}}, '')
         end
 
         # Single common timestamp for all exported example metrics to keep data points consistently grouped
         #
         # @return [Time]
         def time
-          @time ||= DateTime.strptime(env('CI_PIPELINE_CREATED_AT')).to_time
+          @time ||= begin
+            return Time.now unless env('CI_PIPELINE_CREATED_AT')
+
+            DateTime.strptime(env('CI_PIPELINE_CREATED_AT')).to_time
+          end
         end
 
         # Is a merge request execution

qa/spec/spec_helper.rb

@@ -27,8 +27,12 @@ RSpec.configure do |config|
   config.add_formatter QA::Support::Formatters::QuarantineFormatter
   config.add_formatter QA::Support::Formatters::TestStatsFormatter if QA::Runtime::Env.export_metrics?
 
-  config.before do |example|
+  config.prepend_before do |example|
     QA::Runtime::Logger.debug("\nStarting test: #{example.full_description}\n")
+
+    # Reset fabrication counters tracked in resource base
+    Thread.current[:api_fabrication] = 0
+    Thread.current[:browser_ui_fabrication] = 0
   end
 
   config.after do
@@ -36,6 +40,12 @@ RSpec.configure do |config|
     QA::Git::Repository.new.delete_netrc
   end
 
+  # Add fabrication time to spec metadata
+  config.append_after do |example|
+    example.metadata[:api_fabrication] = Thread.current[:api_fabrication]
+    example.metadata[:browser_ui_fabrication] = Thread.current[:browser_ui_fabrication]
+  end
+
   config.after(:context) do
     if !QA::Runtime::Browser.blank_page? && QA::Page::Main::Menu.perform(&:signed_in?)
       QA::Page::Main::Menu.perform(&:sign_out)

qa/spec/support/formatters/test_stats_formatter_spec.rb

@@ -20,6 +20,8 @@ describe QA::Support::Formatters::TestStatsFormatter do
   let(:influx_write_api) { instance_double('InfluxDB2::WriteApi', write: nil) }
   let(:stage) { '1_manage' }
   let(:file_path) { "./qa/specs/features/#{stage}/subfolder/some_spec.rb" }
+  let(:ui_fabrication) { 0 }
+  let(:api_fabrication) { 0 }
 
   let(:influx_client_args) do
     {
@@ -48,6 +50,9 @@ describe QA::Support::Formatters::TestStatsFormatter do
       fields: {
         id: './spec/support/formatters/test_stats_formatter_spec.rb[1:1]',
         run_time: 0,
+        api_fabrication: api_fabrication * 1000,
+        ui_fabrication: ui_fabrication * 1000,
+        total_fabrication: (api_fabrication + ui_fabrication) * 1000,
         retry_attempts: 0,
         job_url: ci_job_url,
         pipeline_url: ci_pipeline_url,
@@ -69,6 +74,11 @@ describe QA::Support::Formatters::TestStatsFormatter do
     RSpec::Core::Sandbox.sandboxed do |config|
       config.formatter = QA::Support::Formatters::TestStatsFormatter
 
+      config.append_after do |example|
+        example.metadata[:api_fabrication] = Thread.current[:api_fabrication]
+        example.metadata[:browser_ui_fabrication] = Thread.current[:browser_ui_fabrication]
+      end
+
       config.before(:context) { RSpec.current_example = nil }
 
       example.run
@@ -171,5 +181,21 @@ describe QA::Support::Formatters::TestStatsFormatter do
         expect(influx_write_api).to have_received(:write).with(data: [data])
       end
     end
+
+    context 'with fabrication runtimes' do
+      let(:ui_fabrication) { 10 }
+      let(:api_fabrication) { 4 }
+
+      before do
+        Thread.current[:api_fabrication] = api_fabrication
+        Thread.current[:browser_ui_fabrication] = ui_fabrication
+      end
+
+      it 'exports data to influxdb with fabrication times' do
+        run_spec
+
+        expect(influx_write_api).to have_received(:write).with(data: [data])
+      end
+    end
   end
 end