Skip to content

Commit

Permalink
Attach latency_ms to e2e events (#718)
Browse files Browse the repository at this point in the history
  • Loading branch information
@dwwoelfel
dwwoelfel authored Jan 16, 2025
1 parent 2899f21 commit 09fc90c
Show file tree
Hide file tree
Showing 5 changed files with 40 additions and 16 deletions.
9 changes: 6 additions & 3 deletions server/src/instant/db/transaction.clj
View file
Original file line number Diff line number Diff line change
Expand Up @@ -207,9 +207,12 @@

results-with-on-deletes (enforce-on-deletes conn attrs app-id results)
tx (transaction-model/create! conn {:app-id app-id})]
(e2e-tracer/start-invalidator-tracking! {:tx-id (:id tx)})
(e2e-tracer/invalidator-tracking-step! {:tx-id (:id tx)
:name "transact"})
(let [tx-created-at (.toInstant (:created_at tx))]
(e2e-tracer/start-invalidator-tracking! {:tx-id (:id tx)
:tx-created-at tx-created-at})
(e2e-tracer/invalidator-tracking-step! {:tx-id (:id tx)
:tx-created-at tx-created-at
:name "transact"}))
(assoc tx :results results-with-on-deletes)))))

(defn transact!
Expand Down
12 changes: 8 additions & 4 deletions server/src/instant/lib/ring/websocket.clj
View file
Original file line number Diff line number Diff line change
Expand Up @@ -216,9 +216,13 @@
(.unlock send-lock)))
(let [ret @p]
(when-let [tx-id (-> obj meta :tx-id)]
(e2e-tracer/invalidator-tracking-step!
{:tx-id tx-id
:name "send-json-delivered"
:attributes {:session-id (-> obj meta :session-id)}}))
(let [tx-created-at (-> obj meta :tx-created-at)]
(when-let [latency-ms (e2e-tracer/tx-latency-ms tx-created-at)]
(tracer/add-data! {:attributes {:tx-latency-ms latency-ms}}))
(e2e-tracer/invalidator-tracking-step!
{:tx-id tx-id
:tx-created-at tx-created-at
:name "send-json-delivered"
:attributes {:session-id (-> obj meta :session-id)}})))
(when (instance? Throwable ret)
(throw ret)))))))
17 changes: 11 additions & 6 deletions server/src/instant/reactive/invalidator.clj
View file
Original file line number Diff line number Diff line change
Expand Up @@ -276,17 +276,19 @@
(instant-user-model/evict-user-id-from-cache id)))

(when (and some-changes app-id)
(let [tx-id (extract-tx-id transactions-change)]
(let [tx-id (extract-tx-id transactions-change)
tx-created-at (extract-tx-created-at transactions-change)]
(e2e-tracer/invalidator-tracking-step! {:tx-id tx-id
:tx-created-at tx-created-at
:name "transform-wal-record"})
;; n.b. make sure to update combine-wal-records below if new
;; items are added to this map
{:attr-changes attrs
:ident-changes idents
:triple-changes triples
:app-id app-id
:tx-created-at (extract-tx-created-at transactions-change)
:tx-id (extract-tx-id transactions-change)
:tx-created-at tx-created-at
:tx-id tx-id
:tx-bytes tx-bytes}))))

(defn wal-record-xf
Expand Down Expand Up @@ -341,7 +343,7 @@
(.between ChronoUnit/MILLIS tx-created-at (Instant/now))))

