Merge pull request #2061 from IrimieBogdan/FACT-1380

(FACT-1380) Restore --timing option to native facter

lib/facter/custom_facts/util/directory_loader.rb

@@ -84,7 +84,7 @@ def load_searched_facts(collection, searched_facts, weight)
           parser = LegacyFacter::Util::Parser.parser_for(fact.file)
           next if parser.nil?
 
-          data = parser.results
+          data = resolve_fact(fact, parser)
 
           if data == false
             LegacyFacter.warn "Could not interpret fact file #{fact.file}"
@@ -99,6 +99,14 @@ def load_searched_facts(collection, searched_facts, weight)
         end
       end
 
+      def resolve_fact(fact, parser)
+        data = nil
+        fact_name = File.basename(fact.file)
+        Facter::Framework::Benchmarking::Timer.measure(fact_name) { data = parser.results }
+
+        data
+      end
+
       def entries
         dirs = @directories.select { |directory| File.directory?(directory) }.map do |directory|
           Dir.entries(directory).map { |directory_entry| File.join(directory, directory_entry) }

lib/facter/custom_facts/util/fact.rb

@@ -118,7 +118,10 @@ def value
 
         searching do
           suitable_resolutions = sort_by_weight(find_suitable_resolutions(@resolves))
-          @value = find_first_real_value(suitable_resolutions)
+
+          Facter::Framework::Benchmarking::Timer.measure(@name) do
+            @value = find_first_real_value(suitable_resolutions)
+          end
 
           announce_when_no_suitable_resolution(suitable_resolutions)
           announce_when_no_value_found(@value)

lib/facter/framework/benchmarking/timer.rb

@@ -0,0 +1,23 @@
+# frozen_string_literal: true
+
+require 'benchmark'
+
+module Facter
+  module Framework
+    module Benchmarking
+      class Timer
+        class << self
+          def measure(fact_name)
+            if Options[:timing]
+              time = Benchmark.measure { yield }
+
+              puts "fact `#{fact_name}`, took: #{time.format('%r')} seconds"
+            else
+              yield
+            end
+          end
+        end
+      end
+    end
+  end
+end

lib/facter/framework/cli/cli.rb

@@ -108,6 +108,11 @@ class Cli < Thor
                  aliases: '-p',
                  desc: 'Load the Puppet libraries, thus allowing Facter to load Puppet-specific facts.'
 
+    class_option :timing,
+                 type: :boolean,
+                 aliases: '-t',
+                 desc: 'Show how much time it took to resolve each fact'
+
     desc '--man', 'Manual', hide: true
     map ['--man'] => :man
     def man(*args)

lib/facter/framework/core/fact/internal/internal_fact_manager.rb

@@ -36,7 +36,8 @@ def resolve(searched_facts)
         .each do |searched_fact|
         begin
           fact = CoreFact.new(searched_fact)
-          fact_value = fact.create
+          fact_value = nil
+          Facter::Framework::Benchmarking::Timer.measure(searched_fact.name) { fact_value = fact.create }
           resolved_facts << fact_value unless fact_value.nil?
         rescue StandardError => e
           @@log.log_exception(e)

lib/facter/framework/core/file_loader.rb

@@ -39,6 +39,8 @@ def load_dir(*dirs)
 load_dir(['facts_utils'])
 load_dir(%w[framework core])
 load_dir(['models'])
+load_dir(%w[framework benchmarking])
+
 load_dir(%w[framework core fact_loaders])
 load_dir(%w[framework core fact internal])
 load_dir(%w[framework core fact external])

lib/facter/framework/core/options/option_store.rb

@@ -23,6 +23,7 @@ class OptionStore
     @block_list = {}
     @fact_groups = {}
     @color = false
+    @timing = false
 
     class << self
       attr_reader :debug, :verbose, :log_level, :show_legacy, :ruby,
@@ -31,7 +32,7 @@ class << self
       attr_accessor :config, :user_query, :strict, :json, :haml, :external_facts,
                     :cache, :yaml, :puppet, :ttls, :block, :cli, :config_file_custom_dir,
                     :config_file_external_dir, :default_external_dir, :fact_groups,
-                    :block_list, :color, :trace
+                    :block_list, :color, :trace, :timing
 
       attr_writer :external_dir
 
@@ -159,6 +160,7 @@ def reset_config
         @blocked_facts = []
         @fact_groups = {}
         @block_list = {}
+        @timing = false
       end
 
       def fallback_external_dir

spec/facter/framework/benchmarking/timer_spec.rb

@@ -0,0 +1,33 @@
+# frozen_string_literal: true
+
+describe Facter::Framework::Benchmarking::Timer do
+  let(:tms_mock) { instance_spy(Benchmark::Tms) }
+
+  describe '#measure' do
+    context 'when timing option is true' do
+      before do
+        allow(Facter::Options).to receive(:[]).with(:timing).and_return(true)
+        allow(tms_mock).to receive(:format).with('%r').and_return('(0.123)')
+        allow(Benchmark).to receive(:measure).and_return(tms_mock)
+      end
+
+      it 'prints fact name and time it took to resolve it' do
+        expect do
+          Facter::Framework::Benchmarking::Timer.measure('my_fact') {}
+        end.to output("fact `my_fact`, took: (0.123) seconds\n").to_stdout
+      end
+    end
+
+    context 'when timing option is false' do
+      before do
+        allow(Facter::Options).to receive(:[]).with(:timing).and_return(false)
+      end
+
+      it 'does not print any message' do
+        expect do
+          Facter::Framework::Benchmarking::Timer.measure('my_fact') {}
+        end.not_to output.to_stdout
+      end
+    end
+  end
+end

spec/framework/core/options/option_store_spec.rb

@@ -35,7 +35,8 @@
         config: nil,
         cache: true,
         color: false,
-        trace: false
+        trace: false,
+        timing: false
       )
     end
   end