       deactivate-node-wire-v2->wire-3))
 
 (defn deactivate-node*
-  [{:keys [id received payload]} db]
+  [{:keys [id received payload]} start-time db]
   (let [certname (:certname payload)
         producer-timestamp (to-timestamp (:producer_timestamp payload (now)))]
     (jdbc/with-transacted-connection db
       (when-not (scf-storage/certname-exists? certname)
         (scf-storage/add-certname! certname))
       (scf-storage/deactivate-node! certname producer-timestamp))
-    (log/info (trs "[{0}-{1}] ''{2}'' command processed for {3}"
+    (log/info (trs "[{0}-{1}] [{2} ms] ''{3}'' command processed for {4}"
                    (str id)
                    (str (tcoerce/to-long received))
+                   (in-millis (interval start-time (now)))
                    (command-names :deactivate-node)
                    certname))))
 
-(defn deactivate-node [{:keys [payload version] :as command} db]
+(defn deactivate-node [{:keys [payload version] :as command} start-time db]
   (-> command
       (assoc :payload (case version
                         1 (deactivate-node-wire-v1->wire-3 payload)
                         2 (deactivate-node-wire-v2->wire-3 payload)
                         payload))
-      (deactivate-node* db)))
+      (deactivate-node* start-time db)))
 
 ;; Report submission
 
 (defn store-report*
-  [{:keys [payload id received]} db]
+  [{:keys [payload id received]} start-time db]
   (let [{:keys [certname puppet_version] :as report} payload
         producer-timestamp (to-timestamp (:producer_timestamp payload (now)))]
     (jdbc/with-transacted-connection db
       (scf-storage/maybe-activate-node! certname producer-timestamp)
       (scf-storage/add-report! report received))
-    (log/info (trs "[{0}-{1}] ''{2}'' puppet v{3} command processed for {4}"
+    (log/info (trs "[{0}-{1}] [{2} ms] ''{3}'' puppet v{4} command processed for {5}"
                    (str id)
                    (str (tcoerce/to-long received))
+                   (in-millis (interval start-time (now)))
                    (command-names :store-report)
                    puppet_version
                    certname))))
 
-(defn store-report [{:keys [payload version received] :as command} db]
+(defn store-report [{:keys [payload version received] :as command} start-time db]
   (let [validated-payload (upon-error-throw-fatality
                            (s/validate report/report-wireformat-schema
                                        (case version

            [schema.core :as s]
            [puppetlabs.puppetdb.config :as conf]
            [puppetlabs.puppetdb.time :refer [to-timestamp]]
            [clj-time.core :as time :refer [now]]
            [clj-time.format :as fmt-time]
            [clojure.set :as set]
            [clojure.core.async :as async]


(defn process-command!
  "Takes a command object and processes it to completion. Dispatch is
   based on the command's name and version information"
  [{command-name :command version :version delete? :delete? :as command} db]
  (when-not delete?
    (let [start (now)]
      (condp supported-command-version? [command-name version]
        "replace catalog" (replace-catalog command start db)
        "replace facts" (replace-facts command start db)
        "store report" (store-report command start db)
        "deactivate node" (deactivate-node command start db)))))

(defn warn-deprecated
  "Logs a deprecation warning message for the given `command` and `version`"