(defn process-wal-record [process-id store-conn record-count wal-record]
(let [{:keys [app-id tx-id tx-bytes]} wal-record]
(let [{:keys [app-id tx-id tx-created-at tx-bytes]} wal-record]
(tracer/with-span! {:name "invalidator/work"
:attributes {:app-id app-id
:tx-id tx-id
Expand All @@ -351,15 +353,18 @@

(try
(let [sockets (invalidate! process-id store-conn wal-record)]
(tracer/add-data! {:attributes {:num-sockets (count sockets)}})
(tracer/add-data! {:attributes {:num-sockets (count sockets)
:tx-latency-ms (e2e-tracer/tx-latency-ms tx-created-at)}})
(e2e-tracer/invalidator-tracking-step! {:tx-id tx-id
:tx-created-at tx-created-at
:name "send-refreshes"
:attributes {:num-sockets (count sockets)}})
(tracer/with-span! {:name "invalidator/send-refreshes"}
(doseq [{:keys [id]} sockets]
(receive-queue/enqueue->receive-q {:op :refresh
:session-id id
:tx-id tx-id}))))
:tx-id tx-id
:tx-created-at tx-created-at}))))
(catch Throwable t
(def -wal-record wal-record)
(def -store-value @store-conn)
Expand Down
7 changes: 6 additions & 1 deletion server/src/instant/reactive/session.clj
View file
Original file line number Diff line number Diff line change
Expand Up @@ -170,6 +170,7 @@

(defn- handle-refresh! [store-conn sess-id event debug-info]
(e2e-tracer/invalidator-tracking-step! {:tx-id (:tx-id event)
:tx-created-at (:tx-created-at event)
:name "start-refresh"
:attributes {:session-id sess-id}})
(let [auth (get-auth! store-conn sess-id)
Expand Down Expand Up @@ -201,8 +202,10 @@
tracer-attrs {:num-recomputations num-recomputations
:num-spam num-spam
:num-computations num-computations
:dropped-spam? drop-spam?}]
:dropped-spam? drop-spam?
:tx-latency-ms (e2e-tracer/tx-latency-ms (:tx-created-at event))}]
(e2e-tracer/invalidator-tracking-step! {:tx-id (:tx-id event)
:tx-created-at (:tx-created-at event)
:name "finish-refresh-queries"
:attributes (assoc tracer-attrs
:session-id sess-id)})
Expand All @@ -215,6 +218,7 @@
:attrs attrs
:computations computations}
{:tx-id (:tx-id event)
:tx-created-at (:tx-created-at event)
:session-id sess-id}))))))

;; -----
Expand Down Expand Up @@ -591,6 +595,7 @@
(defmethod consolidate :refresh [_ batch]
(doseq [{:keys [item]} (drop-last batch)]
(e2e-tracer/invalidator-tracking-step! {:tx-id (:tx-id item)
:tx-created-at (:tx-created-at item)
:name "skipped-refresh"}))
[(-> (last batch)
(assoc :skipped-size (dec (count batch))))])
Expand Down
11 changes: 9 additions & 2 deletions server/src/instant/util/e2e_tracer.clj
View file
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@
(io.opentelemetry.sdk.trace SdkSpan)
(java.lang.reflect Field)
(java.nio ByteBuffer)
(java.time Duration Instant)
(org.apache.commons.codec.binary Hex)))

;; Starts the trace-id with a1 so that it's easy to spot
Expand Down Expand Up @@ -59,7 +60,11 @@
:entropy tx-id})]
(tracer/end-span! span))))

(defn invalidator-tracking-step! [{:keys [^Long tx-id] :as span-opts}]
(defn tx-latency-ms [^Instant tx-created-at]
(when tx-created-at
(.toMillis (Duration/between tx-created-at (Instant/now)))))

(defn invalidator-tracking-step! [{:keys [^Long tx-id tx-created-at] :as span-opts}]
;; Create a new span with a stable trace-id and span-id for the parent
(when (flags/e2e-should-honeycomb-publish? tx-id)
(binding [tracer/*span* (make-invalidator-tracking-span tx-id nil)]
Expand All @@ -71,4 +76,6 @@
{:tx-id tx-id
;; encourage honeycomb not
;; to skip this span
:entropy tx-id}))))))))
:entropy tx-id}
(when-let [latency-ms (tx-latency-ms tx-created-at)]
{:tx-latency-ms latency-ms})))))))))

0 comments on commit 09fc90c

Please sign in to comment.