From 538d732824b28158def6e0f7960d52a55f65ed58 Mon Sep 17 00:00:00 2001 From: BogdanIrimie Date: Wed, 1 Jul 2020 15:45:24 +0300 Subject: [PATCH 1/5] (FACT-1380) Add Timer class. --- lib/framework/benchmarking/Timer.rb | 28 ++++++++++++++++++++++++++++ 1 file changed, 28 insertions(+) create mode 100644 lib/framework/benchmarking/Timer.rb diff --git a/lib/framework/benchmarking/Timer.rb b/lib/framework/benchmarking/Timer.rb new file mode 100644 index 0000000000..ce3075b069 --- /dev/null +++ b/lib/framework/benchmarking/Timer.rb @@ -0,0 +1,28 @@ +# frozen_string_literal: true +require 'benchmark' + +module Facter + module Framework + class Timer + class << self + def measure + time = Benchmark.measure { yield } + + puts "fact name:, took: #{time.format('%t')}" + + time + end + + def measure_for_fact(fact_name) + time = Benchmark.measure { yield } + + puts "fact name #{fact_name}, took: #{time.format('%t')}" + + time + end + end + end + end +end + + From 78b485e8c720d7504cca70d2045360ecc4681c28 Mon Sep 17 00:00:00 2001 From: BogdanIrimie Date: Thu, 2 Jul 2020 10:19:12 +0300 Subject: [PATCH 2/5] (FACT-1380) Add benchmarking in internal fact manager. --- lib/framework/benchmarking/Timer.rb | 24 ++++++++++--------- .../fact/internal/internal_fact_manager.rb | 4 +++- lib/framework/core/file_loader.rb | 1 + 3 files changed, 17 insertions(+), 12 deletions(-) diff --git a/lib/framework/benchmarking/Timer.rb b/lib/framework/benchmarking/Timer.rb index ce3075b069..2650dcdf71 100644 --- a/lib/framework/benchmarking/Timer.rb +++ b/lib/framework/benchmarking/Timer.rb @@ -3,22 +3,24 @@ module Facter module Framework - class Timer - class << self - def measure - time = Benchmark.measure { yield } + module Benchmarking + class Timer + class << self + def measure + time = Benchmark.measure { yield } - puts "fact name:, took: #{time.format('%t')}" + puts "fact name:, took: #{time.format('%t')}" - time - end + time + end - def measure_for_fact(fact_name) - time = Benchmark.measure { yield } + def measure_for_fact(fact_name) + time = Benchmark.measure { yield } - puts "fact name #{fact_name}, took: #{time.format('%t')}" + puts "fact name #{fact_name}, took: #{time.format('%t')}" - time + time + end end end end diff --git a/lib/framework/core/fact/internal/internal_fact_manager.rb b/lib/framework/core/fact/internal/internal_fact_manager.rb index cf249d7990..6c0354b668 100644 --- a/lib/framework/core/fact/internal/internal_fact_manager.rb +++ b/lib/framework/core/fact/internal/internal_fact_manager.rb @@ -38,7 +38,9 @@ def start_threads(searched_facts) threads << Thread.new do begin fact = CoreFact.new(searched_fact) - fact.create + fact_value = nil + Facter::Framework::Benchmarking::Timer.measure_for_fact(searched_fact.name) { fact_value = fact.create } + fact_value rescue StandardError => e @@log.error(e.backtrace.join("\n")) nil diff --git a/lib/framework/core/file_loader.rb b/lib/framework/core/file_loader.rb index 7eda6e3b30..94dc51120a 100644 --- a/lib/framework/core/file_loader.rb +++ b/lib/framework/core/file_loader.rb @@ -41,6 +41,7 @@ def load_lib_dirs(*dirs) load_lib_dirs('facts_utils') load_lib_dirs('framework', 'core') load_lib_dirs('models') +load_lib_dirs('framework', 'benchmarking') load_lib_dirs('framework', 'core', 'fact_loaders') load_lib_dirs('framework', 'core', 'fact', 'internal') load_lib_dirs('framework', 'core', 'fact', 'external') From f3353e8d8e1d0602be7fdb2ebcf01e91f4357e7f Mon Sep 17 00:00:00 2001 From: BogdanIrimie Date: Wed, 2 Sep 2020 11:52:59 +0300 Subject: [PATCH 3/5] (FACT-1380) Add --timing option. Benchmark custom and external facts. Report real time in seconds. --- .../custom_facts/util/directory_loader.rb | 4 +- lib/facter/custom_facts/util/fact.rb | 5 +- lib/facter/framework/cli/cli.rb | 5 ++ .../framework/core/benchmarking/timer.rb | 24 ++++++++ .../fact/internal/internal_fact_manager.rb | 2 +- lib/facter/framework/core/file_loader.rb | 2 + .../framework/core/options/option_store.rb | 4 +- lib/framework/benchmarking/Timer.rb | 30 ---------- lib/framework/core/file_loader.rb | 59 ------------------- 9 files changed, 42 insertions(+), 93 deletions(-) create mode 100644 lib/facter/framework/core/benchmarking/timer.rb delete mode 100644 lib/framework/benchmarking/Timer.rb delete mode 100644 lib/framework/core/file_loader.rb diff --git a/lib/facter/custom_facts/util/directory_loader.rb b/lib/facter/custom_facts/util/directory_loader.rb index db2fe511ba..9a0e39aea8 100644 --- a/lib/facter/custom_facts/util/directory_loader.rb +++ b/lib/facter/custom_facts/util/directory_loader.rb @@ -84,7 +84,9 @@ def load_searched_facts(collection, searched_facts, weight) parser = LegacyFacter::Util::Parser.parser_for(fact.file) next if parser.nil? - data = parser.results + data = nil + fact_name = File.basename(fact.file) + Facter::Framework::Benchmarking::Timer.measure(fact_name) { data = parser.results } if data == false LegacyFacter.warn "Could not interpret fact file #{fact.file}" diff --git a/lib/facter/custom_facts/util/fact.rb b/lib/facter/custom_facts/util/fact.rb index 3689ef1378..3c1ac171d5 100644 --- a/lib/facter/custom_facts/util/fact.rb +++ b/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) diff --git a/lib/facter/framework/cli/cli.rb b/lib/facter/framework/cli/cli.rb index b4b216d415..926a83da11 100755 --- a/lib/facter/framework/cli/cli.rb +++ b/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) diff --git a/lib/facter/framework/core/benchmarking/timer.rb b/lib/facter/framework/core/benchmarking/timer.rb new file mode 100644 index 0000000000..ef00039354 --- /dev/null +++ b/lib/facter/framework/core/benchmarking/timer.rb @@ -0,0 +1,24 @@ +# 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 + + diff --git a/lib/facter/framework/core/fact/internal/internal_fact_manager.rb b/lib/facter/framework/core/fact/internal/internal_fact_manager.rb index 1588491b8c..25afd2e066 100644 --- a/lib/facter/framework/core/fact/internal/internal_fact_manager.rb +++ b/lib/facter/framework/core/fact/internal/internal_fact_manager.rb @@ -37,7 +37,7 @@ def resolve(searched_facts) begin fact = CoreFact.new(searched_fact) fact_value = nil - Facter::Framework::Benchmarking::Timer.measure_for_fact(searched_fact.name) { fact_value = fact.create } + 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) diff --git a/lib/facter/framework/core/file_loader.rb b/lib/facter/framework/core/file_loader.rb index c915ebdd6f..bea70b5b75 100644 --- a/lib/facter/framework/core/file_loader.rb +++ b/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 core benchmarking]) + load_dir(%w[framework core fact_loaders]) load_dir(%w[framework core fact internal]) load_dir(%w[framework core fact external]) diff --git a/lib/facter/framework/core/options/option_store.rb b/lib/facter/framework/core/options/option_store.rb index 7cc586ca7e..734f436e64 100644 --- a/lib/facter/framework/core/options/option_store.rb +++ b/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 diff --git a/lib/framework/benchmarking/Timer.rb b/lib/framework/benchmarking/Timer.rb deleted file mode 100644 index 2650dcdf71..0000000000 --- a/lib/framework/benchmarking/Timer.rb +++ /dev/null @@ -1,30 +0,0 @@ -# frozen_string_literal: true -require 'benchmark' - -module Facter - module Framework - module Benchmarking - class Timer - class << self - def measure - time = Benchmark.measure { yield } - - puts "fact name:, took: #{time.format('%t')}" - - time - end - - def measure_for_fact(fact_name) - time = Benchmark.measure { yield } - - puts "fact name #{fact_name}, took: #{time.format('%t')}" - - time - end - end - end - end - end -end - - diff --git a/lib/framework/core/file_loader.rb b/lib/framework/core/file_loader.rb deleted file mode 100644 index 94dc51120a..0000000000 --- a/lib/framework/core/file_loader.rb +++ /dev/null @@ -1,59 +0,0 @@ -# frozen_string_literal: true - -require 'open3' -require 'json' -require 'yaml' -require 'hocon' -require 'hocon/config_value_factory' -require 'singleton' -require 'logger' - -def load_dir(*dirs) - folder_path = File.join(ROOT_DIR, dirs) - return unless Dir.exist?(folder_path.tr('*', '')) - - files_to_require = Dir.glob(File.join(folder_path, '*.rb')).reject { |file| file =~ %r{/ffi/} } - files_to_require.each(&method(:require)) -end - -def load_lib_dirs(*dirs) - load_dir(['lib', dirs]) -end - -load_lib_dirs('framework', 'core', 'options') -require "#{ROOT_DIR}/lib/framework/core/options" -require "#{ROOT_DIR}/lib/framework/logging/logger_helper" -require "#{ROOT_DIR}/lib/framework/logging/logger" - -require "#{ROOT_DIR}/lib/util/file_helper" - -require "#{ROOT_DIR}/lib/resolvers/base_resolver" -require "#{ROOT_DIR}/lib/framework/detector/os_hierarchy" -require "#{ROOT_DIR}/lib/framework/detector/os_detector" - -require "#{ROOT_DIR}/lib/framework/config/config_reader" -require "#{ROOT_DIR}/lib/framework/config/fact_groups" - -load_dir(['config']) - -load_lib_dirs('resolvers', 'utils') -load_lib_dirs('resolvers') -load_lib_dirs('facts_utils') -load_lib_dirs('framework', 'core') -load_lib_dirs('models') -load_lib_dirs('framework', 'benchmarking') -load_lib_dirs('framework', 'core', 'fact_loaders') -load_lib_dirs('framework', 'core', 'fact', 'internal') -load_lib_dirs('framework', 'core', 'fact', 'external') -load_lib_dirs('framework', 'formatters') - -os_hierarchy = OsDetector.instance.hierarchy -os_hierarchy.each { |operating_system| load_lib_dirs('facts', operating_system.downcase, '**') } -os_hierarchy.each { |operating_system| load_lib_dirs('resolvers', operating_system.downcase, '**') } - -require "#{ROOT_DIR}/lib/custom_facts/core/legacy_facter" -load_lib_dirs('framework', 'utils') -load_lib_dirs('util') - -require "#{ROOT_DIR}/lib/framework/core/fact_augmenter" -require "#{ROOT_DIR}/lib/framework/parsers/query_parser" From 2d83a7acb6326ec10589def6d88119fa0370e52a Mon Sep 17 00:00:00 2001 From: BogdanIrimie Date: Wed, 2 Sep 2020 12:06:13 +0300 Subject: [PATCH 4/5] (FACT-1380) Fix tests and rubocop. --- lib/facter/custom_facts/util/directory_loader.rb | 12 +++++++++--- lib/facter/framework/core/benchmarking/timer.rb | 3 +-- spec/framework/core/options/option_store_spec.rb | 3 ++- 3 files changed, 12 insertions(+), 6 deletions(-) diff --git a/lib/facter/custom_facts/util/directory_loader.rb b/lib/facter/custom_facts/util/directory_loader.rb index 9a0e39aea8..22b34047cb 100644 --- a/lib/facter/custom_facts/util/directory_loader.rb +++ b/lib/facter/custom_facts/util/directory_loader.rb @@ -84,9 +84,7 @@ def load_searched_facts(collection, searched_facts, weight) parser = LegacyFacter::Util::Parser.parser_for(fact.file) next if parser.nil? - data = nil - fact_name = File.basename(fact.file) - Facter::Framework::Benchmarking::Timer.measure(fact_name) { data = parser.results } + data = resolve_fact(fact, parser) if data == false LegacyFacter.warn "Could not interpret fact file #{fact.file}" @@ -101,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) } diff --git a/lib/facter/framework/core/benchmarking/timer.rb b/lib/facter/framework/core/benchmarking/timer.rb index ef00039354..cf3221539a 100644 --- a/lib/facter/framework/core/benchmarking/timer.rb +++ b/lib/facter/framework/core/benchmarking/timer.rb @@ -1,4 +1,5 @@ # frozen_string_literal: true + require 'benchmark' module Facter @@ -20,5 +21,3 @@ def measure(fact_name) end end end - - diff --git a/spec/framework/core/options/option_store_spec.rb b/spec/framework/core/options/option_store_spec.rb index 95cfadf55f..4b5e804fd6 100644 --- a/spec/framework/core/options/option_store_spec.rb +++ b/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 From 4c0294b4830d3b27490ca2d65df266023c075d66 Mon Sep 17 00:00:00 2001 From: BogdanIrimie Date: Wed, 2 Sep 2020 18:11:31 +0300 Subject: [PATCH 5/5] (FACT-1380) Add tests. --- .../{core => }/benchmarking/timer.rb | 0 lib/facter/framework/core/file_loader.rb | 2 +- .../framework/benchmarking/timer_spec.rb | 33 +++++++++++++++++++ 3 files changed, 34 insertions(+), 1 deletion(-) rename lib/facter/framework/{core => }/benchmarking/timer.rb (100%) create mode 100644 spec/facter/framework/benchmarking/timer_spec.rb diff --git a/lib/facter/framework/core/benchmarking/timer.rb b/lib/facter/framework/benchmarking/timer.rb similarity index 100% rename from lib/facter/framework/core/benchmarking/timer.rb rename to lib/facter/framework/benchmarking/timer.rb diff --git a/lib/facter/framework/core/file_loader.rb b/lib/facter/framework/core/file_loader.rb index bea70b5b75..69d52b27cf 100644 --- a/lib/facter/framework/core/file_loader.rb +++ b/lib/facter/framework/core/file_loader.rb @@ -39,7 +39,7 @@ def load_dir(*dirs) load_dir(['facts_utils']) load_dir(%w[framework core]) load_dir(['models']) -load_dir(%w[framework core benchmarking]) +load_dir(%w[framework benchmarking]) load_dir(%w[framework core fact_loaders]) load_dir(%w[framework core fact internal]) diff --git a/spec/facter/framework/benchmarking/timer_spec.rb b/spec/facter/framework/benchmarking/timer_spec.rb new file mode 100644 index 0000000000..9e314cb5ee --- /dev/null +++ b/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