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 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); } }