git_policy_cli/commit/

commit_timing.rs

//! What:
//!  The record of where one wrapped `git commit` spent its time,
//! appended to a size-capped file in the common Git directory
//!  beside the discard audit:
//! preparation,
//! building,
//! setting up the service,
//! reaching it,
//! waiting for its answer,
//! the work
//!  after landing,
//! the post-commit gate and the hand-over of the push.
//! Why:
//!  A commit that took seventeen seconds could not be split afterwards,
//! because nothing outside verbose mode said which phase
//!  held the time.
//! The numbers are taken from the monotonic clock as the commit runs (one `Instant` read per phase edge,
//! no
//!  Git start,
//! no flush to disk) and written once,
//! in one append,
//! when the command ends.
//! The record goes to the file only:
//!  the person's terminal never shows it.
//!
//! In TS you'd write (pseudocode):
//! ```ts
//! await appendFile(join(commonDir, 'cli-git-commit-timing.jsonl'), JSON.stringify(timing) + '\n');
//! ```

use crate::diagnostic_log::debug;
use crate::discard_audit::append_line;
use crate::iso_time::now_iso;
use crate::json_record::{quote, string_array};
use crate::quiet_ledger::{drain, longest_healthy, object_json};
use crate::service_instance::instance_of;
use crate::service_protocol::RELEASE;
use std::path::{Path, PathBuf};
use std::time::{Duration, Instant};

/// The file inside the common Git directory that collects the timing records of every worktree of the repository.
/// It moves
///  aside to `cli-git-commit-timing.jsonl.1`, replacing the older one (a timing log keeps one generation), at the size limit
///  `discard_audit::append_line` applies.
pub const TIMING_FILE: &str = "cli-git-commit-timing.jsonl";

/// The version of the record's fields;
/// it changes only when a field's meaning changes,
/// never when a field is added.
pub const TIMING_SCHEMA_VERSION: u32 = 1;

/// Module tag for diagnostics.
const TAG: &str = "commitTiming";

/// The word written for a release a service did not announce (the services of the earliest releases sent no release).
const UNANNOUNCED: &str = "unannounced";

/// What:
///  What the client did to reach a service that speaks its protocol and was started from its release.
/// Why:
///   The 17-second commit began with a service of another release being asked to retire;
/// the tries,
/// the wait for a start,
/// the
///  retires sent and the releases that answered tell that apart from a slow landing.
///
/// In TS you'd write (pseudocode):
/// ```ts
/// type ReachTrace = { tries: number; refused: number; startWaited: number; retiresSent: number; releasesSeen: string[]; answeredBy?: string };
/// ```
#[derive(Clone, Debug, Default, Eq, PartialEq)]
pub struct ReachTrace {
    /// Connection attempts made,
    /// each one a `connect` call.
    pub tries: usize,
    /// Attempts that found nothing listening or no greeting,
    /// which is the service being started by the manager.
    pub refused: usize,
    /// Time from the first attempt of a reach to the greeting,
    /// summed over the reaches that needed more than one attempt.
    pub start_waited: Duration,
    /// Retire messages sent to services of another release.
    pub retires_sent: usize,
    /// The release of every greeting,
    /// in the order received,
    /// without repeats.
    pub releases_seen: Vec<String>,
    /// The release of the service that finally took the request.
    pub answered_by: Option<String>,
    /// Time spent reaching,
    /// retire rounds included.
    pub elapsed: Duration,
}

impl ReachTrace {
    /// Notes the release a greeting named.
    pub fn saw_release(&mut self, release: Option<&str>) {
        let word: String = release.unwrap_or(UNANNOUNCED).to_string();
        if !self.releases_seen.contains(&word) {
            self.releases_seen.push(word);
        }
    }
}

/// What:
///  What a waiting notice of the service says of the holder of the index lock.
/// Why:
///   The notice is the only thing about the holder that reaches the client,
/// and the record should say whether the wait was for a process proven to hold the lock or for one nobody could prove alive.
///
/// In TS you'd write (pseudocode):
/// ```ts
/// holderKindOf(text) // 'proven-alive' | 'unproven'
/// ```
pub fn holder_kind_of(text: &str) -> &'static str {
    return if text.contains("(proven by ") { "proven-alive" } else { "unproven" };
}

