Adding additional instrumentation to `publish-event!` (#35832)

* Adding additional instrumentation to `publish-event!`

The `publish-events!` defmethod has quite a few code branches and we're trying to figure out if one of these is causing the slowness described in #33499 as well as stats dashboard [2117](https://stats.metabase.com/dashboard/2117). This PR should provide additional information as to where the delays might be occurring.

It adds the following spans/changes:
- An `:events/initialized` attribute at the top level of `publish-event!`
- `record-view!` span
- `record-event!` span
- `update-users-recent-views!` span

If we merge this PR we can decide if these changes are worthwhile and revert if we don't like the additional layer of wrapping.

* Reinstating record-event! span to resolve rebase conflict.

* Fixing bad merge

src/metabase/events.clj

@@ -110,7 +110,8 @@
   [topic event]
   (span/with-span!
     {:name       "publish-event!"
-     :attributes {:event/topic topic}}
+     :attributes {:event/topic topic
+                  :events/initialized (some? @events-initialized?)}}
     (assert (not *compile-files*) "Calls to publish-event! are not allowed in the top level.")
     (if-not @events-initialized?
       ;; if the event namespaces aren't initialized yet, make sure they're all loaded up before trying to do dispatch.

src/metabase/events/view_log.clj

@@ -8,16 +8,22 @@
    [metabase.util.i18n :as i18n :refer [deferred-tru]]
    [metabase.util.log :as log]
    [methodical.core :as m]
+   [steffan-westcott.clj-otel.api.trace.span :as span]
    [toucan2.core :as t2]))
 
 (defn record-view!
   "Simple base function for recording a view of a given `model` and `model-id` by a certain `user`."
   [model model-id user-id metadata]
-  (t2/insert! :model/ViewLog
-              :user_id  user-id
-              :model    (u/lower-case-en model)
-              :model_id model-id
-              :metadata metadata))
+  (span/with-span!
+    {:name       "record-view!"
+     :attributes {:model/id   model-id
+                  :user/id    user-id
+                  :model/name (u/lower-case-en model)}}
+    (t2/insert! :model/ViewLog
+                :user_id user-id
+                :model (u/lower-case-en model)
+                :model_id model-id
+                :metadata metadata)))
 
 (derive ::read-event :metabase/event)
 (derive :event/card-read ::read-event)

src/metabase/models/audit_log.clj

@@ -13,6 +13,7 @@
    [metabase.util.malli.registry :as mr]
    [metabase.util.malli.schema :as ms]
    [methodical.core :as m]
+   [steffan-westcott.clj-otel.api.trace.span :as span]
    [toucan2.core :as t2]))
 
 (set! *warn-on-reflection* true)
@@ -112,24 +113,33 @@
   were updated."
   [topic :- :keyword
    params :- ::event-params]
-  (let [{:keys [user-id model-name model-id details unqualified-topic object]}
-        (construct-event topic params api/*current-user-id*)]
-    (t2/insert! :model/AuditLog
-                :topic    unqualified-topic
-                :details  details
-                :model    model-name
-                :model_id model-id
-                :user_id  user-id)
-    ;; TODO: temporarily double-writing to the `activity` table, delete this in Metabase v48
-    ;; TODO figure out set of events to actually continue recording in activity
-    (when-not (#{:card-read :dashboard-read :table-read :card-query :setting-update} unqualified-topic)
-      (activity/record-activity!
-       {:topic    topic
-        :object   object
-        :details  details
-        :model    model-name
-        :model-id model-id
-        :user-id  user-id}))))
+  (span/with-span!
+    {:name       "record-event!"
+     :attributes (cond-> {}
+                   (:model-id params)
+                   (assoc :model/id (:model-id params))
+                   (:user-id params)
+                   (assoc :user/id (:user-id params))
+                   (:model params)
+                   (assoc :model/name (u/lower-case-en (:model params))))}
+    (let [{:keys [user-id model-name model-id details unqualified-topic object]}
+          (construct-event topic params api/*current-user-id*)]
+      (t2/insert! :model/AuditLog
+                  :topic    unqualified-topic
+                  :details  details
+                  :model    model-name
+                  :model_id model-id
+                  :user_id  user-id)
+      ;; TODO: temporarily double-writing to the `activity` table, delete this in Metabase v48
+      ;; TODO figure out set of events to actually continue recording in activity
+      (when-not (#{:card-read :dashboard-read :table-read :card-query :setting-update} unqualified-topic)
+        (activity/record-activity!
+          {:topic    topic
+           :object   object
+           :details  details
+           :model    model-name
+           :model-id model-id
+           :user-id  user-id})))))
 
 (t2/define-before-insert :model/AuditLog
   [activity]

src/metabase/models/recent_views.clj

@@ -2,12 +2,14 @@
   "The Recent Views table is used to track the most recent views of objects such as Cards, Tables and Dashboards for
   each user."
   (:require
+    #_{:clj-kondo/ignore [:deprecated-namespace]}
    [java-time :as t]
    [metabase.util :as u]
    [metabase.util.honey-sql-2 :as h2x]
    [metabase.util.malli :as mu]
    [metabase.util.malli.schema :as ms]
    [methodical.core :as m]
+   [steffan-westcott.clj-otel.api.trace.span :as span]
    [toucan2.core :as t2]))
 
 (doto :model/RecentViews
@@ -51,14 +53,19 @@
                 :string]
    model-id :- ms/PositiveInt]
   (when user-id
-    (t2/with-transaction [_conn]
-      (t2/insert! :model/RecentViews {:user_id  user-id
-                                      :model    (name model)
-                                      :model_id model-id})
-      (let [current-views (t2/select :model/RecentViews :user_id user-id {:order-by [[:id :desc]]})
-            ids-to-prune  (view-ids-to-prune current-views *recent-views-stored-per-user*)]
-        (when (seq ids-to-prune)
-         (t2/delete! :model/RecentViews :id [:in ids-to-prune]))))))
+    (span/with-span!
+      {:name       "update-users-recent-views!"
+       :attributes {:model/id   model-id
+                    :user/id    user-id
+                    :model/name (u/lower-case-en model)}}
+      (t2/with-transaction [_conn]
+        (t2/insert! :model/RecentViews {:user_id  user-id
+                                        :model    (name model)
+                                        :model_id model-id})
+        (let [current-views (t2/select :model/RecentViews :user_id user-id {:order-by [[:id :desc]]})
+              ids-to-prune  (view-ids-to-prune current-views *recent-views-stored-per-user*)]
+          (when (seq ids-to-prune)
+            (t2/delete! :model/RecentViews :id [:in ids-to-prune])))))))
 
 (defn most-recently-viewed-dashboard-id
   "Returns ID of the most recently viewed dashboard for a given user within the last 24 hours, or `nil`."