ci: probe the tic statement's analysis cost on a runner (do not merge)

.github/workflows/probe.yml

@@ -0,0 +1,42 @@
+# Temporary: measures the tic statement's analysis cost on a runner.
+
+name: probe
+
+on:
+  pull_request:
+    branches: [main]
+  workflow_dispatch:
+
+permissions:
+  contents: read
+
+env:
+  CLICKHOUSE_USER: default
+  CLICKHOUSE_PASSWORD: clickdoom
+  CLICKHOUSE_HOST: localhost
+  CLICKHOUSE_HTTP_PORT: "8123"
+
+jobs:
+  probe:
+    if: github.head_ref == 'ci/probe-analysis-cost' || github.event_name == 'workflow_dispatch'
+    runs-on: ubuntu-latest
+    permissions:
+      contents: read
+    timeout-minutes: 120
+    steps:
+      - uses: actions/checkout@3d3c42e5aac5ba805825da76410c181273ba90b1 # v7.0.1
+        with:
+          persist-credentials: false
+      - uses: Swatinem/rust-cache@6323deb102c322ba6fcbdcafc7e3dddab59af2b6 # v2.9.2
+      - name: Start the pinned ClickHouse
+        run: make up
+      - name: Build the driver and the batch probe test
+        run: |
+          cargo build --locked --release -p clickdoom-driver
+          cargo test --locked --release -p clickdoom-native --features clickhouse-tests \
+              --test probe_batch_live --no-run 2>&1 | tee build-test.log
+          sed -n 's/.*Executable .*(\(.*\))$/\1/p' build-test.log | tail -n 1 > batch-bin.txt
+          cat batch-bin.txt
+      - name: Probe
+        run: |
+          BATCH_BIN=$(cat batch-bin.txt) bash scripts/probe-analysis-cost.sh

native/src/resident/stream.rs

@@ -89,7 +89,7 @@ pub const TIC_TIMEOUT: Duration = Duration::from_secs(5);
 /// How long the first tic after a resident statement opens may take, which
 /// is the statement being analysed. Sized for a CI runner under load,
 /// several times slower than a quiet development machine.
-pub const FIRST_TIC_TIMEOUT: Duration = Duration::from_secs(600);
+pub const FIRST_TIC_TIMEOUT: Duration = Duration::from_secs(1800);
 
 /// Anything that stops a resident statement from opening or from taking
 /// another row.

native/tests/probe_batch_live.rs

@@ -0,0 +1,24 @@
+//! One tic through `run_statement`, for the analysis-cost probe workflow.
+#![cfg(feature = "clickhouse-tests")]
+
+use clickdoom_native::sql::sim;
+use clickdoom_native::{load, sql, wad::Wad};
+
+mod support;
+
+use support::db::Fixture;
+
+#[tokio::test]
+async fn one_batch_tic() {
+    let bytes = support::doom1();
+    let wad = Wad::parse(&bytes).unwrap();
+    let fixture = Fixture::create("probe_batch").await;
+    let db = fixture.database.clone();
+    let mut plan = load::plan(&db, &wad);
+    plan.extend(sql::level_statements(&db, support::MAP, support::DEMO));
+    plan.extend(sim::load_statements(&db));
+    plan.extend(sim::tick::demo_statement(&db, 1, 1));
+    let result = fixture.execute(&plan).await;
+    fixture.finish().await;
+    result.unwrap();
+}

scripts/probe-analysis-cost.sh

@@ -0,0 +1,74 @@
+#!/usr/bin/env bash
+# Measures one resident stage1/stage2 analysis alone, four at once, and four
+# at once beside one run_statement batch tic. Prints system.query_log rows.
+set -uo pipefail
+
+CH="http://localhost:8123/"
+q() { curl -fsS -u "default:${CLICKHOUSE_PASSWORD}" --data-binary "$1" "$CH"; }
+BIN=target/release/clickdoom
+FIXTURE=$(ls refemu/probe/fixtures/*.tsv)
+
+echo "== runner"
+nproc
+grep -m1 'model name' /proc/cpuinfo
+free -g | sed -n 1,2p
+q "SELECT version()"
+
+load() {
+  q "CREATE DATABASE IF NOT EXISTS $1"
+  "$BIN" native load --fresh --database "$1" </dev/null >"load-$1.log" 2>&1
+  echo "load $1 exit=$?"
+}
+diffrun() {
+  local start end code
+  start=$(date +%s)
+  "$BIN" native diff 2 --probe "$FIXTURE" --database "$1" </dev/null >"diff-$1.log" 2>&1
+  code=$?
+  end=$(date +%s)
+  echo "diff $1 exit=$code wall=$((end - start))s"
+  tail -n 2 "diff-$1.log"
+}
+
+for d in pa pb1 pb2 pb3 pb4 pc1 pc2 pc3 pc4; do load "$d"; done
+
+echo "== (a) one session alone"
+diffrun pa
+
+echo "== (b) four sessions at once"
+for d in pb1 pb2 pb3 pb4; do diffrun "$d" & done
+wait
+
+echo "== (c) four sessions at once beside one run_statement batch tic"
+for d in pc1 pc2 pc3 pc4; do diffrun "$d" & done
+(
+  start=$(date +%s)
+  "$BATCH_BIN" --test-threads 1 >batch.log 2>&1
+  code=$?
+  end=$(date +%s)
+  echo "batch exit=$code wall=$((end - start))s"
+  tail -n 3 batch.log
+) &
+wait
+
+q "SYSTEM FLUSH LOGS"
+echo "== query_log, INSERTs whose analysis took over a second"
+q "
+SELECT
+    replaceRegexpOne(extract(query, 'INSERT INTO\\s+([A-Za-z0-9_]+)\\.'), '^clickdoom_native_test_[0-9]+_', '') AS db,
+    multiIf(query_id LIKE '%-sim2-%', 'resident stage2',
+            query_id LIKE '%-sim-%', 'resident stage1',
+            match(query, 'INSERT INTO\\s+\\S+\\.native_stage\\s'), 'batch stage1',
+            'batch stage2') AS kind,
+    round(ProfileEvents['QueryAnalysisMicroseconds'] / 1e6, 1) AS analysis_s,
+    round(ProfileEvents['UserTimeMicroseconds'] / 1e6, 1) AS user_s,
+    round(ProfileEvents['SystemTimeMicroseconds'] / 1e6, 1) AS system_s,
+    round(query_duration_ms / 1e3, 1) AS duration_s,
+    formatReadableSize(memory_usage) AS peak_memory,
+    type,
+    event_time
+FROM system.query_log
+WHERE type != 'QueryStart'
+  AND query_kind = 'Insert'
+  AND ProfileEvents['QueryAnalysisMicroseconds'] > 1000000
+ORDER BY event_time, db, kind
+FORMAT PrettyCompactMonoBlock"