diff --git a/.github/workflows/probe.yml b/.github/workflows/probe.yml new file mode 100644 index 0000000..9d8ddb6 --- /dev/null +++ b/.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 diff --git a/native/src/resident/stream.rs b/native/src/resident/stream.rs index f934b8b..7859d65 100644 --- a/native/src/resident/stream.rs +++ b/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. diff --git a/native/tests/probe_batch_live.rs b/native/tests/probe_batch_live.rs new file mode 100644 index 0000000..4350827 --- /dev/null +++ b/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(); +} diff --git a/scripts/probe-analysis-cost.sh b/scripts/probe-analysis-cost.sh new file mode 100644 index 0000000..d596e21 --- /dev/null +++ b/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" "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" "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"