/// What:
///  What the client did to hand one request to the service and get its answer.
/// Why:
///   The queue wait,
/// the wait for a foreign index lock and the landing itself all happen between the send and the answer;
///  the service's own log line for the request splits that wait,
/// and this record says how long the whole of it was.
///
/// In TS you'd write (pseudocode):
/// ```ts
/// type SubmitTrace = { total: number; reach: ReachTrace; answerWait: number; positions: number[]; waitingNotices: number; holderKind?: string };
/// ```
#[derive(Clone, Debug, Default, Eq, PartialEq)]
pub struct SubmitTrace {
    /// The whole of the sends,
    /// reaches included.
    pub total: Duration,
    /// How the service was reached.
    pub reach: ReachTrace,
    /// Time from a request being written to the answer (or the connection breaking),
    /// summed over the sends.
    pub answer_wait: Duration,
    /// The queue positions the service reported,
    /// in order,
    /// without repeats.
    pub positions: Vec<usize>,
    /// Notices the service sent while it waited for another program's hold on the index.
    pub waiting_notices: usize,
    /// What the last of those notices said of the holder:
    /// `proven-alive` when it named a process proven to hold the lock,
    /// `unproven` when it said the owner could not be proven alive.
    pub holder_kind: Option<&'static str>,
    /// Times the connection broke before an answer and the same request was sent again.
    pub reconnects: usize,
    /// Requests written.
    pub sends: usize,
}

/// What:
///  The common Git directory of a worktree's own Git directory:
/// the directory its `commondir` file names,
/// else the directory
///  itself.
/// Why:
///   A linked worktree's own Git directory goes away with the worktree,
/// while the repository's one timing file lives in the
///  common directory.
/// The service's review module reads the file the same way (Git strips every trailing carriage return and
///  line feed and resolves a relative path against the Git directory),
/// but that module belongs to the service run and the client
///  path may not name it (`standards_review_boundary_tests.rs`),
/// so the few lines are repeated here.
/// A path that cannot be
///  resolved is used as written.
///
/// In TS you'd write (pseudocode):
/// ```ts
/// existsSync(join(gitDir, 'commondir')) ? realpath(resolve(gitDir, readFile(...).trimEnd())) : gitDir
/// ```
fn common_dir_for(git_dir: &Path) -> PathBuf {
    let Ok(text) = std::fs::read_to_string(git_dir.join("commondir")) else {
        return git_dir.to_path_buf();
    };
    let named: &str = text.trim_end_matches(['\r', '\n']);
    if named.is_empty() {
        return git_dir.to_path_buf();
    }
    let joined: PathBuf = git_dir.join(named);
    return std::fs::canonicalize(&joined).unwrap_or(joined);
}

/// Where the record goes and which service instance it belongs to.
#[derive(Clone, Debug, Eq, PartialEq)]
struct Place {
    /// The worktree's own Git directory.
    git_dir: PathBuf,
    /// The common Git directory,
    /// which holds the file.
    common_dir: PathBuf,
    /// The instance name that `journalctl --user --unit=cli-git@<instance>.service` takes.
    instance: String,
}

/// The whole milliseconds of a duration.
fn whole_milliseconds(elapsed: Duration) -> u128 {
    return elapsed.as_millis();
}

/// The JSON word for a field that has no value.
fn null_word() -> String {
    return String::from("null");
}

impl Place {
    /// The instance as a JSON string.
    fn instance_json(&self) -> String {
        return quote(self.instance.as_str());
    }

    /// The worktree's own Git directory as a JSON string.
    fn git_dir_json(&self) -> String {
        return quote(&self.git_dir.to_string_lossy());
    }
}

