Support :time_ms

README.md

@@ -122,15 +122,15 @@ logger.info("My log message")
 # My log message @metadata {"level": "info", "context": {...}}
 ```
 
-Timber will never deviate from the public `::Logger` interface in *any* way.
+Timber will *never* deviate from the public `::Logger` interface in *any* way.
 
 ---
 
 </p></details>
 
-<details><summary><strong>Tagging logs</strong></summary><p>
+<details><summary><strong>Tagging</strong></summary><p>
 
-Need a quick and easy way to identify a log? Use tags!:
+Need a quick way to identify logs? Use tags!:
 
 ```ruby
 logger.info(message: "My log message", tag: "tag")
@@ -156,8 +156,28 @@ end
 # My log message @metadata {"level": "info", "tags": ["tag"], "context": {...}}
 ```
 
+---
+
 </p></details>
 
+<details><summary><strong>Timings & Durations</strong></summary><p>
+
+Sometimes you need a quick way to add timings to log statements:
+
+```ruby
+start = Time.now
+# ...my code to time...
+time_ms = (Time.now - start) * 1000
+logger.info(message: "Task complete", time_ms: time_ms)
+```
+
+* The `:time_ms` attribute is supported by Timber. If present, we will display it in the interface, etc.
+
+---
+
+</p></details>
+
+
 <details><summary><strong>Custom events</strong></summary><p>
 
 1. Log a structured Hash (simplest)

lib/timber/log_entry.rb

@@ -5,7 +5,7 @@ class LogEntry #:nodoc:
     DT_PRECISION = 6.freeze
     SCHEMA = "https://raw.githubusercontent.com/timberio/log-event-json-schema/1.2.3/schema.json".freeze
 
-    attr_reader :context_snapshot, :event, :level, :message, :progname, :tags, :time
+    attr_reader :context_snapshot, :event, :level, :message, :progname, :tags, :time, :time_ms
 
     # Creates a log entry suitable to be sent to the Timber API.
     # @param severity [Integer] the log level / severity
@@ -17,12 +17,13 @@ class LogEntry #:nodoc:
     # @param event [Timber.Event] structured data representing the log line event. This should be
     #   an instance of `Timber.Event`.
     # @return [LogEntry] the resulting LogEntry object
-    def initialize(level, time, progname, message, context_snapshot, event, tags)
+    def initialize(level, time, progname, message, context_snapshot, event, options = {})
       @level = level
       @time = time.utc
       @progname = progname
       @message = message
-      @tags = tags
+      @tags = options[:tags]
+      @time_ms = options[:time_ms]
 
       context_snapshot = {} if context_snapshot.nil?
       system_context = Contexts::System.new(pid: Process.pid)
@@ -34,7 +35,8 @@ def initialize(level, time, progname, message, context_snapshot, event, tags)
 
     def as_json(options = {})
       options ||= {}
-      hash = {:level => level, :dt => formatted_dt, :message => message, :tags => tags}
+      hash = {:level => level, :dt => formatted_dt, :message => message, :tags => tags,
+        :time_ms => time_ms}
 
       if !event.nil?
         hash[:event] = event

lib/timber/logger.rb

@@ -76,15 +76,23 @@ class Formatter
         def build_log_entry(severity, time, progname, msg)
           level = SEVERITY_MAP.fetch(severity)
           context_snapshot = CurrentContext.instance.snapshot
+
           tags = extract_active_support_tagged_logging_tags
-          tags += [msg.delete(:tag)] if msg.is_a?(Hash) && msg.key?(:tag)
-          tags += msg.delete(:tags) if msg.is_a?(Hash) && msg.key?(:tags)
+          time_ms = nil
+          if msg.is_a?(Hash)
+            tags << msg.delete(:tag) if msg.key?(:tag)
+            tags += msg.delete(:tags) if msg.key?(:tags)
+            time_ms = msg.delete(:time_ms) if msg.key?(:time_ms)
+
+            msg = msg[:message] if msg.length == 1
+          end
+
           event = Events.build(msg)
 
           if event
-            LogEntry.new(level, time, progname, event.message, context_snapshot, event, tags)
+            LogEntry.new(level, time, progname, event.message, context_snapshot, event, tags: tags, time_ms: time_ms)
           else
-            LogEntry.new(level, time, progname, msg, context_snapshot, nil, tags)
+            LogEntry.new(level, time, progname, msg, context_snapshot, nil, tags: tags, time_ms: time_ms)
           end
         end
 

spec/timber/logger_spec.rb

@@ -57,6 +57,21 @@
         expect(io.string).to include("\"event\":{\"server_side_app\":{\"sql_query\":{\"sql\":\"select * from users\",\"time_ms\":56.0}}}")
       end
 
+      it "should allow :time_ms" do
+        logger.info(message: "event complete", time_ms: 54.5)
+        expect(io.string).to include("\"time_ms\":54.5")
+      end
+
+      it "should allow :tag" do
+        logger.info(message: "event complete", tag: "tag1")
+        expect(io.string).to include("\"tags\":[\"tag1\"]")
+      end
+
+      it "should allow :tags" do
+        logger.info(message: "event complete", tags: ["tag1", "tag2"])
+        expect(io.string).to include("\"tags\":[\"tag1\",\"tag2\"]")
+      end
+
       it "should allow functions" do
         logger.info do
           {message: "payment rejected", payment_rejected: {customer_id: "abcde1234", amount: 100}}