accurate duration

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
+          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