diff --git a/backend/resources/climit.edn b/backend/resources/climit.edn index c109b2afdb..6e3e40f73c 100644 --- a/backend/resources/climit.edn +++ b/backend/resources/climit.edn @@ -57,4 +57,120 @@ {:permits 4} :profile-plugin-ops/by-profile - {:permits 1 :queue 2}} + {:permits 1 :queue 2} + + ;; Every limit below is provisional. The container that runs the preview + ;; has no heap cap: `docker/devenv/files/entrypoint.sh` and + ;; `backend/scripts/_env` both replace JAVA_OPTS without `-Xmx`, and the + ;; live JVM command line carries none, so the budget is the JVM default + ;; and it is unmeasured. The permit counts are derived from the + ;; neighbours above instead of from a memory figure, and they stay + ;; provisional until a peak-heap measurement of a cold compare on the + ;; design-system file replaces them. + ;; + ;; The anchor is the snapshot pair above: `:create-file-snapshot/global` + ;; admits three whole-file operations at once, each realizing one + ;; document and writing one snapshot, and `:restore-file-snapshot/global` + ;; admits the same three for an operation that also writes a rollback + ;; snapshot and the older payload back into the file. A branch operation + ;; realizes more than one document, so it has to admit fewer at once to + ;; keep the same number of realized documents in flight. + ;; + ;; What each operation holds, read from the code: + ;; * `create-file-branch` realizes main once and writes one snapshot + ;; (`backend/src/app/rpc/commands/files_branch.clj::create-file-branch`), + ;; which is the anchor's shape and the anchor's cost. + ;; * `merge-file-branch` and `update-branch-from-main` hold three + ;; realized documents at once: main, the derived branch, and the base + ;; snapshot (`files_branch.clj::merge-file-branch`, + ;; `files_branch.clj::update-branch-from-main`). Both also write a + ;; snapshot and a whole file payload, and the update computes a + ;; second diff for the squash, so they earn the tightest count. + ;; * `materialize-file-branch` realizes the branch and the libraries it + ;; validates against, then writes the whole payload + ;; (`files_branch.clj::materialize-file-branch`), so it sits between + ;; the anchor and the merge pair. + ;; * `create-pull-request` and `update-pull-request-snapshot` realize the + ;; branch once and write one review snapshot + ;; (`files_pull_request.clj::create-pull-request`, + ;; `files_pull_request.clj::update-pull-request-snapshot`), which is + ;; the anchor's shape again. + ;; + ;; The write-side operations carry a queue and a timeout so that a + ;; refusal follows a bounded wait rather than arriving instantly. The + ;; queue sits on the per-profile entry, following the anchor, and on the + ;; global entry where the command declares no per-profile queue. The + ;; per-profile entry of one permit keeps a single designer to one + ;; operation at a time. The two read-side entries are generous by design + ;; and carry no queue and no timeout, so a panel open waits for its turn + ;; instead of being refused: six three-document comparisons hold + ;; eighteen realized documents, fewer than the twenty one-document saves + ;; `:update-file/global` already admits. + + ;; create-file-branch realizes main and writes one snapshot, the shape + ;; of `:create-file-snapshot` above, so it takes the anchor's numbers + ;; unchanged. Provisional. + :create-file-branch/global + {:permits 3} + + :create-file-branch/by-profile + {:permits 1 :queue 2 :timeout 60000} + + ;; A merge holds three realized documents, a snapshot write, and a + ;; whole-file write into main, so one instance-wide operation holds the + ;; anchor's whole three-permit budget on its own. Provisional. + :merge-file-branch/global + {:permits 1} + + :merge-file-branch/by-profile + {:permits 1 :queue 2 :timeout 60000} + + ;; An update from main holds the same three documents and pays for a + ;; snapshot write and a squash diff on top, so it takes the merge's + ;; count. Provisional. + :update-branch-from-main/global + {:permits 1} + + :update-branch-from-main/by-profile + {:permits 1 :queue 2 :timeout 60000} + + ;; Materialize realizes one document plus its libraries and writes the + ;; payload, which is cheaper than a merge and dearer than the anchor, + ;; so it admits two where the merge admits one and the anchor admits + ;; three. Provisional. + :materialize-file-branch/global + {:permits 2} + + :materialize-file-branch/by-profile + {:permits 1 :queue 2 :timeout 60000} + + ;; A cold listing realizes main once and derives every uncached branch, + ;; which makes it the slowest read of the preview. Six at once is above + ;; what a panel open needs under normal use, and six three-document + ;; operations hold eighteen realized documents, below the twenty + ;; one-document saves `:update-file/global` above already admits. + ;; Provisional. + :get-file-branches/global + {:permits 6} + + ;; The compare dialog's query holds main, the derived branch, and the + ;; base at once, the same three documents the listing holds, so it takes + ;; the same count. Provisional. + :get-branch-diff/global + {:permits 6} + + ;; Creating a pull request realizes the branch and pins one review + ;; snapshot, the anchor's shape. Provisional. + :create-pull-request/global + {:permits 3} + + :create-pull-request/by-profile + {:permits 1 :queue 2 :timeout 60000} + + ;; Publishing the branch state also realizes the branch and pins one + ;; snapshot. The command declares a single instance-wide queue + ;; (`files_pull_request.clj::update-pull-request-snapshot`), so the + ;; bounded wait sits on the global entry here rather than on a + ;; per-profile entry. Provisional. + :update-pull-request-snapshot/global + {:permits 3 :queue 4 :timeout 60000}} diff --git a/backend/src/app/binfile/common.clj b/backend/src/app/binfile/common.clj index a0704aa0fe..712f87df3f 100644 --- a/backend/src/app/binfile/common.clj +++ b/backend/src/app/binfile/common.clj @@ -315,9 +315,21 @@ Returns the file with `:data` decoded (plain maps); callers that asked for `:decode? false` get it re-encoded as bytes so the update-file - pipeline (which always blob-decodes) is unaffected." + pipeline (which always blob-decodes) is unaffected. + + This function carries the whole cost of reading a branch: the file row + stores no payload, so every open pays the base load and the replay. It + therefore reports its own duration and the depth of the log it + replayed, because the depth is what predicts the cost, and the depth is + the quantity `files_branch.clj::check-oplog-depth-limit!` gates. The + same numbers travel on the returned file's metadata as `::audit/props`, + so the RPC command that paid for the derive reports them on its own + audit event. An ordinary file read never reaches this function, so an + ordinary read neither times nor logs anything." [{:keys [::db/conn] :as cfg} {:keys [id] :as file} decode?] - (let [branch (db/get* conn :file-branch {:branch-file-id id}) + (let [tpoint (ct/tpoint) + + branch (db/get* conn :file-branch {:branch-file-id id}) _ (when (nil? branch) (ex/raise :type :not-found @@ -355,12 +367,31 @@ rows (db/exec! conn [sql:get-branch-changes id]) - data (reduce (fn [data {:keys [changes]}] - (cpc/process-changes data (blob/decode changes))) - (:data base) - rows) + ;; the derive replays the log batch by batch, so each batch is + ;; decoded exactly once. `depth` is the flattened op count, the + ;; quantity `files_branch.clj::check-oplog-depth-limit!` limits, + ;; and the one that predicts the cost of the replay. + [data depth] + (reduce (fn [[data depth] {:keys [changes]}] + (let [changes (blob/decode changes)] + [(cpc/process-changes data changes) + (+ depth (count changes))])) + [(:data base) 0] + rows) + + data (if decode? data (blob/encode data)) + + ;; measured once so the log line and the audit props carry the same + ;; number. The timer covers the re-encode as well when the caller + ;; asked for raw bytes: that encode is part of what it waits for. + duration (inst-ms (tpoint))] + + (l/inf :hint "branch file derive" + :file-id (str id) + :oplog-depth depth + :oplog-batches (count rows) + :duration-ms duration) - data (if decode? data (blob/encode data))] (-> file ;; the derived data is the BASE's data plus the op log, so the ;; file carries the base's version and migration set; this keeps @@ -370,7 +401,17 @@ (assoc :data data) (assoc :version (or (:version base) (:version file))) (cond-> (some? (:migrations base)) - (assoc :migrations (:migrations base)))))) + (assoc :migrations (:migrations base))) + ;; the numbers travel with the value, because the RPC audit event + ;; of the read that paid for this derive reads `::audit/props` off + ;; the result metadata + ;; (`app/loggers/audit.clj::prepare-rpc-event`), and a branch open + ;; returns exactly this file. An ordinary file never reaches this + ;; function, so an ordinary read attaches nothing. + (vary-meta assoc ::audit/props + {:branch-derive-ms duration + :branch-oplog-depth depth + :branch-oplog-batches (count rows)})))) (defn- get-file* [{:keys [::db/conn] :as cfg} id {:keys [migrate? diff --git a/backend/src/app/rpc/commands/files_branch.clj b/backend/src/app/rpc/commands/files_branch.clj index d5653f05b4..eff6c48db7 100644 --- a/backend/src/app/rpc/commands/files_branch.clj +++ b/backend/src/app/rpc/commands/files_branch.clj @@ -152,17 +152,29 @@ ;; operation attaches it to its own event. (defn- audited - "Attach `:duration-ms` and `:outcome` to the audit event of a branch - operation. `result` is returned unchanged to the caller." - [result tpoint operation] - (let [duration (inst-ms (tpoint))] - (l/inf :hint "branch operation" :operation (name operation) - :outcome (name (or (:status result) :ok)) - :duration duration) - (vary-meta result update ::audit/props merge - {:branch-operation (name operation) - :branch-outcome (name (or (:status result) :ok)) - :branch-duration-ms duration}))) + "Attach the `:duration-ms` and `:outcome` props to the audit event of a + branch operation, and print the matching log line. `result` is returned + unchanged to the caller, and `extra` lets an operation add numbers of + its own to the same record. + + A listing returns a vector rather than a map, and a vector carries + metadata exactly like the maps the other commands return, so the props + reach the audit middleware (`app/loggers/audit.clj::prepare-rpc-event` + reads `(meta result)`) the way they always have. Nothing between the + handler and that middleware rebuilds the value." + ([result tpoint operation] + (audited result tpoint operation nil)) + ([result tpoint operation extra] + (let [duration (inst-ms (tpoint)) + outcome (name (or (:status result) :ok))] + (l/inf :hint "branch operation" :operation (name operation) + :outcome outcome + :duration duration) + (vary-meta result update ::audit/props merge + (cond-> {:branch-operation (name operation) + :branch-outcome outcome + :branch-duration-ms duration} + (seq extra) (merge extra)))))) ;; --- Helpers: media pairing ;; @@ -663,6 +675,12 @@ in-sync branches skip the diff entirely; `main` is realized once and shared across branches. + A cold listing is one of the slowest things a user meets, so the listing + reports its own duration to `audit_log` and to the log, together with + the two numbers that explain that duration: how many open diverged + branches it had to look a comparison up for, and how many of those the + summary cache answered without computing anything. + The per-branch summary is cached by `(base-snapshot-id, source-revn, branch-revn)`: a repeated listing with no intervening save performs no comparison work, and the tuple names exactly the inputs the computation @@ -670,32 +688,40 @@ The pull-request listing reads the same cache, so either surface can arrive warm." {::doc/added "2.16" - ::sm/params schema:get-file-branches} + ::sm/params schema:get-file-branches + ::climit/id [[:get-file-branches/global]]} [cfg {:keys [::rpc/profile-id file-id include-archived]}] (check-branching-enabled!) (db/run! cfg (fn [{:keys [::db/conn] :as cfg}] (files/check-read-permissions! cfg profile-id file-id) - (let [rows (db/exec! conn [sql:get-file-branches file-id (boolean include-archived)]) + (let [tpoint (ct/tpoint) + rows (db/exec! conn [sql:get-file-branches file-id (boolean include-archived)]) ;; only OPEN branches get diff counts: merged/archived ones ;; are not going to be merged as-is, so the expensive diff ;; would be wasted work (and their base may be released) open? (fn [row] (= "open" (:status row))) - ;; realize main once, only if some open branch diverged - ;; AND its summary is not cached - need? (some (fn [r] (and (open? r) - (nil? (cached-summary r)) - (let [[a b] (revn-deltas r)] (or (pos? a) (pos? b))))) - rows) - main-data (when need? (:data (bfc/get-file cfg file-id :realize? true)))] - (mapv (fn [row] - (let [[ahead behind conflicts] (if (open? row) - (cached-diff-counts cfg main-data row) - [0 0 0])] - (-> row - (assoc :ahead ahead :behind behind :conflicts conflicts) - (dissoc :branch-revn :source-revn :base-snapshot-id :base-branch-revn)))) - rows))))) + ;; an open branch whose cheap revn deltas say it diverged is + ;; the only one the listing looks a comparison up for + diverged? (fn [row] (let [[a b] (revn-deltas row)] (or (pos? a) (pos? b)))) + compared (filterv (fn [row] (and (open? row) (diverged? row))) rows) + ;; the rows the summary cache answers without computing + cached (filterv (comp some? cached-summary) compared) + ;; realize main once, only if some compared branch is not + ;; already cached + need? (< (count cached) (count compared)) + main-data (when need? (:data (bfc/get-file cfg file-id :realize? true))) + branches (mapv (fn [row] + (let [[ahead behind conflicts] (if (open? row) + (cached-diff-counts cfg main-data row) + [0 0 0])] + (-> row + (assoc :ahead ahead :behind behind :conflicts conflicts) + (dissoc :branch-revn :source-revn :base-snapshot-id :base-branch-revn)))) + rows)] + (audited branches tpoint :list-branches + {:branches-compared (count compared) + :branches-cached (count cached)}))))) ;; --- COMMAND QUERY: get-branch-diff @@ -716,6 +742,7 @@ later refinement." {::doc/added "2.16" ::sm/params schema:get-branch-diff + ::climit/id [[:get-branch-diff/global]] ::db/transaction true} [{:keys [::db/conn] :as cfg} {:keys [::rpc/profile-id branch-id direction]}] (check-branching-enabled!) @@ -787,7 +814,8 @@ {::doc/added "2.16" ::webhooks/event? true ::sm/params schema:merge-file-branch - ::climit/id [[:merge-file-branch/global]]} + ::climit/id [[:merge-file-branch/by-profile ::rpc/profile-id] + [:merge-file-branch/global]]} [{:keys [::mbus/msgbus] :as cfg} {:keys [::rpc/profile-id ::rpc/session-id branch-id resolutions expected-main-revn keep-branch]}] (check-branching-enabled!) @@ -1010,7 +1038,8 @@ {::doc/added "2.16" ::webhooks/event? true ::sm/params schema:update-branch-from-main - ::climit/id [[:update-branch-from-main/global]]} + ::climit/id [[:update-branch-from-main/by-profile ::rpc/profile-id] + [:update-branch-from-main/global]]} [{:keys [::mbus/msgbus] :as cfg} {:keys [::rpc/profile-id ::rpc/session-id branch-id resolutions]}] (check-branching-enabled!) @@ -1226,7 +1255,8 @@ {::doc/added "2.16" ::webhooks/event? true ::sm/params schema:materialize-file-branch - ::climit/id [[:materialize-file-branch/global]]} + ::climit/id [[:materialize-file-branch/by-profile ::rpc/profile-id] + [:materialize-file-branch/global]]} [cfg {:keys [::rpc/profile-id file-id]}] (check-branching-enabled!) (files/check-edition-permissions! cfg profile-id file-id) diff --git a/backend/src/app/rpc/commands/files_update.clj b/backend/src/app/rpc/commands/files_update.clj index a6ed200c83..e559bc2411 100644 --- a/backend/src/app/rpc/commands/files_update.clj +++ b/backend/src/app/rpc/commands/files_update.clj @@ -149,7 +149,17 @@ (files/check-edition-permissions! conn profile-id id) (db/xact-lock! conn id) - (let [file (get-file cfg id) + ;; The timer starts BEFORE `get-file`. A branch file stores no payload, + ;; so that read folds the merge-base snapshot and the op log into the + ;; derived document, and every other branch command (compare, merge, + ;; update-from-main, materialize) creates its timer ahead of its own + ;; file reads. Starting here puts a branch save's `branch-duration-ms` + ;; on the same footing as theirs: the number covers the read, and for a + ;; branch the derive inside it, as well as the rest of the save. The + ;; trace below covers the read for an ordinary save as well, which is + ;; what the request actually cost. + (let [tpoint (ct/tpoint) + file (get-file cfg id) team (teams/get-team conn :profile-id profile-id :team-id (:team-id file)) @@ -169,9 +179,7 @@ (assoc :file file) (assoc :changes changes)) - cfg (assoc cfg ::timestamp (ct/now)) - - tpoint (ct/tpoint)] + cfg (assoc cfg ::timestamp (ct/now))] (when (not= (:vern params) (:vern file)) @@ -223,7 +231,9 @@ `tpoint` is the request's own timer, threaded in so that a save routed to a branch's op log can report its duration on the audit event the way - the other branch commands do. + the other branch commands do. The timer is started by `update-file` + before it reads the file, so a branch save's number includes the derive + that every other branch command includes too. Only intended for internal use on this module." [{:keys [::db/conn ::timestamp] :as cfg} @@ -289,23 +299,33 @@ ;; Send asynchronous notifications (send-notifications! cfg params file) - (with-meta {:revn revn :lagged (get-lagged-changes conn params)} - {::audit/replace-props - (cond-> {:id (:id file) - :name (:name file) - :features (:features file) - :project-id (:project-id file) - :team-id (:team-id file)} + (let [branch? (:is-branch file) + duration (inst-ms (tpoint))] - ;; A save routed to a branch's op log is the preview's most - ;; frequent operation, so it reports its duration and outcome on - ;; its own audit event like every other branch command. The - ;; ordinary save path is untouched: the props above are the ones - ;; it has always carried. - (:is-branch file) - (assoc :branch-operation "save-branch" - :branch-outcome "saved" - :branch-duration-ms (inst-ms (tpoint))))})))) + ;; A save routed to a branch's op log is the preview's most + ;; frequent operation, so it reports its duration and outcome in + ;; the log exactly like the other branch commands print theirs. + ;; Without this line the backend log shows five operation kinds + ;; where the audit table records six. An ordinary save prints + ;; nothing at all. + (when branch? + (l/inf :hint "branch operation" :operation "save-branch" + :outcome "saved" :duration duration)) + + (with-meta {:revn revn :lagged (get-lagged-changes conn params)} + {::audit/replace-props + (cond-> {:id (:id file) + :name (:name file) + :features (:features file) + :project-id (:project-id file) + :team-id (:team-id file)} + + ;; The ordinary save path is untouched: the props above are + ;; the ones it has always carried. + branch? + (assoc :branch-operation "save-branch" + :branch-outcome "saved" + :branch-duration-ms duration))}))))) (defn get-file "Get not-decoded file, only decodes the features set." diff --git a/backend/test/backend_tests/helpers.clj b/backend/test/backend_tests/helpers.clj index 13ac46cf66..ed4bcb1acd 100644 --- a/backend/test/backend_tests/helpers.clj +++ b/backend/test/backend_tests/helpers.clj @@ -325,19 +325,25 @@ ([params] (update-file* *system* params)) ([system {:keys [file-id changes session-id profile-id revn] :or {session-id (uuid/next) revn 0}}] - (-> system - (assoc ::files.update/timestamp (ct/now)) - (db/tx-run! (fn [{:keys [::db/conn] :as system}] - (let [file (files.update/get-file conn file-id)] - (#'files.update/update-file* system - {:id file-id - :revn revn - :vern 0 - :file file - :features (:features file) - :changes changes - :session-id session-id - :profile-id profile-id}))))))) + ;; `update-file*` takes the request's own timer, so that a save routed + ;; to a branch's op log can report its duration on the audit event the + ;; way the other branch commands do. A test drives the private fn + ;; directly, so it opens the timer the RPC method would have opened. + (let [tpoint (ct/tpoint)] + (-> system + (assoc ::files.update/timestamp (ct/now)) + (db/tx-run! (fn [{:keys [::db/conn] :as system}] + (let [file (files.update/get-file conn file-id)] + (#'files.update/update-file* system + {:id file-id + :revn revn + :vern 0 + :file file + :features (:features file) + :changes changes + :session-id session-id + :profile-id profile-id} + tpoint)))))))) (declare command!)