(FACT-2815) Added timing for cached facts (#2134)

lib/facter/framework/benchmarking/timer.rb

@@ -7,11 +7,13 @@ module Framework
     module Benchmarking
       class Timer
         class << self
-          def measure(fact_name)
+          def measure(fact_name, prefix_message = '')
             if Options[:timing]
               time = Benchmark.measure { yield }
 
-              puts "fact `#{fact_name}`, took: #{time.format('%r')} seconds"
+              log = "fact '#{fact_name}', took: #{time.format('%r')} seconds"
+              prefix_message = "#{prefix_message} " unless prefix_message.empty?
+              puts "#{prefix_message}#{log}"
             else
               yield
             end

lib/facter/framework/core/cache_manager.rb

@@ -74,7 +74,10 @@ def resolve_fact(searched_fact)
     end
 
     def read_fact(searched_fact, fact_group)
-      data = read_group_json(fact_group)
+      data = nil
+      Facter::Framework::Benchmarking::Timer.measure(searched_fact.name, 'cached') do
+        data = read_group_json(fact_group)
+      end
       return unless data
 
       @log.debug("loading cached values for #{searched_fact.name} facts")

spec/facter/cache_manager_spec.rb

@@ -32,6 +32,7 @@
     allow(LegacyFacter::Util::Config).to receive(:facts_cache_dir).and_return(cache_dir)
     allow(Facter::FactGroups).to receive(:new).and_return(fact_groups)
     allow(Facter::Options).to receive(:[]).with(:debug).and_return(false)
+    allow(Facter::Options).to receive(:[])
   end
 
   describe '#resolve_facts' do
@@ -135,6 +136,33 @@
         )
       end
     end
+
+    context 'with timer' do
+      before do
+        allow(File).to receive(:directory?).and_return(true)
+        allow(fact_groups).to receive(:get_fact_group).and_return(group_name)
+        allow(fact_groups).to receive(:get_group_ttls).and_return(nil)
+        allow(fact_groups).to receive(:get_fact).and_return(nil)
+        allow(File).to receive(:readable?)
+        allow(File).to receive(:mtime).with(cache_file_name).and_return(Time.now)
+        allow(Facter::Util::FileHelper).to receive(:safe_read).with(cache_file_name).and_return(cached_core_fact)
+        allow(Facter::Options).to receive(:[]).with(:cache).and_return(true)
+        allow(Facter::Framework::Benchmarking::Timer).to receive(:measure)
+      end
+
+      it 'returns cached external facts' do
+        allow(fact_groups).to receive(:get_fact).with('os').and_return(nil)
+        allow(fact_groups).to receive(:get_fact).with('my_custom_fact').and_return(nil)
+        allow(fact_groups).to receive(:get_fact).with('ext_file.txt').and_return(external_fact)
+        allow(Facter::Util::FileHelper).to receive(:safe_read).with(File.join(cache_dir, 'ext_file.txt'))
+                                                              .and_return(cached_external_fact)
+        allow(File).to receive(:mtime).with(File.join(cache_dir, 'ext_file.txt')).and_return(Time.now)
+
+        cache_manager.resolve_facts(searched_facts)
+
+        expect(Facter::Framework::Benchmarking::Timer).to have_received(:measure)
+      end
+    end
   end
 
   describe '#cache_facts' do

spec/facter/framework/benchmarking/timer_spec.rb

@@ -14,7 +14,13 @@
       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.to output("fact 'my_fact', took: (0.123) seconds\n").to_stdout
+      end
+
+      it 'adds prefix to printed message' do
+        expect do
+          Facter::Framework::Benchmarking::Timer.measure('my_fact', 'my_custom_prefix') {}
+        end.to output("my_custom_prefix fact 'my_fact', took: (0.123) seconds\n").to_stdout
       end
     end