forge_server/
perf_log.rs

1//! The web page's perf log: the frame records a client with no shell measures,
2//! written beside `forge.log`.
3//!
4//! The page owns the measurement (`client/src/perf.ts`); a shell writes it
5//! through its own invoke and a page sends the same batches over the socket.
6//! Records arrive as the page serialised them and leave as one JSON line each,
7//! under the log's own size cap with a single rolled copy - the log is read
8//! after the fact, and the newest window is what a reader wants.
9
10use std::io::Write as _;
11use std::path::Path;
12use std::sync::{Mutex, MutexGuard};
13
14use crate::logging::{LOG_ROTATION_MAX_BYTES, RollingFileWriter, default_diagnostics_dir};
15
16/// Where the web client's perf log sits beside the server's own `forge.log`.
17const PERF_LOG_NAME: &str = "forge-perf-web.log";
18
19/// One rolled copy, as the shell's sink keeps.
20const PERF_ROTATION_FILES: usize = 1;
21
22/// One append at a time.
23///
24/// **Every connection's batch shares one file**, and a rotation is a rename:
25/// two appends interleaving would race each other's rename and split a record
26/// across the roll. The lock covers the blocking pool's own callers too.
27static WRITE: Mutex<()> = Mutex::new(());
28
29fn write_guard() -> MutexGuard<'static, ()> {
30    match WRITE.lock() {
31        Ok(guard) => guard,
32        // **A panic in one append is not the file's fault**, and poisoning
33        // every later batch would be a silent loss. The guard holds no state.
34        Err(poisoned) => poisoned.into_inner(),
35    }
36}
37
38/// Append one batch to the web client's perf log.
39pub(crate) fn append(records: &[serde_json::Value]) -> anyhow::Result<()> {
40    let _guard = write_guard();
41    let dir = default_diagnostics_dir()?;
42    append_in(&dir, records, LOG_ROTATION_MAX_BYTES)
43}
44
45/// The write itself, over a directory and a cap a test can hand it.
46fn append_in(dir: &Path, records: &[serde_json::Value], max_bytes: u64) -> anyhow::Result<()> {
47    std::fs::create_dir_all(dir)?;
48    let path = dir.join(PERF_LOG_NAME);
49    // **A file already at the cap keeps its rolled copy.** The writer's own
50    // at-cap start discards a file that is over the cap; the previous window
51    // is the one a reader wants, so it is rolled here and the writer starts
52    // on an empty file.
53    let current = std::fs::metadata(&path).map_or(0, |meta| meta.len());
54    if current >= max_bytes {
55        let rolled = dir.join(format!("{PERF_LOG_NAME}.1"));
56        let _ = std::fs::remove_file(&rolled);
57        std::fs::rename(&path, &rolled)?;
58    }
59    let mut writer = RollingFileWriter::new(&path, true, max_bytes, PERF_ROTATION_FILES)?;
60    for record in records {
61        // **One buffer per record**, so a rotation can never split a line.
62        let line = format!("{}\n", serde_json::to_string(record)?);
63        writer.write_all(line.as_bytes())?;
64    }
65    writer.flush()?;
66    Ok(())
67}
68
69#[cfg(test)]
70mod tests {
71    use super::*;
72
73    /// **A batch lands as one JSON line per record**, so the web page's log
74    /// reads exactly as a shell's does.
75    #[test]
76    fn a_batch_lands_as_one_json_line_each() {
77        let dir = tempfile::tempdir().expect("tempdir");
78        append_in(
79            dir.path(),
80            &[
81                serde_json::json!({"schema": "forge-perf/v1", "kind": "run_started", "ts_ms": 1}),
82                serde_json::json!({"schema": "forge-perf/v1", "kind": "frame", "ms": 120.0}),
83            ],
84            LOG_ROTATION_MAX_BYTES,
85        )
86        .expect("append");
87
88        let text = std::fs::read_to_string(dir.path().join(PERF_LOG_NAME)).expect("read back");
89        let lines: Vec<&str> = text.lines().collect();
90        assert_eq!(lines.len(), 2, "one line per record: {text}");
91        let parsed: serde_json::Value = serde_json::from_str(lines[1]).expect("a JSON line");
92        assert_eq!(parsed["kind"], "frame");
93        assert_eq!(parsed["ms"], 120.0);
94    }
95
96    /// **A record the server does not know still reaches the file.** The page
97    /// learns fields the server never parses; writing the page's own JSON is
98    /// what keeps a new mark visible without a server change.
99    #[test]
100    fn a_record_with_a_field_the_server_does_not_know_survives() {
101        let dir = tempfile::tempdir().expect("tempdir");
102        append_in(
103            dir.path(),
104            &[serde_json::json!({"schema": "forge-perf/v1", "kind": "frame", "invented": true})],
105            LOG_ROTATION_MAX_BYTES,
106        )
107        .expect("append");
108
109        let text = std::fs::read_to_string(dir.path().join(PERF_LOG_NAME)).expect("read back");
110        assert!(text.contains("\"invented\":true"), "the page's field survives: {text}");
111    }
112
113    /// **A file already at the cap keeps its rolled copy.** The writer's own
114    /// at-cap start deletes it; here the previous window is what a reader
115    /// wants, so the batch lands in a fresh file beside the old one.
116    #[test]
117    fn a_file_at_the_cap_is_kept_as_the_rolled_copy() {
118        let dir = tempfile::tempdir().expect("tempdir");
119        std::fs::write(dir.path().join(PERF_LOG_NAME), "x".repeat(20)).expect("seed at the cap");
120        append_in(dir.path(), &[serde_json::json!({"kind": "frame", "ts_ms": 1})], 20)
121            .expect("append");
122
123        let rolled = std::fs::read_to_string(dir.path().join(format!("{PERF_LOG_NAME}.1")))
124            .expect("the previous window");
125        assert_eq!(rolled, "x".repeat(20), "the at-cap copy is kept: {rolled}");
126        let fresh = std::fs::read_to_string(dir.path().join(PERF_LOG_NAME)).expect("read back");
127        assert!(fresh.contains("\"frame\""), "and the new batch is in the fresh file: {fresh}");
128    }
129
130    /// **A batch that crosses the cap rolls whole records**, not bytes: the
131    /// first record stays in the rolled copy and the second opens the fresh
132    /// file.
133    #[test]
134    fn a_batch_crossing_the_cap_rolls_between_records() {
135        let dir = tempfile::tempdir().expect("tempdir");
136        let record =
137            |ts: u64| serde_json::json!({ "kind": "frame", "ts_ms": ts, "pad": "aaaaaaaa" });
138        append_in(dir.path(), &[record(1), record(2)], 40).expect("append");
139
140        let rolled = std::fs::read_to_string(dir.path().join(format!("{PERF_LOG_NAME}.1")))
141            .expect("the first record rolled");
142        let fresh = std::fs::read_to_string(dir.path().join(PERF_LOG_NAME)).expect("read back");
143        assert!(rolled.contains("\"ts_ms\":1"), "the first record is whole in the roll: {rolled}");
144        assert!(!rolled.contains("\"ts_ms\":2"), "and the second is not in it: {rolled}");
145        assert!(fresh.contains("\"ts_ms\":2"), "the second is whole in the fresh file: {fresh}");
146    }
147}
forge_server/perf_log.rs

forge_server/
perf_log.rs
