diff --git a/CHANGELOG.md b/CHANGELOG.md index 40a7ebd27b..6529be16e9 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,8 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). ## [Unreleased] +### Added +- Slow Queries Logger feature logging slow queries in a dedicated log file ### Fixed - `first_or_create` with a polymorphic association [#288](https://github.com/NoBrainerORM/nobrainer/issues/288) diff --git a/lib/no_brainer/config.rb b/lib/no_brainer/config.rb index 8780484ad6..51d42ff88c 100644 --- a/lib/no_brainer/config.rb +++ b/lib/no_brainer/config.rb @@ -1,29 +1,36 @@ +# frozen_string_literal: true + require 'logger' module NoBrainer::Config SETTINGS = { - :app_name => { :default => ->{ default_app_name } }, - :environment => { :default => ->{ default_environment } }, - :rethinkdb_urls => { :default => ->{ [default_rethinkdb_url] } }, - :ssl_options => { :default => ->{ nil } }, - :driver => { :default => ->{ :regular }, :valid_values => [:regular, :em] }, - :logger => { :default => ->{ default_logger } }, - :colorize_logger => { :default => ->{ true }, :valid_values => [true, false] }, - :warn_on_active_record => { :default => ->{ true }, :valid_values => [true, false] }, - :durability => { :default => ->{ nil } }, # legacy - :table_options => { :default => ->{ {:shards => 1, :replicas => 1, :write_acks => :majority} }, - :valid_keys => [:durability, :shards, :replicas, :primary_replica_tag, :nonvoting_replica_tags, :write_acks] }, - :run_options => { :default => ->{ {:durability => default_durability} } }, - :max_string_length => { :default => ->{ 255 } }, - :user_timezone => { :default => ->{ :local }, :valid_values => [:unchanged, :utc, :local] }, - :db_timezone => { :default => ->{ :utc }, :valid_values => [:unchanged, :utc, :local] }, - :geo_options => { :default => ->{ {:geo_system => 'WGS84', :unit => 'm'} } }, - :distributed_lock_class => { :default => ->{ "NoBrainer::Lock" } }, - :lock_options => { :default => ->{ { :expire => 60, :timeout => 10 } }, :valid_keys => [:expire, :timeout] }, - :per_thread_connection => { :default => ->{ false }, :valid_values => [true, false] }, - :machine_id => { :default => ->{ default_machine_id } }, - :criteria_cache_max_entries => { :default => -> { 10_000 } }, - } + app_name: { default: -> { default_app_name } }, + colorize_logger: { default: -> { true }, valid_values: [true, false] }, + criteria_cache_max_entries: { default: -> { 10_000 } }, + db_timezone: { default: -> { :utc }, valid_values: %i[unchanged utc local] }, + distributed_lock_class: { default: -> { 'NoBrainer::Lock' } }, + driver: { default: -> { :regular }, valid_values: %i[regular em] }, + durability: { default: -> {} }, # legacy + environment: { default: -> { default_environment } }, + geo_options: { default: -> { { geo_system: 'WGS84', unit: 'm' } } }, + lock_options: { default: -> { { expire: 60, timeout: 10 } }, valid_keys: %i[expire timeout] }, + log_slow_queries: { default: -> { false } }, + logger: { default: -> { default_logger } }, + long_query_time: { default: -> { 10 } }, + machine_id: { default: -> { default_machine_id } }, + max_string_length: { default: -> { 255 } }, + per_thread_connection: { default: -> { false }, valid_values: [true, false] }, + rethinkdb_urls: { default: -> { [default_rethinkdb_url] } }, + run_options: { default: -> { { durability: default_durability } } }, + slow_query_log_file: { default: -> { File.join('/', 'var', 'log', 'rethinkdb', 'slow_queries.log') } }, + ssl_options: { default: -> {} }, + table_options: { + default: -> { { shards: 1, replicas: 1, write_acks: :majority } }, + valid_keys: %i[durability shards replicas primary_replica_tag nonvoting_replica_tags write_acks] + }, + user_timezone: { default: -> { :local }, valid_values: %i[unchanged utc local] }, + warn_on_active_record: { default: -> { true }, valid_values: [true, false] } + }.freeze class << self attr_accessor(*SETTINGS.keys) diff --git a/lib/no_brainer/profiler/logger.rb b/lib/no_brainer/profiler/logger.rb index 038cf7ebbd..10d57e15bb 100644 --- a/lib/no_brainer/profiler/logger.rb +++ b/lib/no_brainer/profiler/logger.rb @@ -1,45 +1,62 @@ -class NoBrainer::Profiler::Logger - def on_query(env) - not_indexed = env[:criteria] && env[:criteria].where_present? && - !env[:criteria].where_indexed? && - !env[:criteria].model.try(:perf_warnings_disabled) - - level = env[:exception] ? Logger::ERROR : - not_indexed ? Logger::INFO : Logger::DEBUG - return if NoBrainer.logger.level > level - - msg_duration = (env[:duration] * 1000.0).round(1).to_s - msg_duration = " " * [0, 6 - msg_duration.size].max + msg_duration - msg_duration = "[#{msg_duration}ms] " - - env[:query_type] = NoBrainer::RQL.type_of(env[:query]) - - msg_db = "[#{env[:options][:db]}] " if env[:options][:db] - msg_query = env[:query].inspect.gsub(/\n/, '').gsub(/ +/, ' ') - - msg_exception = "#{env[:exception].class} #{env[:exception].message.split("\n").first}" if env[:exception] - msg_exception ||= "perf: filtering without using an index" if not_indexed - - msg_last = nil - - if NoBrainer::Config.colorize_logger - query_color = case env[:query_type] - when :write then "\e[1;31m" # red - when :read then "\e[1;32m" # green - when :management then "\e[1;33m" # yellow - end - msg_duration = [query_color, msg_duration].join - msg_db = ["\e[0;34m", msg_db, query_color].join if msg_db - if msg_exception - exception_color = "\e[0;31m" if level == Logger::ERROR - msg_exception = ["\e[0;39m", " -- ", exception_color, msg_exception].compact.join +# frozen_string_literal: true + +module NoBrainer + module Profiler + class Logger + def on_query(env) + level = ::Logger::ERROR if env[:exception] + level ||= not_indexed(env) ? ::Logger::INFO : ::Logger::DEBUG + return if NoBrainer.logger.level > level + + NoBrainer.logger.add(level, build_message(env)) end - msg_last = "\e[0m" - end - msg = [msg_duration, msg_db, msg_query, msg_exception, msg_last].join - NoBrainer.logger.add(level, msg) - end + private + + def build_message(env) + msg_duration = (env[:duration] * 1000.0).round(1).to_s + msg_duration = (' ' * [0, 6 - msg_duration.size].max) + msg_duration + msg_duration = "[#{msg_duration}ms] " + + env[:query_type] = NoBrainer::RQL.type_of(env[:query]) + + msg_db = "[#{env[:options][:db]}] " if env[:options][:db] + msg_query = env[:query].inspect.gsub(/\n/, '').gsub(/ +/, ' ') + + msg_exception = "#{env[:exception].class} #{env[:exception].message.split("\n").first}" if env[:exception] + msg_exception ||= 'perf: filtering without using an index' if not_indexed(env) + + msg_last = nil - NoBrainer::Profiler.register(self.new) + if NoBrainer::Config.colorize_logger + msg_duration = [query_color(env[:query_type]), msg_duration].join + msg_db = ["\e[0;34m", msg_db, query_color(env[:query_type])].join if msg_db + if msg_exception + exception_color = "\e[0;31m" if level == Logger::ERROR + msg_exception = ["\e[0;39m", ' -- ', exception_color, msg_exception].compact.join + end + msg_last = "\e[0m" + end + + [msg_duration, msg_db, msg_query, msg_exception, msg_last].join + end + + def not_indexed(env) + env[:criteria] && + env[:criteria].where_present? && + !env[:criteria].where_indexed? && + !env[:criteria].model.try(:perf_warnings_disabled) + end + + def query_color(query_type) + { + write: "\e[1;31m", # red + read: "\e[1;32m", # green + management: "\e[1;33m" # yellow + }[query_type] + end + + NoBrainer::Profiler.register(new) + end + end end diff --git a/lib/no_brainer/profiler/slow_queries.rb b/lib/no_brainer/profiler/slow_queries.rb new file mode 100644 index 0000000000..84ace935af --- /dev/null +++ b/lib/no_brainer/profiler/slow_queries.rb @@ -0,0 +1,23 @@ +# frozen_string_literal: true + +module NoBrainer + module Profiler + class SlowQueries < Logger + def on_query(env) + return unless NoBrainer::Config.log_slow_queries + + query_duration = (env[:duration] * 1000.0).round(1) + + return unless query_duration > NoBrainer::Config.long_query_time + + File.write( + NoBrainer::Config.slow_query_log_file, + build_message(env), + mode: 'a' + ) + end + + NoBrainer::Profiler.register(new) + end + end +end diff --git a/lib/no_brainer/query_runner/profiler.rb b/lib/no_brainer/query_runner/profiler.rb index 7398c9ac04..37ebf41bbe 100644 --- a/lib/no_brainer/query_runner/profiler.rb +++ b/lib/no_brainer/query_runner/profiler.rb @@ -1,3 +1,5 @@ +# frozen_string_literal: true + class NoBrainer::QueryRunner::Profiler < NoBrainer::QueryRunner::Middleware def call(env) profiler_start(env) @@ -10,12 +12,13 @@ def call(env) private require 'no_brainer/profiler/logger' + require 'no_brainer/profiler/slow_queries' def profiler_start(env) env[:start_time] = Time.now end - def profiler_end(env, exception=nil) + def profiler_end(env, exception = nil) return if handle_on_demand_exception?(env, exception) env[:end_time] = Time.now @@ -26,10 +29,11 @@ def profiler_end(env, exception=nil) env[:query_type] = NoBrainer::RQL.type_of(env[:query]) NoBrainer::Profiler.registered_profilers.each do |profiler| - begin + begin # rubocop:disable Style/RedundantBegin profiler.on_query(env) - rescue Exception => e - STDERR.puts "[NoBrainer] Profiling error: #{e.class} #{e.message}" + rescue StandardError => error + STDERR.puts "[NoBrainer] #{profiler.class.name} profiler error: " \ + "#{error.class} #{error.message}\n#{error.backtrace.join('\n')}" end end end diff --git a/lib/rails/generators/templates/nobrainer.rb b/lib/rails/generators/templates/nobrainer.rb index 121a4e5fc0..a2106ac733 100644 --- a/lib/rails/generators/templates/nobrainer.rb +++ b/lib/rails/generators/templates/nobrainer.rb @@ -1,3 +1,5 @@ +# frozen_string_literal: true + NoBrainer.configure do |config| # app_name is the name of your application in lowercase. # When using Rails, the application name is automatically inferred. @@ -94,4 +96,16 @@ # is cached. The per criteria cache is disabled if it grows too big to avoid # out of memory issues. # config.criteria_cache_max_entries = 10_000 + + # Write queries running longer than config.long_query_time seconds. + # The slow query log can be used to find queries that take a long time to + # execute and are therefore candidates for optimization. + # config.log_slow_queries = true + + # Queries running longer than the bellow value will be logged in a log file if + # the above `config.log_slow_queries` is `true`. + # config.long_query_time = 10 # seconds + + # Path of the slow queries log file + # config.slow_query_log_file = File.join('/', 'var', 'log', 'rethinkdb', 'slow_queries.log') end diff --git a/nobrainer.gemspec b/nobrainer.gemspec index c17552cab7..7d1fc4ba00 100644 --- a/nobrainer.gemspec +++ b/nobrainer.gemspec @@ -15,7 +15,7 @@ Gem::Specification.new do |s| 'on top of RethinkDB while providing precise semantics.' s.license = 'LGPL-3.0-only' - s.required_ruby_version = '>= 1.9.0' + s.required_ruby_version = ">= #{ENV.fetch('EARTHLY_RUBY_VERSION', '1.9.0')}" s.metadata['allowed_push_host'] = 'https://rubygems.org' s.metadata['homepage_uri'] = s.homepage diff --git a/spec/integration/slow_queries_spec.rb b/spec/integration/slow_queries_spec.rb new file mode 100644 index 0000000000..3ca574c537 --- /dev/null +++ b/spec/integration/slow_queries_spec.rb @@ -0,0 +1,62 @@ +# frozen_string_literal: true + +require 'spec_helper' + +describe 'NoBrainer slow queries feature' do # rubocop:disable RSpec/DescribeClass + before do + NoBrainer.configure do |config| + config.long_query_time = 0.4 # 700ms + config.slow_query_log_file = File.join('/tmp', 'rdb_slow.log') + end + + load_simple_document + end + + def run_long_query + SimpleDocument.first + + sleep NoBrainer::Config.long_query_time + 0.1 # + 100ms + end + + context 'when config.log_slow_queries is not `true`' do + before { NoBrainer::Config.log_slow_queries = false } + + context "when the slow query log file doesn't exist" do + before do + FileUtils.rm_f(NoBrainer::Config.slow_query_log_file) && run_long_query + end + + it "doesn't not create the log file" do + expect(File.exist?(NoBrainer::Config.slow_query_log_file)).to be_falsy # rubocop:disable RSpec/PredicateMatcher + end + end + + context 'when the slow query log file exist' do + before do + File.write(NoBrainer::Config.slow_query_log_file, "test\n") + run_long_query + end + + it "doesn't write to the log file" do + expect(File.read(NoBrainer::Config.slow_query_log_file)).to eql("test\n") + end + end + end + + context 'when config.log_slow_queries is `true`' do + before do + NoBrainer::Config.log_slow_queries = true + run_long_query + end + + it 'does create the log file' do + expect(File.exist?(NoBrainer::Config.slow_query_log_file)).to be_truthy # rubocop:disable RSpec/PredicateMatcher + end + + it 'does write to the log file' do + expect(File.read(NoBrainer::Config.slow_query_log_file)).to match( + /\[\s+[\d.]+ms\] r\.table\("simple_documents"\)\.order_by\(\{"index" => r.asc\(:_id_\)\}\).limit\(1\)/ + ) + end + end +end