/// What:
///  The phases of one wrapped commit,
/// filled as the commit runs and written when it ends.
/// Why:
///   Each field is one disjoint stretch of the command,
/// so the phases add up to no more than the total,
/// and what they do not
///  cover is reported as `otherMs` instead of being hidden.
///
/// In TS you'd write (pseudocode):
/// ```ts
/// type CommitTiming = { began: number; prepare: number; build: number; provision: number; submit: SubmitTrace; /* ... */ };
/// ```
#[derive(Clone, Debug)]
pub struct CommitTiming {
    /// The monotonic start.
    began: Instant,
    /// Milliseconds since the Unix epoch at the start,
    /// for finding the commit among the service's journal lines.
    start_millis: u128,
    /// Known once the worktree's Git directory was found.
    place: Option<Place>,
    /// The branch (or `HEAD`) the first preparation found.
    pub reference: Option<String>,
    /// The identity the commit's request carries, which the service's `answered` line states as `request` and as the
    /// journal field `CLI_GIT_REQUEST_ID`; the key that joins this record to the service's.
    pub request: Option<String>,
    /// How the command ended:
    /// `landed`,
    /// `ended` (blocked or declined,
    /// nothing landed) or `stopped` (a failure).
    pub outcome: &'static str,
    /// Preparations made:
    /// one,
    /// and one more for each time the service sent the commit back or Git built it again.
    pub attempts: usize,
    /// Policies,
    /// hooks,
    /// the private index,
    /// the tree and the objects of the commit,
    /// summed over the attempts.
    pub prepare: Duration,
    /// The message,
    /// the identities,
    /// the tree check and Git's own build of the commit,
    /// with the scratch hand-over.
    pub build: Duration,
    /// Setting up socket activation,
    /// which is the manager's unit comparison and,
    /// after an upgrade,
    /// a rewrite and a reload.
    pub provision: Duration,
    /// Sending the request and waiting for the answer.
    pub submit: SubmitTrace,
    /// The summary line,
    /// the names it needs,
    /// and the files a policy corrected,
    /// after the branch moved.
    pub after_landing: Duration,
    /// The post-commit gate.
    pub gate: Duration,
    /// Leaving the push and the upkeep for the service and waking it.
    pub handoff: Duration,
    /// The longest quiet gap of every Git step and tool this command ran, by step name, taken from the ledger when the record
    ///  is written; a step that was ended for being quiet is listed apart from the steps that ended by themselves.
    pub quiet: Vec<(String, Duration)>,
}

impl CommitTiming {
    /// Starts the clocks:
    /// the monotonic one for the durations and the wall clock for the stamp.
    pub fn start() -> Self {
        let start_millis: u128 = std::time::SystemTime::now()
            .duration_since(std::time::UNIX_EPOCH)
            .map(whole_milliseconds)
            .unwrap_or_default();
        return Self {
            began: Instant::now(),
            start_millis,
            place: None,
            reference: None,
            request: None,
            outcome: "stopped",
            attempts: 0,
            prepare: Duration::ZERO,
            build: Duration::ZERO,
            provision: Duration::ZERO,
            submit: SubmitTrace::default(),
            after_landing: Duration::ZERO,
            gate: Duration::ZERO,
            handoff: Duration::ZERO,
            quiet: Vec::new(),
        };
    }

    /// Names the worktree whose Git directory the command found;
    /// a command outside a repository writes no record.
    pub fn place_at(&mut self, git_dir: &Path) {
        self.place = Some(Place { git_dir: git_dir.to_path_buf(), common_dir: common_dir_for(git_dir), instance: instance_of(git_dir) });
    }

    /// What the phases leave uncovered out of `total`.
    fn other(&self, total: Duration) -> Duration {
        let covered: Duration = self.prepare + self.build + self.provision + self.submit.total + self.after_landing + self.gate + self.handoff;
        return total.saturating_sub(covered);
    }

