diff --git a/lib/semantic/subscribers/active_record.rb b/lib/semantic/subscribers/active_record.rb index dd4576e..63d8a1f 100644 --- a/lib/semantic/subscribers/active_record.rb +++ b/lib/semantic/subscribers/active_record.rb @@ -14,40 +14,45 @@ module Semantic category, model, *remaining = name.split.reverse return if category == 'TRANSACTION' + statement_taint = AnsiColors::TEXT_GRAY_300 case category when 'Count' - statement_taint = AnsiColors::TEXT_GRAY_300 name = "#{category} #{model}" when 'Load' - name = if event.payload[:cached] - statement_taint = AnsiColors::TEXT_GRAY_300 - name = "Cache #{model}" - else - statement_taint = TEXT_BLUE - row_count = event.payload[:row_count] - name = "#{category} #{row_count} #{model.pluralize(row_count)}" - end + if event.payload[:cached] + name = "Cache #{model}" + no_stats = true + else + statement_taint = TEXT_BLUE + row_count = event.payload[:row_count] + name = "#{category} #{row_count} #{model.pluralize(row_count)}" + end when 'Update', 'Create', 'Destroy' + statement_taint = TEXT__PINK name = "#{category} #{model}" category_taint = TRANSACTION_TAINT - statement_taint = TEXT__PINK - increment_transaction_local(event.payload[:transaction].uuid, category.downcase.to_sym) + increment_transaction_local(event.payload[:transaction].uuid, category.downcase.to_sym, event.duration) else raise "unknown sql category: <#{category}>" end + + name = "#{name} #{stats_event(event.duration)}" unless no_stats name = "#{name} #{remaining.join(' ')}" if remaining.any? name = colorize(name, category_taint) if category_taint statement = colorize(event.payload[:sql], statement_taint) + logger.debug("#{name} #{statement}") end - def start_transaction(event) + def start_transaction(_event) logger.info(colorize('Begin', TRANSACTION_TAINT)) end def transaction(event) outcome = colorize(event.payload[:outcome].capitalize, TRANSACTION_TAINT) - summary = transaction_summary(event.payload[:transaction]) - logger.info("#{outcome} (#{summary})") + transaction = event.payload[:transaction] + summary = transaction_summary(transaction) + stats = stats_event(event.duration - transaction_internal_duration(transaction)) + logger.info("#{outcome} #{summary} #{stats}") end def instantiation(event); end @@ -56,18 +61,27 @@ module Semantic private + def stats_event(duration)= colorize("(#{number_to_ms(duration)})", TEXT_GRAY_400) + def number_to_ms(number) = "#{::ActionController::Base.helpers.number_with_precision(number, precision: 1)}ms" + def transaction_internal_duration(transaction) = transaction_local(transaction.uuid)[:total_duration] + def transaction_summary(transaction) transaction_local(transaction.uuid) + .except(:total_duration) .select { |_, value| value.positive? } .map { |k, v| "#{v} #{k.to_s.pluralize(v)}" } .join(',') end - def increment_transaction_local(transaction_id, sql_command) = transaction_local(transaction_id)[sql_command] += 1 + def increment_transaction_local(transaction_id, sql_command, duration) + transaction_local(transaction_id)[sql_command] += 1 + transaction_local(transaction_id)[:total_duration] += duration + end + def thread_local = Thread.current[self.class.to_s] ||= {} def transaction_local(transaction_id) - thread_local[transaction_id] ||= { update: 0, create: 0, destroy: 0 } + thread_local[transaction_id] ||= { update: 0, create: 0, destroy: 0, total_duration: 0 } end end end