Add support for metrics when calling benchmark methods and set Java t…

…hread name under JRuby

.gitignore

@@ -3,4 +3,5 @@ nbproject/*
 *.gem
 .idea/*
 Gemfile.lock
-._test
+._test
+.bundle

Gemfile

@@ -7,6 +7,7 @@ group :test do
   gem "bson_ext", :platform => 'ruby'
   gem 'syslog_protocol'
   gem 'resilient_socket'
+  gem 'awesome_print'
 end
 
 gem "sync_attr"

README.md

@@ -311,20 +311,30 @@ Parameters
     :full
       Log the exception class, message, and backtrace
     :partial
-      Log the exception class and messag
+      Log the exception class and message
       The backtrace will not be logged
     :off
-      Any unhandled exception from the block will not be logged
+      Any unhandled exception raised in the block will not be logged
+    Default: :partial
 
-  :min_duration
+  :min_duration [Float]
     Only log if the block takes longer than this duration in ms
     Default: 0.0
 
-  :payload
+  :payload [Hash]
     Optional, Hash payload
 
-  :exception
+  :exception [Exception]
     Optional, Ruby Exception object to log along with the duration of the supplied block
+
+  :duration [Float]
+    Optional, supply the duration in ms that is logged when a block is not supplied
+    If a block is not supplied then :duration is mandatory
+    If a block is supplied :duration is ignored
+
+  :metric [Object]
+    Optional, when this parameter is supplied all subscribers will be notified of this
+    metric, along with the Log Struct described below
 ```
 
 ### Logging levels
@@ -488,6 +498,9 @@ Sample output:
 2013-11-07 16:26:02.744139 I [35841:User calculation thread 32] (0.0ms) ExternalSupplier -- Calling external interface
 ```
 
+When running JRuby, Thread.current.name will also set the underlying thread name in the JVM
+which is very useful when monitoring the JVM via JMX using tools such as jconsole.
+
 #### NOTE:
 
 Make sure that the assigned thread name is unique otherwise it will be difficult
@@ -499,6 +512,45 @@ For example, use the current thread object_id to ensure uniqueness:
 Thread.current.name = "Worker Thread:#{Thread.current.object_id}"
 ```
 
+### Metrics integration
+
+In production environments it is often necessary to not only measure the performance of a
+block of code using for example:
+
+```ruby
+logger.benchmark_info "Calling external interface" do
+  # Code to call the external supplier ...
+end
+```
+
+Sending the performance information gathered above to something like NewRelic
+is also very useful, and we can end up with:
+
+```ruby
+logger.benchmark_info "Calling external interface" do
+  self.class.trace_execution_scoped(['Custom/slow_action/beginning_work']) do
+    # Code to call the external supplier ...
+  end
+end
+```
+
+Rather than wrapping the code everywhere with two blocks, a single subscriber can
+be setup in config/initializers/semantic_logger_metrics.rb:
+
+```ruby
+SemanticLogger.on_metric do |log_struct|
+  ::NewRelic::Agent.record_metric(log_struct.metric, log_struct.duration)
+end
+```
+
+Then update the log entry as follows:
+
+```ruby
+logger.benchmark_info "Calling external interface", :metric => 'Custom/slow_action/beginning_work' do
+  # Code to call the external supplier ...
+end
+```
+
 ## Standalone SemanticLogger
 
 When using SemanticLogger inside of Rails all we need to do is include the
@@ -843,6 +895,11 @@ Once the logging data is in the NOSQL data store it can be queried quickly and
 efficiently. Some SQL data stores also allow complex data types that could be used
 for storing and querying the logging data
 
+Before writing SemanticLogger all of the following logging frameworks were thoroughly
+evaluated. None of them met the above Semantic requirements, or the performance requirements
+of hundreds of threads all logging at the same time:
+logback, logging, log4r, central_logger, whoops
+
 ## Architecture & Performance
 
 In order to ensure that logging does not hinder the performance of the application
@@ -931,7 +988,7 @@ To log to MongoDB, it also needs the Ruby Mongo Driver
 
 - Add support for a configuration file that can set log level by class name
 - Configuration file to support adding appenders
-- Based on end-user demand add appenders for: Syslog, hadoop, redis, etc..
+- Based on end-user demand add appenders for: hadoop, redis, etc..
 
 Meta
 ----

lib/semantic_logger/appender/base.rb

@@ -36,7 +36,7 @@ def default_formatter
 
           message = log.message.to_s.dup
           message << " -- " << log.payload.inspect if log.payload
-          message << " -- " << "#{log.exception.class}: #{log.exception.message}\n#{(log.exception.backtrace || []).join("\n")}" if log.exception
+          message << " -- Exception: " << "#{log.exception.class}: #{log.exception.message}\n#{(log.exception.backtrace || []).join("\n")}" if log.exception
 
           duration_str = log.duration ? "(#{'%.1f' % log.duration}ms) " : ''
 
@@ -56,7 +56,7 @@ def self.colorized_formatter
 
           message = log.message.to_s.dup
           message << " -- " << log.payload.inspect if log.payload
-          message << " -- " << "#{colors::BOLD}#{log.exception.class}: #{log.exception.message}#{colors::CLEAR}\n#{(log.exception.backtrace || []).join("\n")}" if log.exception
+          message << " -- Exception: " << "#{colors::BOLD}#{log.exception.class}: #{log.exception.message}#{colors::CLEAR}\n#{(log.exception.backtrace || []).join("\n")}" if log.exception
 
           duration_str = log.duration ? "(#{colors::BOLD}#{'%.1f' % log.duration}ms#{colors::CLEAR}) " : ''
 

lib/semantic_logger/base.rb

@@ -70,28 +70,9 @@ def level=(level)
     #
     SemanticLogger::LEVELS.each_with_index do |level, index|
       class_eval <<-EOT, __FILE__, __LINE__
-        def #{level}(message=nil, payload=nil, exception=nil)
+        def #{level}(message=nil, payload=nil, exception=nil, &block)
           if @level_index <= #{index}
-            if exception.nil? && payload && payload.is_a?(Exception)
-              exception = payload
-              payload = nil
-            end
-
-            if block_given? && (result = yield)
-              if result.is_a?(String)
-                message = message.nil? ? result : "\#{message} -- \#{result}"
-              elsif payload && payload.respond_to?(:merge)
-                payload.merge(result)
-              else
-                payload = result
-              end
-            end
-
-            # Add scoped payload
-            if self.payload
-              payload = payload.nil? ? self.payload : self.payload.merge(payload)
-            end
-            log Log.new(:#{level}, Thread.current.name, name, message, payload, Time.now, nil, tags, #{index}, exception)
+            log_internal(:#{level}, #{index}, message, payload, exception, &block)
             true
           else
             false
@@ -102,41 +83,11 @@ def #{level}?
           @level_index <= #{index}
         end
 
-        def benchmark_#{level}(message, params = nil)
-          raise "Mandatory block missing" unless block_given?
+        def benchmark_#{level}(message, params = {}, &block)
           if @level_index <= #{index}
-            log_exception = params.nil? ? :partial : (params[:log_exception] || :partial)
-            min_duration  = params.nil? ? 0.0      : (params[:min_duration] || 0.0)
-            payload       = params.nil? ? nil      : params[:payload]
-            exception     = params.nil? ? nil      : params[:exception]
-            start         = Time.now
-            begin
-              yield
-            rescue Exception => exc
-              exception = exc
-            ensure
-              end_time = Time.now
-              duration = 1000.0 * (end_time - start)
-
-              # Add scoped payload
-              if self.payload
-                payload = payload.nil? ? self.payload : self.payload.merge(payload)
-              end
-              if exception
-                case log_exception
-                when :full
-                  log Log.new(:#{level}, Thread.current.name, name, message, payload, end_time, duration, tags, #{index}, exception)
-                when :partial
-                  log Log.new(:#{level}, Thread.current.name, name, "\#{message} -- Exception: \#{exception.class}: \#{exception.message}", payload, end_time, duration, tags, #{index}, nil)
-                end
-                raise exception
-              elsif duration >= min_duration
-                # Only log if the block took longer than 'min_duration' to complete
-                log Log.new(:#{level}, Thread.current.name, name, message, payload, end_time, duration, tags, #{index}, nil)
-              end
-            end
+            benchmark_internal(:#{level}, #{index}, message, params, &block)
           else
-            yield
+            block.call(params) if block
           end
         end
       EOT
@@ -213,8 +164,6 @@ def payload
     alias :unknown :error
     alias :unknown? :error?
 
-    # #TODO implement a thread safe #silence method
-
     # DEPRECATED See SemanticLogger.default_level=
     def self.default_level=(level)
       warn "[DEPRECATION] `SemanticLogger::Logger.default_level=` is deprecated.  Please use `SemanticLogger.default_level=` instead."
@@ -272,7 +221,10 @@ def log(log_)
     #
     # level_index
     #   Internal index of the log level
-    Log = Struct.new(:level, :thread_name, :name, :message, :payload, :time, :duration, :tags, :level_index, :exception)
+    #
+    # metric [Object]
+    #   Object supplied when benchmark_x was called
+    Log = Struct.new(:level, :thread_name, :name, :message, :payload, :time, :duration, :tags, :level_index, :exception, :metric)
 
     # Internal method to return the log level as an internal index
     # Also supports mapping the ::Logger levels to SemanticLogger levels
@@ -297,5 +249,70 @@ def self.map_level_to_index(level)
       index
     end
 
+    # Log message at the specified level
+    def log_internal(level, index, message=nil, payload=nil, exception=nil, &block)
+      if exception.nil? && payload && payload.is_a?(Exception)
+        exception = payload
+        payload = nil
+      end
+
+      if block && (result = block.call)
+        if result.is_a?(String)
+          message = message.nil? ? result : "#{message} -- #{result}"
+        elsif payload && payload.respond_to?(:merge)
+          payload.merge(result)
+        else
+          payload = result
+        end
+      end
+
+      # Add scoped payload
+      if self.payload
+        payload = payload.nil? ? self.payload : self.payload.merge(payload)
+      end
+      log Log.new(level, Thread.current.name, name, message, payload, Time.now, nil, tags, index, exception)
+    end
+
+    # Measure the supplied block and log the message
+    def benchmark_internal(level, index, message, params, &block)
+      start     = Time.now
+      begin
+        rc = block.call(params) if block
+        exception = params[:exception]
+        rc
+      rescue Exception => exc
+        exception = exc
+      ensure
+        end_time = Time.now
+        # Extract options after block completes so that block can modify any of the options
+        log_exception = params[:log_exception] || :partial
+        min_duration  = params[:min_duration] || 0.0
+        payload       = params[:payload]
+        metric        = params[:metric]
+        duration      = if block_given?
+          1000.0 * (end_time - start)
+        else
+          params[:duration] || raise("Mandatory block missing when :duration option is not supplied")
+        end
+
+        # Add scoped payload
+        if self.payload
+          payload = payload.nil? ? self.payload : self.payload.merge(payload)
+        end
+        if exception
+          case log_exception
+          when :full
+            log Log.new(level, Thread.current.name, name, message, payload, end_time, duration, tags, index, exception, metric)
+          when :partial
+            log Log.new(level, Thread.current.name, name, "#{message} -- Exception: #{exception.class}: #{exception.message}", payload, end_time, duration, tags, index, nil, metric)
+          end
+          raise exception
+        elsif duration >= min_duration
+          # Only log if the block took longer than 'min_duration' to complete
+          log Log.new(level, Thread.current.name, name, message, payload, end_time, duration, tags, index, nil, metric)
+        end
+      end
+    end
+
   end
 end

lib/semantic_logger/core_ext/thread.rb

@@ -2,12 +2,9 @@
 class Thread
   # Returns the name of the current thread
   # Default:
-  #    JRuby: The Java thread name
+  #    JRuby: The underlying Java thread name
   #    Other: String representation of this thread's object_id
   if defined? JRuby
-    # Design Note:
-    #   In JRuby with "thread.pool.enabled=true" each Ruby Thread instance is
-    #   new, even though the Java threads are being re-used from the pool
     def name
       @name ||= JRuby.reference(self).native_thread.name
     end
@@ -17,8 +14,15 @@ def name
     end
   end
 
-  # Set the name of this thread for logging and debugging purposes
-  def name=(name)
-    @name = name.to_s
+  # Set the name of this thread
+  #   On JRuby it also sets the underlying Java Thread name
+  if defined? JRuby
+    def name=(name)
+      JRuby.reference(self).native_thread.name = @name = name.to_s
+    end
+  else
+    def name=(name)
+      @name = name.to_s
+    end
   end
 end