diff --git a/crates/zu-capi/tests/capi.rs b/crates/zu-capi/tests/capi.rs index 33007954..3399eae1 100644 --- a/crates/zu-capi/tests/capi.rs +++ b/crates/zu-capi/tests/capi.rs @@ -2100,8 +2100,9 @@ fn a_statement_stopped_from_another_thread_leaves_the_connection_warm() { std::thread::sleep(std::time::Duration::from_micros(200)); } assert!(rows > 0, "the statement never started reading"); + let asked = std::time::Instant::now(); assert_eq!(zu_conn_interrupt(handed.0), ZuStatus::Ok); - rows + (rows, asked) }); let mut result: *mut ZuResult = ptr::null_mut(); let mut err: *mut ZuError = ptr::null_mut(); @@ -2112,11 +2113,21 @@ fn a_statement_stopped_from_another_thread_leaves_the_connection_warm() { &mut result, &mut err, ); - let seen = asking.join().expect("the asking thread"); - (status, result, err, seen) + let felt = std::time::Instant::now(); + let (seen, asked) = asking.join().expect("the asking thread"); + (status, result, err, seen, felt.duration_since(asked)) }); - let (status, result, err, seen) = stopped; + let (status, result, err, seen, took) = stopped; assert_eq!(status, ZuStatus::Interrupted, "the statement was stopped"); + // dx/02 asks for fifty milliseconds from the ask to the return, + // and the executor reads the flag at the boundary of a chunk, + // which is a fraction of a millisecond of work. The margin is + // for a machine running the whole suite at once, not for the + // engine. + assert!( + took < std::time::Duration::from_millis(50), + "the ask took {took:?} to land" + ); assert!(result.is_null(), "a stopped statement has no result"); // Stopping is not failing, but it is still reported as an // error handle, and what it says is that it stopped. diff --git a/crates/zu-cli/src/repl.rs b/crates/zu-cli/src/repl.rs index e39b2591..5c46f625 100644 --- a/crates/zu-cli/src/repl.rs +++ b/crates/zu-cli/src/repl.rs @@ -240,11 +240,20 @@ fn timed(session: &mut Session, statement: &str, timing: bool) -> (String, bool) /// How often the watcher wakes: often enough that a `Ctrl-C` is /// answered while the finger is still on the key, rare enough that -/// waiting on a statement costs nothing measurable. Fifty presses a +/// waiting on a statement costs nothing measurable. Two hundred wakes a /// second against an executor that checks its flag every chunk puts the /// whole round trip well inside the tenth of a second a person reads as -/// immediate. -const TICK: std::time::Duration = std::time::Duration::from_millis(20); +/// immediate, and a wake that finds nothing to do is a compare and a +/// sleep. +/// +/// A press pays this twice: once for the wake that reads the flag and +/// once for the wake that finds the statement over, since the loop only +/// looks between two sleeps. Ten milliseconds of budget for a press +/// measured at forty when this was twenty, against a budget of fifty. +/// The progress line is unaffected either way, because it is written +/// only when the tenth of a second or the row count it prints has +/// changed. +const TICK: std::time::Duration = std::time::Duration::from_millis(5); /// How long a statement runs before the shell says it is running. /// diff --git a/crates/zu-cli/tests/press.rs b/crates/zu-cli/tests/press.rs new file mode 100644 index 00000000..78ff02d6 --- /dev/null +++ b/crates/zu-cli/tests/press.rs @@ -0,0 +1,228 @@ +//! `Ctrl-C` while a statement is running, measured. +//! +//! The shell only watches for a press where there is a terminal, so +//! this test gives it one: a pseudoterminal, the pair the operating +//! system hands out for exactly this, with the shell on the far side of +//! it reading keys and drawing a progress line the way it would under a +//! person. Driving it over a pipe instead would test the other branch, +//! the one that runs the statement inline and cannot be interrupted at +//! all. +//! +//! The press itself is a `SIGINT` sent to the child rather than a `^C` +//! byte written into the terminal, because the byte only becomes a +//! signal when the driver's signal characters are on and the child is +//! the foreground process group of a controlling terminal, which is +//! session bookkeeping this test would have to do to arrive at the +//! same signal. What the terminal driver does on `Ctrl-C` is send this +//! signal, so this is the press with the driver's part played out. +//! +//! Unix only. Windows has no pseudoterminal with this shape and no +//! `SIGINT` to send one, and the console equivalent is a different +//! mechanism the shell does not use yet. +#![cfg(unix)] + +use std::ffi::{CStr, c_char, c_int}; +use std::fs::{File, OpenOptions}; +use std::io::{Read, Write}; +use std::os::fd::FromRawFd; +use std::os::unix::fs::OpenOptionsExt; +use std::process::{Child, Command, Stdio}; +use std::sync::{Arc, Mutex}; +use std::time::{Duration, Instant}; + +/// What the milestone asks for, from the press to the shell saying it +/// stopped. +const BUDGET: Duration = Duration::from_millis(50); + +/// Enough people that every pair of them is minutes of work, so the +/// statement is certainly still running when the press arrives and the +/// test never races the answer. +const PEOPLE: u64 = 12_000; + +/// `SIGINT`, which is 2 everywhere a unix runs. +const SIGINT: c_int = 2; + +const O_RDWR: c_int = 2; + +/// Do not take this terminal as a controlling one. The parent is a test +/// binary that already has its own, and a slave opened without this +/// flag by a process that is a session leader would take it over. +#[cfg(target_os = "linux")] +const O_NOCTTY: i32 = 0o400; +#[cfg(not(target_os = "linux"))] +const O_NOCTTY: i32 = 0x0002_0000; + +unsafe extern "C" { + fn posix_openpt(flags: c_int) -> c_int; + fn grantpt(fd: c_int) -> c_int; + fn unlockpt(fd: c_int) -> c_int; + fn ptsname(fd: c_int) -> *mut c_char; + fn kill(pid: c_int, sig: c_int) -> c_int; +} + +/// The two ends of a fresh pseudoterminal: the master this test writes +/// keys into and reads the screen out of, and the path of the slave the +/// child opens as its own terminal. +fn pty() -> (File, String) { + // Safety: the four calls are the sequence `posix_openpt` documents, + // each checked, and the name is copied out before anything else can + // call `ptsname` again on this thread. + unsafe { + let master = posix_openpt(O_RDWR | O_NOCTTY); + assert!(master >= 0, "no pseudoterminal"); + assert_eq!(grantpt(master), 0, "grantpt"); + assert_eq!(unlockpt(master), 0, "unlockpt"); + let name = ptsname(master); + assert!(!name.is_null(), "ptsname"); + let name = CStr::from_ptr(name).to_string_lossy().into_owned(); + (File::from_raw_fd(master), name) + } +} + +/// The screen, as the shell paints it, with the moment each piece of it +/// arrived. +#[derive(Default)] +struct Screen { + chunks: Vec<(Instant, String)>, +} + +impl Screen { + /// The moment the whole of `wanted` had arrived, or `None` while it + /// has not. The time is the end of the chunk that completed it, + /// which is when a person would have seen it. + fn when(&self, wanted: &str) -> Option { + let mut seen = String::new(); + for (at, chunk) in &self.chunks { + seen.push_str(chunk); + if seen.contains(wanted) { + return Some(*at); + } + } + None + } + + fn text(&self) -> String { + self.chunks.iter().map(|(_, c)| c.as_str()).collect() + } +} + +/// Reads the master until the child hangs up, timestamping what it +/// reads. A thread of its own because a read on a terminal blocks and +/// the test has to be watching the clock while the shell is quiet. +fn watch(mut master: File) -> Arc> { + let screen = Arc::new(Mutex::new(Screen::default())); + let out = Arc::clone(&screen); + std::thread::spawn(move || { + let mut buf = [0u8; 4096]; + while let Ok(n) = master.read(&mut buf) { + if n == 0 { + break; + } + let at = Instant::now(); + let text = String::from_utf8_lossy(&buf[..n]).into_owned(); + out.lock().expect("screen").chunks.push((at, text)); + } + }); + screen +} + +/// Waits for `wanted` to appear on the screen and answers when it did, +/// or gives up after `patience` and says what was there instead. +fn until(screen: &Mutex, wanted: &str, patience: Duration) -> Instant { + let start = Instant::now(); + while start.elapsed() < patience { + if let Some(at) = screen.lock().expect("screen").when(wanted) { + return at; + } + std::thread::sleep(Duration::from_millis(1)); + } + let seen = screen.lock().expect("screen").text(); + panic!("waited {patience:?} for {wanted:?}, saw {seen:?}"); +} + +/// A database with enough people in it, written the fast way rather +/// than a statement at a time. +fn seeded(path: &std::path::Path) { + let mut db = zu::zu1::file::Zu1File::create(path).expect("create"); + zu::zu1::graph::bulk_load_as(&mut db, "person", "knows", PEOPLE, &[(0, 1)]).expect("load"); +} + +/// Types a line into the shell the way a keyboard does, return key and +/// all. Raw mode is on while the editor is reading, so the key is a +/// carriage return and not a newline. +fn typed(keys: &mut File, line: &str) { + keys.write_all(line.as_bytes()).expect("type"); + keys.write_all(b"\r").expect("return"); + keys.flush().expect("flush"); +} + +/// Kills the shell however far it got, so a failed assertion does not +/// leave a process holding a terminal open. +struct Reaped(Child); + +impl Drop for Reaped { + fn drop(&mut self) { + let _ = self.0.kill(); + let _ = self.0.wait(); + } +} + +#[test] +fn a_press_stops_a_long_statement_inside_the_budget() { + let dir = tempfile::tempdir().expect("tempdir"); + let path = dir.path().join("press.zu1"); + seeded(&path); + + let (master, slave) = pty(); + let terminal = || { + OpenOptions::new() + .read(true) + .write(true) + .custom_flags(O_NOCTTY) + .open(&slave) + .expect("slave") + }; + let child = Command::new(env!("CARGO_BIN_EXE_zu")) + .arg("shell") + .arg(&path) + .stdin(Stdio::from(terminal())) + .stdout(Stdio::from(terminal())) + .stderr(Stdio::from(terminal())) + .spawn() + .expect("spawn"); + let pid = child.id() as c_int; + let child = Reaped(child); + // Keys go into the master, which is the end a keyboard is on: what + // is written to the slave comes back out of the master as output, + // which would be this test reading its own typing. + let mut keys = master.try_clone().expect("keys"); + let screen = watch(master); + + // The prompt, so the press cannot land on a shell that is still + // opening the file. + until(&screen, "zu>", Duration::from_secs(30)); + typed( + &mut keys, + "MATCH (a:person), (b:person) WHERE a.id < b.id RETURN count(a) AS n", + ); + // The progress line, which the shell only writes once a statement + // has been running for a while: waiting for it is how this test + // knows the press lands on a statement that is inside the executor + // rather than one still being parsed. + until(&screen, "running", Duration::from_secs(30)); + + let pressed = Instant::now(); + // Safety: a signal to a child this test spawned and has not reaped. + assert_eq!(unsafe { kill(pid, SIGINT) }, 0, "kill"); + let stopped = until(&screen, "interrupted at", Duration::from_secs(30)); + let took = stopped.duration_since(pressed); + assert!(took < BUDGET, "the press took {took:?} to arrive"); + + // And the session is the one it was: the shell says so, and then + // answers the next statement without being reopened. + let seen = screen.lock().expect("screen").text(); + assert!(seen.contains("the session is still open"), "got {seen:?}"); + typed(&mut keys, "MATCH (p:person) RETURN count(p) AS n"); + until(&screen, &PEOPLE.to_string(), Duration::from_secs(30)); + drop(child); +} diff --git a/docs/10-api-and-tooling.md b/docs/10-api-and-tooling.md index 722c0f7b..576aba47 100644 --- a/docs/10-api-and-tooling.md +++ b/docs/10-api-and-tooling.md @@ -120,9 +120,9 @@ None of that is a dependency. The workspace has no terminal crate and no line ed Raw mode is held while a statement is typed and dropped while it runs, so a query that takes a minute takes it with the driver back to normal and `Ctrl-C` at that moment is the signal it has always been rather than a byte nobody is reading. What that signal now does is stop the statement instead of the process, which is the paragraph after this one. `crates/zu-cli/benches/editor.rs` holds the typing path to a number, since a redraw rebuilds the whole buffer per key: 0.21 to 0.46 microseconds for a key on a one-line statement and 0.47 to 1.03 on a six-line one, the spread being what else the machine was doing, 2.17 to paint that six-line statement and 2.85 for a tab weighed against a hundred labels and a hundred tables, against a 50 microsecond ceiling in `bench/budgets.toml` that a per-character allocation or a reparse per keystroke would not fit under. -`Ctrl-C` on a running statement stops the statement and keeps everything else, which takes a word the engine reads and a handler that writes it. The word lives on the session, rides with the switches in `exec::Options` so that no execution path can be the one that was never wired, and is read at the boundaries both executors already stop at: the single pull entry point of the chunk executor, which every operator's inner loop goes through, so a filter rejecting a million rows without emitting one is still interruptible, and the stop flag the push pipeline's workers already test per morsel, which folds the ask into a load that was happening anyway. A stopped run is an error rather than a short answer, because workers that drained at their next boundary hold a piece of a result and a piece of a result printed as a result is worse than no result. Stopping is not failing, so `Interrupted` carries no GQLSTATUS, the standard having no condition for it, the session stays warm and answers the next statement, and the ask stays where the caller put it until the caller clears it, since a handle that cleared itself would race the statement still winding down. The signal handler does nothing but set an atomic, which is all a unix handler may do, and the shell polls it rather than acting inside it. +`Ctrl-C` on a running statement stops the statement and keeps everything else, which takes a word the engine reads and a handler that writes it. The word lives on the session, rides with the switches in `exec::Options` so that no execution path can be the one that was never wired, and is read at the boundaries both executors already stop at: the single pull entry point of the chunk executor, which every operator's inner loop goes through, so a filter rejecting a million rows without emitting one is still interruptible, and the stop flag the push pipeline's workers already test per morsel, which folds the ask into a load that was happening anyway. A stopped run is an error rather than a short answer, because workers that drained at their next boundary hold a piece of a result and a piece of a result printed as a result is worse than no result. Stopping is not failing, so `Interrupted` carries no GQLSTATUS, the standard having no condition for it, the session stays warm and answers the next statement, and the ask stays where the caller put it until the caller clears it, since a handle that cleared itself would race the statement still winding down. The signal handler does nothing but set an atomic, which is all a unix handler may do, and the shell polls it rather than acting inside it. Fifty milliseconds from the press to the answer is the number, and it is asserted on all three surfaces rather than described: `crates/zu-cli/tests/press.rs` drives the shell under a pseudoterminal, presses, and reads the interrupted line back at 11 ms; the C ABI's stop test times the ask against the return of `zu_query`; and the Python client's suite times a press against the `KeyboardInterrupt` it raises. The shell's watcher wakes two hundred times a second because a press pays that wait twice, once for the wake that reads the flag and once for the wake that finds the statement over. -Progress rides on the same handle, because a person watching a statement that has taken ten seconds is asking a question the engine can already answer. The count is rows read from storage, incremented once per chunk at the scan and once per claimed morsel in the pipeline rather than once per row, so the counter is a relaxed add per thousands of rows and not a shared word on the hot path. The shell runs a statement on a scoped thread only when it has a terminal, so the JSONL path and every snapshot around it spawn nothing, polls twenty times a second, and paints nothing for the first four hundred milliseconds: a statement that answers immediately must not flicker a progress line on the way. What it paints is the elapsed time, the rows read grouped in threes, and the fact that `Ctrl-C` stops it, redrawn in place and erased before the answer goes out. A statement the user stopped says so and says the session survived, the process exits 130 if that was the last thing it did, which is the number a shell reports for a process killed by the signal, and a host on the C ABI reads the same fact as `ZU_INTERRUPTED`. +Progress rides on the same handle, because a person watching a statement that has taken ten seconds is asking a question the engine can already answer. The count is rows read from storage, incremented once per chunk at the scan and once per claimed morsel in the pipeline rather than once per row, so the counter is a relaxed add per thousands of rows and not a shared word on the hot path. The shell runs a statement on a scoped thread only when it has a terminal, so the JSONL path and every snapshot around it spawn nothing, polls two hundred times a second, and paints nothing for the first four hundred milliseconds: a statement that answers immediately must not flicker a progress line on the way. What it paints is the elapsed time, the rows read grouped in threes, and the fact that `Ctrl-C` stops it, redrawn in place and erased before the answer goes out. A statement the user stopped says so and says the session survived, the process exits 130 if that was the last thing it did, which is the number a shell reports for a process killed by the signal, and a host on the C ABI reads the same fact as `ZU_INTERRUPTED`. `zu shell --format jsonl` is the same session over a pipe, one JSON frame per line, for a harness or an editor rather than a person: `query`, `prepare`/`execute`/`close_stmt`, `explain`, `explain_analyze`, `hello`, `quit`. The two explain frames are deliberately distinct. `explain_analyze` runs the statement and reports what each operator actually did; `explain` compiles and renders and runs nothing, which is the one a caller can afford beside a latency it measured separately, and the only one that is safe to ask about a statement that writes.