git_policy_cli/
commit_timing.rs

1//! What:
2//!  The record of where one wrapped `git commit` spent its time,
3//! appended to a size-capped file in the common Git directory
4//!  beside the discard audit:
5//! preparation,
6//! building,
7//! setting up the service,
8//! reaching it,
9//! waiting for its answer,
10//! the work
11//!  after landing,
12//! the post-commit gate and the hand-over of the push.
13//! Why:
14//!  A commit that took seventeen seconds could not be split afterwards,
15//! because nothing outside verbose mode said which phase
16//!  held the time.
17//! The numbers are taken from the monotonic clock as the commit runs (one `Instant` read per phase edge,
18//! no
19//!  Git start,
20//! no flush to disk) and written once,
21//! in one append,
22//! when the command ends.
23//! The record goes to the file only:
24//!  the person's terminal never shows it.
25//!
26//! In TS you'd write (pseudocode):
27//! ```ts
28//! await appendFile(join(commonDir, 'cli-git-commit-timing.jsonl'), JSON.stringify(timing) + '\n');
29//! ```
30
31use super::diagnostic_log::debug;
32use super::discard_audit::append_line;
33use super::json_record::{quote, string_array};
34use super::service_instance::instance_of;
35use super::service_protocol::RELEASE;
36use std::path::{Path, PathBuf};
37use std::time::{Duration, Instant};
38
39/// The file inside the common Git directory that collects the timing records of every worktree of the repository.
40/// It moves
41///  aside to `cli-git-commit-timing.jsonl.1` at the size limit `discard_audit::append_line` applies.
42pub const TIMING_FILE: &str = "cli-git-commit-timing.jsonl";
43
44/// The version of the record's fields;
45/// it changes only when a field's meaning changes,
46/// never when a field is added.
47pub const TIMING_SCHEMA_VERSION: u32 = 1;
48
49/// Module tag for diagnostics.
50const TAG: &str = "commitTiming";
51
52/// The word written for a release a service did not announce (the services of the earliest releases sent no release).
53const UNANNOUNCED: &str = "unannounced";
54
55/// What:
56///  What the client did to reach a service that speaks its protocol and was started from its release.
57/// Why:
58///   The 17-second commit began with a service of another release being asked to retire;
59/// the tries,
60/// the wait for a start,
61/// the
62///  retires sent and the releases that answered tell that apart from a slow landing.
63///
64/// In TS you'd write (pseudocode):
65/// ```ts
66/// type ReachTrace = { tries: number; refused: number; startWaited: number; retiresSent: number; releasesSeen: string[]; answeredBy?: string };
67/// ```
68#[derive(Clone, Debug, Default, Eq, PartialEq)]
69pub struct ReachTrace {
70    /// Connection attempts made,
71    /// each one a `connect` call.
72    pub tries: usize,
73    /// Attempts that found nothing listening or no greeting,
74    /// which is the service being started by the manager.
75    pub refused: usize,
76    /// Time from the first attempt of a reach to the greeting,
77    /// summed over the reaches that needed more than one attempt.
78    pub start_waited: Duration,
79    /// Retire messages sent to services of another release.
80    pub retires_sent: usize,
81    /// The release of every greeting,
82    /// in the order received,
83    /// without repeats.
84    pub releases_seen: Vec<String>,
85    /// The release of the service that finally took the request.
86    pub answered_by: Option<String>,
87    /// Time spent reaching,
88    /// retire rounds included.
89    pub elapsed: Duration,
90}
91
92impl ReachTrace {
93    /// Notes the release a greeting named.
94    pub fn saw_release(&mut self, release: Option<&str>) {
95        let word: String = release.unwrap_or(UNANNOUNCED).to_string();
96        if !self.releases_seen.contains(&word) {
97            self.releases_seen.push(word);
98        }
99    }
100}
101
102/// What:
103///  What the client did to hand one request to the service and get its answer.
104/// Why:
105///   The queue wait,
106/// the wait for a foreign index lock and the landing itself all happen between the send and the answer;
107///  the service's own log line for the request splits that wait,
108/// and this record says how long the whole of it was.
109///
110/// In TS you'd write (pseudocode):
111/// ```ts
112/// type SubmitTrace = { total: number; reach: ReachTrace; answerWait: number; positions: number[]; waitingNotices: number };
113/// ```
114#[derive(Clone, Debug, Default, Eq, PartialEq)]
115pub struct SubmitTrace {
116    /// The whole of the sends,
117    /// reaches included.
118    pub total: Duration,
119    /// How the service was reached.
120    pub reach: ReachTrace,
121    /// Time from a request being written to the answer (or the connection breaking),
122    /// summed over the sends.
123    pub answer_wait: Duration,
124    /// The queue positions the service reported,
125    /// in order,
126    /// without repeats.
127    pub positions: Vec<usize>,
128    /// Notices the service sent while it waited for another program's hold on the index.
129    pub waiting_notices: usize,
130    /// Times the connection broke before an answer and the same request was sent again.
131    pub reconnects: usize,
132    /// Requests written.
133    pub sends: usize,
134}
135
136/// What:
137///  The common Git directory of a worktree's own Git directory:
138/// the directory its `commondir` file names,
139/// else the directory
140///  itself.
141/// Why:
142///   A linked worktree's own Git directory goes away with the worktree,
143/// while the repository's one timing file lives in the
144///  common directory.
145/// The service's review module reads the file the same way (Git strips every trailing carriage return and
146///  line feed and resolves a relative path against the Git directory),
147/// but that module belongs to the service run and the client
148///  path may not name it (`standards_review_boundary_tests.rs`),
149/// so the few lines are repeated here.
150/// A path that cannot be
151///  resolved is used as written.
152///
153/// In TS you'd write (pseudocode):
154/// ```ts
155/// existsSync(join(gitDir, 'commondir')) ? realpath(resolve(gitDir, readFile(...).trimEnd())) : gitDir
156/// ```
157fn common_dir_for(git_dir: &Path) -> PathBuf {
158    let Ok(text) = std::fs::read_to_string(git_dir.join("commondir")) else {
159        return git_dir.to_path_buf();
160    };
161    let named: &str = text.trim_end_matches(['\r', '\n']);
162    if named.is_empty() {
163        return git_dir.to_path_buf();
164    }
165    let joined: PathBuf = git_dir.join(named);
166    return std::fs::canonicalize(&joined).unwrap_or(joined);
167}
168
169/// Where the record goes and which service instance it belongs to.
170#[derive(Clone, Debug, Eq, PartialEq)]
171struct Place {
172    /// The worktree's own Git directory.
173    git_dir: PathBuf,
174    /// The common Git directory,
175    /// which holds the file.
176    common_dir: PathBuf,
177    /// The instance name that `journalctl --user --unit=cli-git@<instance>.service` takes.
178    instance: String,
179}
180
181/// The whole milliseconds of a duration.
182fn whole_milliseconds(elapsed: Duration) -> u128 {
183    return elapsed.as_millis();
184}
185
186/// The JSON word for a field that has no value.
187fn null_word() -> String {
188    return String::from("null");
189}
190
191impl Place {
192    /// The instance as a JSON string.
193    fn instance_json(&self) -> String {
194        return quote(self.instance.as_str());
195    }
196
197    /// The worktree's own Git directory as a JSON string.
198    fn git_dir_json(&self) -> String {
199        return quote(&self.git_dir.to_string_lossy());
200    }
201}
202
203/// What:
204///  The phases of one wrapped commit,
205/// filled as the commit runs and written when it ends.
206/// Why:
207///   Each field is one disjoint stretch of the command,
208/// so the phases add up to no more than the total,
209/// and what they do not
210///  cover is reported as `otherMs` instead of being hidden.
211///
212/// In TS you'd write (pseudocode):
213/// ```ts
214/// type CommitTiming = { began: number; prepare: number; build: number; provision: number; submit: SubmitTrace; /* ... */ };
215/// ```
216#[derive(Clone, Debug)]
217pub struct CommitTiming {
218    /// The monotonic start.
219    began: Instant,
220    /// Milliseconds since the Unix epoch at the start,
221    /// for finding the commit among the service's journal lines.
222    start_millis: u128,
223    /// Known once the worktree's Git directory was found.
224    place: Option<Place>,
225    /// The branch (or `HEAD`) the first preparation found.
226    pub reference: Option<String>,
227    /// How the command ended:
228    /// `landed`,
229    /// `ended` (blocked or declined,
230    /// nothing landed) or `stopped` (a failure).
231    pub outcome: &'static str,
232    /// Preparations made:
233    /// one,
234    /// and one more for each time the service sent the commit back or Git built it again.
235    pub attempts: usize,
236    /// Policies,
237    /// hooks,
238    /// the private index,
239    /// the tree and the objects of the commit,
240    /// summed over the attempts.
241    pub prepare: Duration,
242    /// The message,
243    /// the identities,
244    /// the tree check and Git's own build of the commit,
245    /// with the scratch hand-over.
246    pub build: Duration,
247    /// Setting up socket activation,
248    /// which is the manager's unit comparison and,
249    /// after an upgrade,
250    /// a rewrite and a reload.
251    pub provision: Duration,
252    /// Sending the request and waiting for the answer.
253    pub submit: SubmitTrace,
254    /// The summary line,
255    /// the names it needs,
256    /// and the files a policy corrected,
257    /// after the branch moved.
258    pub after_landing: Duration,
259    /// The post-commit gate.
260    pub gate: Duration,
261    /// Leaving the push and the upkeep for the service and waking it.
262    pub handoff: Duration,
263}
264
265impl CommitTiming {
266    /// Starts the clocks:
267    /// the monotonic one for the durations and the wall clock for the stamp.
268    pub fn start() -> Self {
269        let start_millis: u128 = std::time::SystemTime::now()
270            .duration_since(std::time::UNIX_EPOCH)
271            .map(whole_milliseconds)
272            .unwrap_or_default();
273        return Self {
274            began: Instant::now(),
275            start_millis,
276            place: None,
277            reference: None,
278            outcome: "stopped",
279            attempts: 0,
280            prepare: Duration::ZERO,
281            build: Duration::ZERO,
282            provision: Duration::ZERO,
283            submit: SubmitTrace::default(),
284            after_landing: Duration::ZERO,
285            gate: Duration::ZERO,
286            handoff: Duration::ZERO,
287        };
288    }
289
290    /// Names the worktree whose Git directory the command found;
291    /// a command outside a repository writes no record.
292    pub fn place_at(&mut self, git_dir: &Path) {
293        self.place = Some(Place { git_dir: git_dir.to_path_buf(), common_dir: common_dir_for(git_dir), instance: instance_of(git_dir) });
294    }
295
296    /// What the phases leave uncovered out of `total`.
297    fn other(&self, total: Duration) -> Duration {
298        let covered: Duration = self.prepare + self.build + self.provision + self.submit.total + self.after_landing + self.gate + self.handoff;
299        return total.saturating_sub(covered);
300    }
301
302    /// What:
303    ///  The record as one line of JSON ending in a newline.
304    /// Why:
305    ///   One `write` call per line keeps lines of concurrent commits from interleaving;
306    /// a branch name with a quote or a
307    ///  newline is escaped by `quote`,
308    /// so the line stays one line.
309    ///
310    /// In TS you'd write (pseudocode):
311    /// ```ts
312    /// JSON.stringify(record) + '\n'
313    /// ```
314    pub fn line(&self, total: Duration, exit_code: i32) -> String {
315        let place: Option<&Place> = self.place.as_ref();
316        let branch: String = self.reference.as_deref().map_or_else(null_word, quote);
317        let answered_by: String = self.submit.reach.answered_by.as_deref().map_or_else(null_word, quote);
318        let positions: Vec<String> = self.submit.positions.iter().map(usize::to_string).collect();
319        return format!(
320            "{{\"schemaVersion\":{TIMING_SCHEMA_VERSION},\"startMillis\":{},\"pid\":{},\"release\":{},\"instance\":{},\"gitDir\":{},\
321             \"branch\":{branch},\"outcome\":{},\"exitCode\":{exit_code},\"totalMs\":{},\
322             \"prepareMs\":{},\"attempts\":{},\"buildMs\":{},\"provisionMs\":{},\
323             \"submitMs\":{},\"sends\":{},\"reachMs\":{},\"connectTries\":{},\"refusedConnects\":{},\"startWaitMs\":{},\
324             \"updateRounds\":{},\"releasesSeen\":{},\"answeredByRelease\":{answered_by},\
325             \"answerWaitMs\":{},\"positions\":[{}],\"waitingNotices\":{},\"reconnects\":{},\
326             \"afterLandingMs\":{},\"gateMs\":{},\"handoffMs\":{},\"otherMs\":{}}}\n",
327            self.start_millis,
328            std::process::id(),
329            quote(RELEASE),
330            place.map_or_else(null_word, Place::instance_json),
331            place.map_or_else(null_word, Place::git_dir_json),
332            quote(self.outcome),
333            total.as_millis(),
334            self.prepare.as_millis(),
335            self.attempts,
336            self.build.as_millis(),
337            self.provision.as_millis(),
338            self.submit.total.as_millis(),
339            self.submit.sends,
340            self.submit.reach.elapsed.as_millis(),
341            self.submit.reach.tries,
342            self.submit.reach.refused,
343            self.submit.reach.start_waited.as_millis(),
344            self.submit.reach.retires_sent,
345            string_array(self.submit.reach.releases_seen.as_slice()),
346            self.submit.answer_wait.as_millis(),
347            positions.join(","),
348            self.submit.waiting_notices,
349            self.submit.reconnects,
350            self.after_landing.as_millis(),
351            self.gate.as_millis(),
352            self.handoff.as_millis(),
353            self.other(total).as_millis(),
354        );
355    }
356
357    /// What:
358    ///  Appends the record to the repository's timing file,
359    /// best effort.
360    /// Why:
361    ///   The command's result never depends on the record:
362    /// a file that cannot be written is only a debug line.
363    /// The directory
364    ///  is never created,
365    /// and nothing is flushed to disk,
366    /// so the record costs one `write`.
367    ///
368    /// In TS you'd write (pseudocode):
369    /// ```ts
370    /// recordTiming(timing, exitCode)
371    /// ```
372    pub fn finish(&self, exit_code: i32) {
373        let Some(place) = self.place.as_ref() else { return };
374        let target: PathBuf = place.common_dir.join(TIMING_FILE);
375        let line: String = self.line(self.began.elapsed(), exit_code);
376        if let Err(error) = append_line(target.as_path(), line.as_bytes()) {
377            debug(TAG, &format!("the timing record could not be written to {}: {error}", target.display()));
378        }
379    }
380}
381
382/// The line,
383/// the sum rule,
384/// and the escaping.
385#[cfg(test)]
386#[path = "commit_timing_tests.rs"]
387mod tests;
git_policy_cli/commit_timing.rs

git_policy_cli/
commit_timing.rs
