Implements slow query logger (#294)

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)

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)

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

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

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

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

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

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