diff --git a/issues/t14-desktop-froze-at-64s.md b/issues/t14-desktop-froze-at-64s.md index ae7817f646c..81b6070721d 100644 --- a/issues/t14-desktop-froze-at-64s.md +++ b/issues/t14-desktop-froze-at-64s.md @@ -58,10 +58,14 @@ ruled it out. **What the next boot should capture.** Nothing new, which is the point: the compositor now names every client it drops and why. A recurrence with no `compositor: dropping pid` line and no telemetry is a mechanism none of the -four closed ones covers, and that is itself the finding. If it is worth -narrowing further before then, the cheap change is a `pipes=` field on the -compositor's own 2 s report — same cadence as the thing that goes missing, -where the PMM dump's is not. +four closed ones covers, and that is itself the finding. + +**Nothing replaces the 2 s report as a heartbeat.** It left the log (#891), +and with it the `pipes=` field this issue once proposed for it, so a +recurrence's log no longer says when the compositor last composited. On a +machine still up, `inspect display` says it: `frames.composited` asked twice +a few seconds apart, the taskbar damaging itself every second, or a `did not +answer` from a compositor no longer in its loop. After the fact, nothing does. Do not read the 9.58 s of no kernel output as evidence. It is the longest gap in the log, but an idle desktop in this same session goes 4–6 s between diff --git a/sdk/window/src/framebuffer.rs b/sdk/window/src/framebuffer.rs index 9b20bba153f..f580ad2b280 100644 --- a/sdk/window/src/framebuffer.rs +++ b/sdk/window/src/framebuffer.rs @@ -149,46 +149,6 @@ impl Screen { } } -/// Bytes a [`Framebuffer`] has moved through its surface since it was created. -/// -/// Cumulative; a caller sampling a window subtracts its previous sample. -#[derive(Clone, Copy, Default)] -pub struct Traffic { - /// Bytes written by the bulk paths — `blit` and `fill_rect`. - /// - /// `put_pixel` is not counted. It is the per-pixel path — every glyph a - /// font draws goes through it one pixel at a time — so a counter there - /// would tax every program that draws text to pay for one program's - /// instrument. - pub written: u64, - /// Bytes read back *out of* the surface: `get_pixel`, and the row - /// replication inside `fill_rect`. - /// - /// Zero for a surface that is only ever drawn into. A caller holding a - /// scanout mapping should read this as its bill: a read of write-combining - /// memory misses every cache, so it costs a bus transaction that a write — - /// which merges with its neighbours — does not. - pub read: u64, - /// Reads of a single pixel (`get_pixel`) — each one a separate round trip. - pub pixel_reads: u64, - /// Reads of a whole row or region (`fill_rect`). - pub bulk_reads: u64, -} - -impl Traffic { - /// What moved between an earlier sample and this one. Both must come from - /// the same surface; a sample from another one underflows rather than - /// producing a plausible figure. - pub fn since(self, earlier: Self) -> Self { - Self { - written: self.written - earlier.written, - read: self.read - earlier.read, - pixel_reads: self.pixel_reads - earlier.pixel_reads, - bulk_reads: self.bulk_reads - earlier.bulk_reads, - } - } -} - pub struct Framebuffer { buf: *mut u8, len: usize, @@ -196,10 +156,6 @@ pub struct Framebuffer { height: usize, stride: usize, pixel_format: PixelFormat, - written: Cell, - read: Cell, - pixel_reads: Cell, - bulk_reads: Cell, } impl Framebuffer { @@ -214,19 +170,6 @@ impl Framebuffer { height, stride, pixel_format: PixelFormat::from_raw(pixel_format), - written: Cell::new(0), - read: Cell::new(0), - pixel_reads: Cell::new(0), - bulk_reads: Cell::new(0), - } - } - - pub fn traffic(&self) -> Traffic { - Traffic { - written: self.written.get(), - read: self.read.get(), - pixel_reads: self.pixel_reads.get(), - bulk_reads: self.bulk_reads.get(), } } @@ -260,8 +203,6 @@ impl Framebuffer { if x < self.width && y < self.height { let offset = (y * self.stride + x) * 4; debug_assert!(offset + 4 <= self.len); - self.read.set(self.read.get() + 4); - self.pixel_reads.set(self.pixel_reads.get() + 1); let pixel = unsafe { core::slice::from_raw_parts(self.buf.add(offset), 4) }; match self.pixel_format { PixelFormat::Rgb => Color { r: pixel[0], g: pixel[1], b: pixel[2] }, @@ -285,22 +226,18 @@ impl Framebuffer { } /// Fill a row of pixels with a 4-byte pattern using doubling memcpy. - /// Returns how many of those copies read back out of the row. - unsafe fn fill_row(dst: *mut u8, pixel: &[u8; 4], count: usize) -> u64 { + unsafe fn fill_row(dst: *mut u8, pixel: &[u8; 4], count: usize) { if count == 0 { - return 0; + return; } ptr::copy_nonoverlapping(pixel.as_ptr(), dst, 4); let total_bytes = count * 4; let mut filled = 4usize; - let mut copies = 0; while filled < total_bytes { let chunk = filled.min(total_bytes - filled); ptr::copy_nonoverlapping(dst, dst.add(filled), chunk); filled += chunk; - copies += 1; } - copies } pub fn fill_rect(&self, x: usize, y: usize, w: usize, h: usize, color: Color) { @@ -314,26 +251,17 @@ impl Framebuffer { let row_bytes = actual_w * 4; let pixel = self.encode_pixel(color); - let doubling_copies = unsafe { + unsafe { let first_row = self.buf.add((y * self.stride + x) * 4); debug_assert!((y * self.stride + x) * 4 + row_bytes <= self.len); - let copies = Self::fill_row(first_row, &pixel, actual_w); + Self::fill_row(first_row, &pixel, actual_w); for dy in 1..rows { let dst_offset = ((y + dy) * self.stride + x) * 4; debug_assert!(dst_offset + row_bytes <= self.len); let dst = self.buf.add(dst_offset); ptr::copy_nonoverlapping(first_row, dst, row_bytes); } - copies - }; - - // Every row but the first is a copy *of* the first, and the doubling - // that built the first read all but its seed pixel back. - self.written.set(self.written.get() + (row_bytes * rows) as u64); - self.read - .set(self.read.get() + (row_bytes - 4 + row_bytes * (rows - 1)) as u64); - self.bulk_reads - .set(self.bulk_reads.get() + doubling_copies + (rows - 1) as u64); + } } /// Blit a buffer to a region of the framebuffer (row-by-row memcpy). @@ -358,7 +286,6 @@ impl Framebuffer { ); } } - self.written.set(self.written.get() + (copy_bytes * rows) as u64); } pub fn clear(&self, color: Color) { diff --git a/sdk/window/src/lib.rs b/sdk/window/src/lib.rs index 8447d8bc717..c011b367909 100644 --- a/sdk/window/src/lib.rs +++ b/sdk/window/src/lib.rs @@ -2,7 +2,7 @@ mod arch; pub mod framebuffer; pub mod wait; -pub use framebuffer::{Color, Framebuffer, Screen, Traffic}; +pub use framebuffer::{Color, Framebuffer, Screen}; pub use wait::{Waiter, Waker, Woke}; /// What [`Window::handle`] answers with, and what a [`Waiter`] waits on. pub use toyos_abi::RawHandle; diff --git a/system/compositor/src/client.rs b/system/compositor/src/client.rs index 9eeb6e96f5a..2f958eda58e 100644 --- a/system/compositor/src/client.rs +++ b/system/compositor/src/client.rs @@ -257,15 +257,11 @@ pub fn announce(dead: &[Dead]) { /// Say that a window was deliberately closed, and by what. /// -/// A client that *dies* is already announced — `dropping client N — why` — and -/// a window somebody closed was not, so the desktop's only record of one was the -/// `windows=N` count in the statistics line. That is a sample of a level taken -/// every two seconds: two closes inside one interval are indistinguishable -/// from one, and from none if a window opened in between. Every report the -/// owner has made about this desktop begins "I closed a window and then", so -/// which window went, why, and how many are left is the first thing anyone -/// asks of the log — and a caller that re-sends a close because it could not -/// tell whether the first one landed closes the next window down. +/// A client that *dies* is already announced — `dropping client N — why`. +/// Every report the owner has made about this desktop begins "I closed a window +/// and then", so which window went, why, and how many are left is the first +/// thing anyone asks of the log — and a caller that re-sends a close because it +/// could not tell whether the first one landed closes the next window down. pub fn note_closed(by: &str, win: &Win, remaining: usize) { println!( "compositor: window closed client={} by {by}, {remaining} left, presents={} frames={}", diff --git a/system/compositor/src/main.rs b/system/compositor/src/main.rs index 0645e25575b..4aedb0063a0 100644 --- a/system/compositor/src/main.rs +++ b/system/compositor/src/main.rs @@ -29,7 +29,6 @@ use toyos_manifest::package; pub const DOUBLE_CLICK_TIME: Duration = Duration::from_millis(400); pub const FRAME_INTERVAL: Duration = Duration::from_nanos(16_666_667); // ~60fps -pub const STATS_INTERVAL: Duration = Duration::from_secs(2); /// How long one pass may spend draining clients before it must composite. /// diff --git a/system/compositor/src/session.rs b/system/compositor/src/session.rs index 5c50badcf31..05e14e7981d 100644 --- a/system/compositor/src/session.rs +++ b/system/compositor/src/session.rs @@ -33,10 +33,10 @@ use crate::client::{ HANDSHAKE_TIMEOUT, MAX_KEPT_PAYLOAD, MAX_PENDING_CONNS, }; use crate::render::{self, Assets, BackBuffer, SystemStats, TitleBarIcons}; -use crate::stats::{FrameStats, FrameTotals}; +use crate::stats::FrameTotals; use crate::{ launcher_apps, DOUBLE_CLICK_TIME, DRAIN_BUDGET, FIXED_POLL_HANDLES, - FLAG_HARDWARE_CURSOR, FRAME_INTERVAL, MAX_WINDOW_SLOTS, PROMPT_POLL_HANDLES, STATS_INTERVAL, + FLAG_HARDWARE_CURSOR, FRAME_INTERVAL, MAX_WINDOW_SLOTS, PROMPT_POLL_HANDLES, }; const _: () = assert!( @@ -148,16 +148,11 @@ pub struct Session { /// Tokens the last `wait` reported ready. ready: Vec, - stats: FrameStats, - /// Every window `stats` has reported, summed, for `inspect`. totals: FrameTotals, cached_stats: SystemStats, prev_busy_ticks: u64, prev_total_ticks: u64, last_taskbar_update: Instant, - next_stats_report: Instant, - reported_traffic: (u64, u64), - reported_composed: window::Traffic, } impl Session { @@ -265,8 +260,6 @@ impl Session { let now = Instant::now(); Self { - reported_traffic: screen.traffic(), - reported_composed: back.surface.traffic(), acceptor, prompts, prompt: None, @@ -303,13 +296,11 @@ impl Session { max_windows, dead: Vec::new(), ready: Vec::new(), - stats: FrameStats::default(), totals: FrameTotals::default(), cached_stats: SystemStats { used_mb: 0, total_mb: 0, cpu_pct: 0 }, prev_busy_ticks: 0, prev_total_ticks: 0, last_taskbar_update: now, - next_stats_report: now + STATS_INTERVAL, } } @@ -1144,7 +1135,7 @@ impl Session { snap.put("cursor", if self.hw_cursor { "hardware" } else { "software" }); snap.put("windows.open", self.stack.len()); snap.put("windows.max", self.max_windows); - self.totals.plus(&self.stats).inspect(&mut snap); + self.totals.inspect(&mut snap); let encoded = snap.encode().unwrap_or_else(|why| panic!("compositor: its snapshot: {why}")); if let Err(e) = ipc::try_send_bytes(handle, toyos_inspect::MSG_SNAPSHOT, &encoded) { @@ -1169,10 +1160,6 @@ impl Session { ); self.back = BackBuffer::new(self.screen.width(), self.screen.height(), self.pixel_format()); - // The counters belong to the mapping, and this is a new one starting at - // zero. - self.reported_traffic = self.screen.traffic(); - self.reported_composed = self.back.surface.traffic(); self.desk = desk_of(&self.screen, &self.font, self.apps.len()); // What a window costs moved, so what we can afford moved with it. // Windows already open are left alone if the new figure is below their @@ -1321,7 +1308,6 @@ impl Session { ); if regions.iter().any(|r| r.overlaps(rect)) { render::draw_software_cursor(&self.back.surface, sprite, self.cursor); - self.stats.cursor_draws += 1; } } @@ -1337,12 +1323,7 @@ impl Session { ); damage_px += region.area(); } - let composited_at = Instant::now(); - self.stats.record( - composited_at.duration_since(started).as_nanos() as u64, - regions.len(), - damage_px, - ); + self.totals.record(started.elapsed().as_nanos() as u64, regions.len(), damage_px); for region in ®ions { self.fb_dev @@ -1356,21 +1337,6 @@ impl Session { } self.frame_callbacks(®ions); - - if composited_at >= self.next_stats_report { - let traffic = self.screen.traffic(); - let composed = self.back.surface.traffic(); - self.stats.report( - (traffic.0 - self.reported_traffic.0, traffic.1 - self.reported_traffic.1), - composed.since(self.reported_composed), - self.stack.len(), - ); - self.totals.fold(&self.stats); - self.stats = FrameStats::default(); - self.reported_traffic = traffic; - self.reported_composed = composed; - self.next_stats_report = composited_at + STATS_INTERVAL; - } } /// Tell every window that presented and was composited that its frame is diff --git a/system/compositor/src/stats.rs b/system/compositor/src/stats.rs index 4228668522c..d52b33aa693 100644 --- a/system/compositor/src/stats.rs +++ b/system/compositor/src/stats.rs @@ -1,103 +1,23 @@ -use window::Traffic; - -/// Counters for one reporting window, flushed from a composited frame and -/// never otherwise: a compositor with nothing to draw says nothing, as soundserver -/// says nothing with no clients. -/// -/// Here to be read off `/log/kernel.log` on a machine whose only other -/// instrument is the panel. `damage_px_max` is the one to read first: it is the -/// largest single frame any interval contained, so it says whether one typed -/// character, one clock tick or one dragged window still costs a repaint of -/// something much larger than itself. `damage_px` over `frames` is the average -/// of the same question. -/// -/// There is no scanout *read* figure because there is nothing that could -/// produce one: the panel is held as a `window::Screen`, which returns no pixel -/// and hands out no pointer. `back_rd_bytes` is where the reads went instead — -/// the cursor's blend and `fill_rect`'s row replication, in system RAM. +/// Every frame composited so far, for `inspect`, which is where they are read. #[derive(Default)] -pub struct FrameStats { - pub frames: u32, - pub cursor_draws: u32, - rects: u32, +pub struct FrameTotals { + frames: u64, + rects: u64, damage_px: u64, - damage_px_max: u64, - composite_ns_min: u64, - composite_ns_max: u64, - composite_ns_total: u64, + composite_ns: u64, } -impl FrameStats { +impl FrameTotals { /// `composite_ns` covers composing every region of the frame, the software /// cursor and the blits that carry them to the panel — everything between /// one frame's damage being taken and it being on screen. Not the /// `gpu::present` calls that follow: those are syscalls, and on the /// firmware framebuffer they do nothing at all. pub fn record(&mut self, composite_ns: u64, rects: usize, damage_px: u64) { - self.composite_ns_min = if self.frames == 0 { - composite_ns - } else { - self.composite_ns_min.min(composite_ns) - }; - self.composite_ns_max = self.composite_ns_max.max(composite_ns); - self.composite_ns_total += composite_ns; - self.rects += rects as u32; - self.damage_px += damage_px; - self.damage_px_max = self.damage_px_max.max(damage_px); self.frames += 1; - } - - /// `moved` is the panel traffic of this window alone and `composed` the - /// back buffer's. Totals rather than means: with `frames` beside them the - /// mean is a division, and the total is the share of the window that - /// compositing cost, which the mean is not. - pub fn report(&self, moved: (u64, u64), composed: Traffic, windows: usize) { - println!( - "compositor: frames={} rects={} damage_px={} damage_px_max={} \ - composite_us_min={} composite_us_max={} composite_us_total={} \ - scanout_wr_bytes={} scanout_blits={} back_rd_bytes={} cursor={} windows={}", - self.frames, - self.rects, - self.damage_px, - self.damage_px_max, - self.composite_ns_min / 1_000, - self.composite_ns_max / 1_000, - self.composite_ns_total / 1_000, - moved.0, - moved.1, - composed.read, - self.cursor_draws, - windows, - ); - } -} - -/// Every reported window summed, for `inspect`: the console says a window at a -/// time and this is what they add up to. No new measurement — the same four -/// counters [`FrameStats::record`] fills. -#[derive(Default, Clone, Copy)] -pub struct FrameTotals { - frames: u64, - rects: u64, - damage_px: u64, - composite_ns: u64, -} - -impl FrameTotals { - /// Add a window the console has just reported, before it is reset. - pub fn fold(&mut self, window: &FrameStats) { - *self = self.plus(window); - } - - /// These totals with the still-open window on top: where the compositor is - /// now. - pub fn plus(self, window: &FrameStats) -> Self { - Self { - frames: self.frames + u64::from(window.frames), - rects: self.rects + u64::from(window.rects), - damage_px: self.damage_px + window.damage_px, - composite_ns: self.composite_ns + window.composite_ns_total, - } + self.rects += rects as u64; + self.damage_px += damage_px; + self.composite_ns += composite_ns; } pub fn inspect(&self, snap: &mut toyos_inspect::Snapshot) { diff --git a/system/console/src/main.rs b/system/console/src/main.rs index d6866dc4740..e1d33386e26 100644 --- a/system/console/src/main.rs +++ b/system/console/src/main.rs @@ -95,11 +95,12 @@ impl Log { /// Take every whole line in `bytes` that goes on the screen. /// - /// **Every program's line but this program's own**, which it has already - /// drawn, and **the kernel's records of the boot before this program - /// asked** — the boot so far, as the panel it took over would have shown - /// it. A record after that is not drawn: it would put a `spawn:` and an - /// `exit:` beside every command typed. + /// **Every program's line but this program's own**, and **the kernel's + /// records of the boot before this program asked** — the boot so far, as + /// the panel it took over would have shown it. A record after that is not + /// drawn: it would put a `spawn:` and an `exit:` beside every command + /// typed, as this program's own lines would put a grab and a release beside + /// every program that takes the keyboard. /// /// Each is drawn as [`Showing`] shows it. fn take(&mut self, bytes: &[u8]) { @@ -257,7 +258,6 @@ fn main() { } n => { console.write_bytes(&buf[..n]); - std::io::stdout().lock().write_all(&buf[..n]).ok(); unfinished(&mut partial, &buf[..n]); painted = true; } @@ -269,7 +269,6 @@ fn main() { let n = shell.stderr.read(&mut buf).unwrap_or(0); if n > 0 { console.write_bytes(&buf[..n]); - std::io::stdout().lock().write_all(&buf[..n]).ok(); unfinished(&mut partial, &buf[..n]); painted = true; } diff --git a/system/terminal/src/main.rs b/system/terminal/src/main.rs index a25fd3ad16c..8bd78bd427d 100644 --- a/system/terminal/src/main.rs +++ b/system/terminal/src/main.rs @@ -101,13 +101,11 @@ fn main() { let n = shell_stderr.read(&mut buf).unwrap_or(0); if n > 0 { console.write_bytes(&buf[..n]); - std::io::stdout().lock().write_all(&buf[..n]).ok(); present(&console, &window); } break; } console.write_bytes(&buf[..n]); - std::io::stdout().lock().write_all(&buf[..n]).ok(); present(&console, &window); } @@ -116,7 +114,6 @@ fn main() { let n = shell_stderr.read(&mut buf).unwrap_or(0); if n > 0 { console.write_bytes(&buf[..n]); - std::io::stdout().lock().write_all(&buf[..n]).ok(); present(&console, &window); } } diff --git a/tests/checks/qemu.rs b/tests/checks/qemu.rs index 0096b197cee..3342adbe069 100644 --- a/tests/checks/qemu.rs +++ b/tests/checks/qemu.rs @@ -107,7 +107,7 @@ pub fn ceiling_self_check() -> Result<(), String> { // 2b. The same two cases for the wait that holds a whole capture rather // than a line at a time — `await_guest`, whose `it went quiet` is the // wording #156's signature is stated in. - let halted = format!("[ 0.400 cpu0 kernel] compositor: frames=120\n{KERNEL}\n"); + let halted = format!("[ 0.400 cpu0 kernel] compositor: ready\n{KERNEL}\n"); let Some(found) = super::serial::kernel_death(&halted) else { return Err(String::from("a capture ending in a kernel panic reads as a guest that merely \ stopped, which is the verdict that threw the cause away")); @@ -115,7 +115,7 @@ pub fn ceiling_self_check() -> Result<(), String> { if kernel_died_here(found) != panic { return Err(String::from("the two waits word one panic differently")); } - let program_died = format!("[ 0.400 cpu0 kernel] compositor: frames=120\n{USER}\n"); + let program_died = format!("[ 0.400 cpu0 kernel] compositor: ready\n{USER}\n"); if super::serial::kernel_death(&program_died).is_some() { return Err(format!( "a capture whose only panic is a program's reads as a halted machine:\n{program_died}" diff --git a/tests/common/qemu.rs b/tests/common/qemu.rs index 144826a69f7..c68087bb7f5 100644 --- a/tests/common/qemu.rs +++ b/tests/common/qemu.rs @@ -293,9 +293,8 @@ pub fn budget_smp(ceiling: Duration, smp: u32) -> Duration { /// about the host. /// /// `total` is the second half, and it is a wedge guard rather than a verdict -/// too. A guest can be stuck and chatty: the compositor prints an interval line -/// every two seconds whatever else has stopped, so silence alone cannot end a -/// desktop loop and a suite that never ends is worse than one that reds. +/// too. A guest can be stuck and chatty, and a suite that never ends is worse +/// than one that reds. /// /// The caller owns the capture, so progress is "did it grow" and costs nothing. pub struct Liveness { @@ -355,24 +354,17 @@ pub const TIMED_OUT: &str = "timed out after"; /// How long a guest may say nothing before a wait on it is a stall. /// -/// Every config these waits run on has something on a periodic interval — the -/// compositor's frame batch and soundserver's stats window are both about 2 s — so -/// silence here is a machine that has stopped rather than a machine that is -/// thinking. It is not a verdict about any of them: no assertion in this suite -/// is satisfied by the guest merely talking. +/// It is not a verdict: no assertion in this suite is satisfied by the guest +/// merely talking. /// -/// The other side of that coin: on a shared boot the kernel itself is one of -/// the periodic speakers, on a 10 s cadence, so a wait whose predicate never -/// comes true is never ended by this bound — the guest keeps talking, and the -/// wait runs the whole of [`GUEST_WEDGED`]. +/// On a shared boot the kernel itself is a periodic speaker, on a 10 s cadence, +/// so a wait whose predicate never comes true is never ended by this bound — +/// the guest keeps talking, and the wait runs the whole of [`GUEST_WEDGED`]. pub const GUEST_QUIET: Duration = Duration::from_secs(15); -/// The other end of the same guard: a guest can be stuck and chatty. -/// -/// The compositor prints its interval line whatever else has stopped, so -/// silence alone cannot end a desktop wait, and a suite that never ends is -/// worse than one that reds. [`budget_smp`]'s rule over the tests that wait -/// through [`await_guest`]. +/// The other end of the same guard: a guest can be stuck and chatty, and a +/// suite that never ends is worse than one that reds. [`budget_smp`]'s rule +/// over the tests that wait through [`await_guest`]. pub const GUEST_WEDGED: Duration = Duration::from_secs(141); /// A kernel line without its head. @@ -490,8 +482,8 @@ pub const VERDICT_POLL: Duration = Duration::from_millis(100); /// /// **`elapsed > ceiling` stays a necessary condition, and that is what keeps /// this safe.** Silence alone is not a wedge on this suite's boots: a healthy -/// but idle guest on a config with no live periodic speaker — no compositor, an -/// idle soundserver, and the kernel's own ~10 s line halting with the idle loop — was +/// but idle guest on a config with no live periodic speaker — an idle +/// soundserver, and the kernel's own ~10 s line halting with the idle loop — was /// measured quiet for as long as 102 s, so a guard that fired on 15 s of silence /// by itself would red a working machine. A guest's own budget is what says how /// long its silence is allowed; only past *that* does quiet mean stopped.