    /// What:
    ///  The record as one line of JSON ending in a newline.
    /// Why:
    ///   One `write` call per line keeps lines of concurrent commits from interleaving;
    /// a branch name with a quote or a
    ///  newline is escaped by `quote`,
    /// so the line stays one line.
    ///
    /// In TS you'd write (pseudocode):
    /// ```ts
    /// JSON.stringify(record) + '\n'
    /// ```
    pub fn line(&self, total: Duration, exit_code: i32) -> String {
        let place: Option<&Place> = self.place.as_ref();
        let branch: String = self.reference.as_deref().map_or_else(null_word, quote);
        let answered_by: String = self.submit.reach.answered_by.as_deref().map_or_else(null_word, quote);
        let request: String = self.request.as_deref().map_or_else(null_word, quote);
        let level: &str = if self.outcome == "stopped" { "warn" } else { "info" };
        let positions: Vec<String> = self.submit.positions.iter().map(usize::to_string).collect();
        return format!(
            "{{\"schemaVersion\":{TIMING_SCHEMA_VERSION},\"time\":{},\"level\":\"{level}\",\"startMillis\":{},\"pid\":{},\"release\":{},\"instance\":{},\"gitDir\":{},\
             \"requestId\":{request},\"branch\":{branch},\"outcome\":{},\"exitCode\":{exit_code},\"totalMs\":{},\
             \"prepareMs\":{},\"attempts\":{},\"buildMs\":{},\"provisionMs\":{},\
             \"submitMs\":{},\"sends\":{},\"reachMs\":{},\"connectTries\":{},\"refusedConnects\":{},\"startWaitMs\":{},\
             \"updateRounds\":{},\"releasesSeen\":{},\"answeredByRelease\":{answered_by},\
             \"answerWaitMs\":{},\"positions\":[{}],\"waitingNotices\":{},\"lockHolderKind\":{},\"reconnects\":{},\
             \"afterLandingMs\":{},\"gateMs\":{},\"handoffMs\":{},\"otherMs\":{},\
             \"longestQuietMs\":{},\"quietMs\":{}}}\n",
            quote(now_iso().as_str()),
            self.start_millis,
            std::process::id(),
            quote(RELEASE),
            place.map_or_else(null_word, Place::instance_json),
            place.map_or_else(null_word, Place::git_dir_json),
            quote(self.outcome),
            total.as_millis(),
            self.prepare.as_millis(),
            self.attempts,
            self.build.as_millis(),
            self.provision.as_millis(),
            self.submit.total.as_millis(),
            self.submit.sends,
            self.submit.reach.elapsed.as_millis(),
            self.submit.reach.tries,
            self.submit.reach.refused,
            self.submit.reach.start_waited.as_millis(),
            self.submit.reach.retires_sent,
            string_array(self.submit.reach.releases_seen.as_slice()),
            self.submit.answer_wait.as_millis(),
            positions.join(","),
            self.submit.waiting_notices,
            self.submit.holder_kind.map_or_else(null_word, quote),
            self.submit.reconnects,
            self.after_landing.as_millis(),
            self.gate.as_millis(),
            self.handoff.as_millis(),
            self.other(total).as_millis(),
            longest_healthy(self.quiet.as_slice()),
            object_json(self.quiet.as_slice()),
        );
    }

    /// What:
    ///  Appends the record to the repository's timing file,
    /// best effort.
    /// Why:
    ///   The command's result never depends on the record:
    /// a file that cannot be written is only a debug line.
    /// The directory
    ///  is never created,
    /// and nothing is flushed to disk,
    /// so the record costs one `write`.
    ///
    /// In TS you'd write (pseudocode):
    /// ```ts
    /// recordTiming(timing, exitCode)
    /// ```
    pub fn finish(&self, exit_code: i32) {
        let Some(place) = self.place.as_ref() else { return };
        let target: PathBuf = place.common_dir.join(TIMING_FILE);
        // The ledger holds what this command's Git steps and tools showed; the record takes it and the next command starts empty.
        let mut with_quiet: CommitTiming = self.clone();
        with_quiet.quiet = drain();
        let line: String = with_quiet.line(self.began.elapsed(), exit_code);
        if let Err(error) = append_line(target.as_path(), line.as_bytes()) {
            debug(TAG, &format!("the timing record could not be written to {}: {error}", target.display()));
        }
    }
}

/// The line,
/// the sum rule,
/// and the escaping.
#[cfg(test)]
#[path = "commit_timing_tests.rs"]
mod tests;