From 72d6da62c251dd3d410504b26585066959052069 Mon Sep 17 00:00:00 2001 From: TimelordUK Date: Wed, 16 Sep 2026 18:54:51 +0100 Subject: [PATCH 1/2] perf: drop per-row logging from column resolution `ExecutionContext::resolve_column_index` logged every successful resolution. WHERE resolves each column operand of each row through it, and non-interactive mode records TRACE to a ring buffer and a log file, so the log cost more than the comparison it resolved for. The error paths keep their messages. Best of 3 over trades_100000.csv, ~2.4 s of which is the CSV load: WHERE price > quantity 3.34 s -> 2.42 s WHERE price > 100 2.83 s -> 2.42 s WHERE trader LIKE 'Trader0%' 2.87 s -> 2.43 s All three now run in load time. Follow-up to the same finding in R13 slice 4 (per-node logging in the value evaluator); it was the ~1 s that WHERE's own comparison path still carried afterwards. Parity report byte-identical, 826 lib + 498 integration tests pass. Co-Authored-By: Claude Opus 5 (1M context) --- src/data/query_engine.rs | 21 +++++---------------- 1 file changed, 5 insertions(+), 16 deletions(-) diff --git a/src/data/query_engine.rs b/src/data/query_engine.rs index f389d2d0..5eeb34ab 100644 --- a/src/data/query_engine.rs +++ b/src/data/query_engine.rs @@ -102,6 +102,11 @@ impl ExecutionContext { /// 2. If column_ref has no prefix: /// a. Try simple column name lookup: "amount" /// b. Try as qualified name if it contains a dot: "table.column" + /// + /// No logging on the success paths: WHERE resolves every column operand of + /// every row through here, and non-interactive mode records TRACE to a + /// file, so a `debug!` per resolution cost ~470 ms per column operand over + /// 100k rows -- more than the comparison it was resolving for. pub fn resolve_column_index(&self, table: &DataTable, column_ref: &ColumnRef) -> Result { if let Some(table_prefix) = &column_ref.table_prefix { // Qualified column reference: resolve the alias first @@ -110,19 +115,11 @@ impl ExecutionContext { // Try qualified lookup: "actual_table.column" let qualified_name = format!("{}.{}", actual_table, column_ref.name); if let Some(idx) = table.find_column_by_qualified_name(&qualified_name) { - debug!( - "Resolved {}.{} -> qualified column '{}' at index {}", - table_prefix, column_ref.name, qualified_name, idx - ); return Ok(idx); } // Fall back to unqualified lookup if let Some(idx) = table.get_column_index(&column_ref.name) { - debug!( - "Resolved {}.{} -> unqualified column '{}' at index {}", - table_prefix, column_ref.name, column_ref.name, idx - ); return Ok(idx); } @@ -138,20 +135,12 @@ impl ExecutionContext { } else { // Unqualified column reference if let Some(idx) = table.get_column_index(&column_ref.name) { - debug!( - "Resolved unqualified column '{}' at index {}", - column_ref.name, idx - ); return Ok(idx); } // If the column name contains a dot, try it as a qualified name if column_ref.name.contains('.') { if let Some(idx) = table.find_column_by_qualified_name(&column_ref.name) { - debug!( - "Resolved '{}' as qualified column at index {}", - column_ref.name, idx - ); return Ok(idx); } } From ab0df320f23a712d6ec17ad3eb164c996d90fcff Mon Sep 17 00:00:00 2001 From: TimelordUK Date: Wed, 16 Sep 2026 18:55:06 +0100 Subject: [PATCH 2/2] docs(r13): record the column-resolution logging follow-up Co-Authored-By: Claude Opus 5 (1M context) --- docs/ENGINE_REFACTORING.md | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/docs/ENGINE_REFACTORING.md b/docs/ENGINE_REFACTORING.md index c175e1fb..368aa207 100644 --- a/docs/ENGINE_REFACTORING.md +++ b/docs/ENGINE_REFACTORING.md @@ -631,10 +631,14 @@ feature work**, and so we can tell the difference between "this is awkward" and twin yet (slice 5). `LIKE` has a regex cache in `EvaluationContext` that the value evaluator's matcher does not use. `AND` / `OR` / `NOT` / `CASE` stay recursive until their children can be WHERE-only method calls no longer. - - *Noticed, not done:* `WHERE price > quantity` (WHERE's own path) still runs - ~1 s over load where the delegated shapes do not — likely more per-row - logging in or around the WHERE loop; and window evaluation logs `info!` - timings per row (out of R13's scope). + - *The same finding, once more (2026-09-16).* `WHERE price > quantity` still + carried ~1 s over load after the above. Same cause, one level down: + `ExecutionContext::resolve_column_index` logged every successful + resolution, and WHERE resolves each column operand of each row through it — + ~470 ms per column operand over 100k rows. Removed; col-col 3.34 → 2.42 s, + `price > 100` 2.83 → 2.42 s, `LIKE` 2.87 → 2.43 s, all now at load time. + Still outstanding: window evaluation logs `info!` timings per row (out of + R13's scope). - **Slices, in the R10 pattern — no-op slices kept apart from the one that changes answers:** 1. ✅ **Pin the divergences, no engine change.** *(Done 2026-09-13.)* A per-operator matrix run through