From c6269ad3dd873736acd63abdea3879aed46e3d98 Mon Sep 17 00:00:00 2001 From: dev Date: Sun, 11 Oct 2026 21:08:35 +0530 Subject: [PATCH] Honour RUST_LOG, add load and scale benchmarks The subscriber was pinned to DEBUG, so RUST_LOG=warn was ignored and sqlx logged every statement to stderr in production. Now an EnvFilter defaults to info with sqlx at warn; RUST_LOG=debug restores the query log. Three benchmarks, so the hosting numbers come from measurement rather than guesswork: scripts/bench.py for latency and throughput, bench_write.py for the autosave and submit path under concurrent students, and bench_scale.py which builds a database at the real bank's size (10,905 questions, 2,000 students, 12,000 papers, 900k answers) to report disk cost and query timings. --- Cargo.lock | 39 ++++++++++ Cargo.toml | 2 +- scripts/bench.py | 68 +++++++++++++++++ scripts/bench_scale.py | 164 +++++++++++++++++++++++++++++++++++++++++ scripts/bench_write.py | 83 +++++++++++++++++++++ src/main.rs | 7 +- 6 files changed, 361 insertions(+), 2 deletions(-) create mode 100755 scripts/bench.py create mode 100755 scripts/bench_scale.py create mode 100755 scripts/bench_write.py diff --git a/Cargo.lock b/Cargo.lock index 64a27f8..d8270c5 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2,6 +2,15 @@ # It is not intended for manual editing. version = 4 +[[package]] +name = "aho-corasick" +version = "1.1.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c982642fa9e8606056828ee9a8505737230110bb1099153c79efe865c59d12ba" +dependencies = [ + "memchr", +] + [[package]] name = "allocator-api2" version = "0.2.21" @@ -1325,6 +1334,15 @@ version = "0.1.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "4050469837a6ff301cd14c1f8f24f88549e6d548f24f64e2148eb0f72cebc51f" +[[package]] +name = "matchers" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d1525a2a28c7f4fa0fc98bb91ae755d1e2d1505079e05539e35bc876b5d65ae9" +dependencies = [ + "regex-automata", +] + [[package]] name = "matchit" version = "0.8.4" @@ -1752,6 +1770,23 @@ dependencies = [ "bitflags", ] +[[package]] +name = "regex-automata" +version = "0.4.18" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ad8553b9b26413251cbf30e620595c7a41b3887f03da04579c0e6b0d6a06b4b2" +dependencies = [ + "aho-corasick", + "memchr", + "regex-syntax", +] + +[[package]] +name = "regex-syntax" +version = "0.8.11" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d6f6ff9a378485b298a5286656da665ba74413d36db0979633275d2e708145d4" + [[package]] name = "reqwest" version = "0.13.5" @@ -2752,10 +2787,14 @@ version = "0.3.23" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "cb7f578e5945fb242538965c2d0b04418d38ec25c79d160cd279bf0731c8d319" dependencies = [ + "matchers", "nu-ansi-term", + "once_cell", + "regex-automata", "sharded-slab", "smallvec", "thread_local", + "tracing", "tracing-core", "tracing-log", ] diff --git a/Cargo.toml b/Cargo.toml index 507f408..072d81a 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -18,7 +18,7 @@ tokio = { version = "1.53.2", features = ["full"] } tower-cookies = "0.11.0" tower-http = { version = "0.7.1", features = ["fs"] } tracing = "0.1.44" -tracing-subscriber = "0.3.23" +tracing-subscriber = { version = "0.3.23", features = ["env-filter"] } uuid = { version = "1.28.0", features = ["v4", "serde"] } [dev-dependencies] diff --git a/scripts/bench.py b/scripts/bench.py new file mode 100755 index 0000000..8977f21 --- /dev/null +++ b/scripts/bench.py @@ -0,0 +1,68 @@ +#!/usr/bin/env python3 +"""Load check for the PYQ server. + + scripts/bench.py [requests] [concurrency] + +Reports latency percentiles per route and sustained throughput under load. +""" +import http.cookiejar +import statistics +import sys +import time +import urllib.request +from concurrent.futures import ThreadPoolExecutor + +BASE = sys.argv[1] if len(sys.argv) > 1 else "http://127.0.0.1:8171" +N = int(sys.argv[2]) if len(sys.argv) > 2 else 300 +CONC = int(sys.argv[3]) if len(sys.argv) > 3 else 20 + +jar = http.cookiejar.CookieJar() +opener = urllib.request.build_opener(urllib.request.HTTPCookieProcessor(jar)) + + +def sign_in(): + body = b"name=Bench&email=bench@example.com&next=/build" + req = urllib.request.Request(f"{BASE}/student", data=body, method="POST") + opener.open(req).read() + + +def timed(path): + t0 = time.perf_counter() + with opener.open(BASE + path) as r: + r.read() + return (time.perf_counter() - t0) * 1000 + + +def percentile(values, p): + s = sorted(values) + return s[min(int(len(s) * p), len(s) - 1)] + + +def report(path, samples): + print( + f" {path:<22} n={len(samples):<5} " + f"p50={statistics.median(samples):6.2f}ms " + f"p95={percentile(samples, .95):6.2f}ms " + f"max={max(samples):6.2f}ms" + ) + + +def load(path, concurrency): + t0 = time.perf_counter() + with ThreadPoolExecutor(max_workers=concurrency) as pool: + list(pool.map(lambda _: timed(path), range(N))) + return N / (time.perf_counter() - t0) + + +sign_in() +print(f"=== {BASE} | {N} requests | {CONC} parallel ===") +print("sequential latency") +for p in ["/", "/static/style.css", "/build", "/dashboard", "/history"]: + report(p, [timed(p) for _ in range(min(N, 50))]) + +print(f"throughput at {CONC} concurrent") +for p in ["/", "/build"]: + warm = [timed(p) for _ in range(CONC * 2)] + rps = load(p, CONC) + report(p, warm) + print(f" -> {p:<20} {rps:,.0f} req/s sustained") \ No newline at end of file diff --git a/scripts/bench_scale.py b/scripts/bench_scale.py new file mode 100755 index 0000000..0892e97 --- /dev/null +++ b/scripts/bench_scale.py @@ -0,0 +1,164 @@ +#!/usr/bin/env python3 +"""Estimates disk and index cost at the real bank's scale. + +Builds a throwaway database holding 10,905 questions plus simulated student +activity, then reports the size on disk and the query timings that decide +whether SQLite is still the right store. + scripts/bench_scale.py [db-path] +""" +import os +import random +import sqlite3 +import sys +import time + +DB = sys.argv[1] if len(sys.argv) > 1 else "/tmp/scale.db" +QUESTIONS = 10905 +SUBTOPICS = 349 +STUDENTS = 2000 +PAPERS_PER_STUDENT = 6 +QUESTIONS_PER_PAPER = 75 + +for suffix in ("", "-wal", "-shm"): + try: + os.remove(DB + suffix) + except FileNotFoundError: + pass + +con = sqlite3.connect(DB) +con.executescript( + """ + PRAGMA journal_mode=WAL; + CREATE TABLE users(id TEXT PRIMARY KEY, name TEXT, email TEXT UNIQUE, created_at TEXT); + CREATE TABLE chapters(id INTEGER PRIMARY KEY, subject TEXT, name TEXT); + CREATE TABLE subtopics(id INTEGER PRIMARY KEY, chapter_id INTEGER, name TEXT); + CREATE TABLE questions(id INTEGER PRIMARY KEY, subject TEXT, chapter_id INTEGER, + subtopic_id INTEGER, qtype TEXT, stem TEXT, opt_a TEXT, opt_b TEXT, opt_c TEXT, + opt_d TEXT, answer TEXT, difficulty TEXT, year INTEGER, shift TEXT, solution TEXT); + CREATE TABLE papers(id TEXT PRIMARY KEY, user_id TEXT, title TEXT, + duration_min INTEGER, created_at TEXT, share_token TEXT); + CREATE TABLE paper_questions(paper_id TEXT, question_id INTEGER, ord INTEGER, + PRIMARY KEY(paper_id, question_id)); + CREATE TABLE attempts(id TEXT PRIMARY KEY, paper_id TEXT, user_id TEXT, + started_at TEXT, submitted_at TEXT, score INTEGER, max_score INTEGER, used_secs INTEGER); + CREATE TABLE answers(attempt_id TEXT, question_id INTEGER, selected TEXT, + marked_review INTEGER, time_secs INTEGER, PRIMARY KEY(attempt_id, question_id)); + CREATE TABLE sessions(token TEXT PRIMARY KEY, user_id TEXT, created_at TEXT); + CREATE TABLE seen_questions(user_id TEXT, question_id INTEGER, + PRIMARY KEY(user_id, question_id)); + CREATE TABLE mistake_tags(attempt_id TEXT, question_id INTEGER, tag TEXT, + PRIMARY KEY(attempt_id, question_id, tag)); + """ +) + +rng = random.Random(7) +stem = ("A particle of mass 2 kg moves along the x axis under a restoring force " + "F = -kx. If k = 200 N/m the time period of small oscillations is:") +opt = "A 0.1 s" * 4 + +t0 = time.perf_counter() +con.executemany("INSERT INTO chapters VALUES(?,?,?)", + [(i, ["Physics", "Chemistry", "Maths"][i % 3], f"Chapter {i}") for i in range(1, 28)]) +con.executemany("INSERT INTO subtopics VALUES(?,?,?)", + [(i, i % 27 + 1, f"Subtopic {i}") for i in range(1, SUBTOPICS + 1)]) +con.executemany( + "INSERT INTO questions VALUES(?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)", + [(i, ["Physics", "Chemistry", "Maths"][i % 3], i % 27 + 1, i % SUBTOPICS + 1, + "MCQ" if i % 4 else "NUM", stem, opt, opt, opt, opt, "ABCD"[i % 4], + ["Easy", "Medium", "Hard"][i % 3], 2020 + i % 7, f"S{i % 4 + 1}", stem) + for i in range(1, QUESTIONS + 1)]) +con.commit() +print(f"seeded {QUESTIONS:,} questions in {time.perf_counter()-t0:.1f}s") + +# Indexes the app would need for subtopic filtering and per-user lookups. +t0 = time.perf_counter() +con.executescript( + """ + CREATE INDEX q_chapter ON questions(chapter_id); + CREATE INDEX q_subtopic ON questions(subtopic_id); + CREATE INDEX pq_question ON paper_questions(question_id); + CREATE INDEX a_paper ON attempts(paper_id); + CREATE INDEX a_user ON attempts(user_id, submitted_at); + CREATE INDEX ans_question ON answers(question_id); + CREATE INDEX seen_q ON seen_questions(question_id); + """ +) +con.commit() +print(f"indexes built in {time.perf_counter()-t0:.1f}s") + +t0 = time.perf_counter() +papers = STUDENTS * PAPERS_PER_STUDENT +for s in range(STUDENTS): + uid = f"user-{s}" + con.execute("INSERT INTO users VALUES(?,?,?,?)", (uid, f"Student {s}", f"s{s}@x.com", "2026-01-01")) + for _ in range(PAPERS_PER_STUDENT): + pid, aid = f"paper-{s}-{_}", f"att-{s}-{_}" + con.execute("INSERT INTO papers VALUES(?,?,?,?,?,?)", + (pid, uid, "Paper", 180, "2026-01-01", f"tok{pid}")) + picks = rng.sample(range(1, QUESTIONS + 1), QUESTIONS_PER_PAPER) + con.executemany("INSERT INTO paper_questions VALUES(?,?,?)", + [(pid, q, n) for n, q in enumerate(picks)]) + con.execute("INSERT INTO attempts VALUES(?,?,?,?,?,?,?,?)", + (aid, pid, uid, "2026-01-01", "2026-01-01", 180, 300, 5400)) + con.executemany("INSERT INTO answers VALUES(?,?,?,?,?)", + [(aid, q, "ABCD"[q % 4], q % 5 == 0, 40 + q % 60) for q in picks]) + # A question already answered on an earlier paper is not "new" for this student. + con.executemany("INSERT OR IGNORE INTO seen_questions VALUES(?,?)", + [(uid, q) for q in picks]) +con.commit() +elapsed = time.perf_counter() - t0 +print(f"seeded {STUDENTS:,} students / {papers:,} papers in {elapsed:.1f}s") +con.execute("VACUUM") +con.commit() +con.close() + + +def mb(path): + total = 0 + for suffix in ("", "-wal", "-shm"): + try: + total += os.path.getsize(path + suffix) + except FileNotFoundError: + pass + return total / 1024 / 1024 + + +db_mb = mb(DB) +print(f"\n=== {DB} ===") +print(f" questions {QUESTIONS:>9,}") +print(f" students {STUDENTS:>9,}") +print(f" papers {papers:>9,}") +print(f" answer rows {papers * QUESTIONS_PER_PAPER:>9,}") +print(f" on disk {db_mb:>9.1f} MB") +print(f" per paper {db_mb * 1024 / papers:.1f} KB") +print(f" per student {db_mb * 1024 / STUDENTS:.1f} KB") + +con = sqlite3.connect(f"file:{DB}?mode=ro", uri=True) +print("\nquery timings at this size") +queries = { + "paper builder (subtopic filter)": + "SELECT q.id FROM questions q WHERE q.subtopic_id IN (?, ?) AND q.chapter_id IN (?, ?) " + "AND q.id NOT IN (SELECT question_id FROM seen_questions WHERE user_id=?) LIMIT 75", + "seen-question exclusion (450 rows)": + "SELECT q.id FROM questions q WHERE q.id NOT IN " + "(SELECT question_id FROM seen_questions WHERE user_id=?)", + "dashboard topic rollup": + "SELECT c.name, s.name, COUNT(*) FROM answers a JOIN attempts at ON at.id=a.attempt_id " + "JOIN questions q ON q.id=a.question_id JOIN chapters c ON c.id=q.chapter_id " + "JOIN subtopics s ON s.id=q.subtopic_id WHERE at.user_id=? GROUP BY c.name, s.name", + "history list": + "SELECT a.id, a.score FROM attempts a WHERE a.user_id=? ORDER BY a.started_at DESC", + "mistake-tag rollup": + "SELECT tag, COUNT(*) FROM mistake_tags WHERE attempt_id IN " + "(SELECT id FROM attempts WHERE user_id=?) GROUP BY tag", +} +uid = "user-3" +topics = ",".join(str(i) for i in range(1, 31)) +chapters = ",".join(str(i) for i in range(1, 10)) +for label, q in queries.items(): + # Bind exactly what each statement declares, in order. + n_list = q.count("?") - 1 + params = [int(i) for i in topics.split(",")][:n_list] + [uid] + t0 = time.perf_counter() + rows = con.execute(q, tuple(params)).fetchall() + print(f" {label:<34} {(time.perf_counter()-t0)*1000:7.1f} ms ({len(rows)} rows)") diff --git a/scripts/bench_write.py b/scripts/bench_write.py new file mode 100755 index 0000000..85fe0cd --- /dev/null +++ b/scripts/bench_write.py @@ -0,0 +1,83 @@ +#!/usr/bin/env python3 +"""Write-path check: many concurrent students autosaving and submitting at once. + +SQLite serialises writers, so this is where the ceiling actually lives. + scripts/bench_write.py +""" +import http.cookiejar +import sqlite3 +import statistics +import sys +import time +import urllib.parse +import urllib.request +from concurrent.futures import ThreadPoolExecutor + +BASE = sys.argv[1] if len(sys.argv) > 1 else "http://127.0.0.1:8171" +STUDENTS = int(sys.argv[2]) if len(sys.argv) > 2 else 20 +QUESTIONS = int(sys.argv[3]) if len(sys.argv) > 3 else 12 +DB = sys.argv[4] if len(sys.argv) > 4 else "/tmp/bench.db" + + +def student_session(i): + jar = http.cookiejar.CookieJar() + opener = urllib.request.build_opener(urllib.request.HTTPCookieProcessor(jar)) + body = urllib.parse.urlencode( + {"name": f"Load{i}", "email": f"load{i}@example.com", "next": "/build"} + ).encode() + opener.open(urllib.request.Request(f"{BASE}/student", data=body, method="POST")).read() + return opener + + +def run(i): + opener = student_session(i) + form = urllib.parse.urlencode( + {"chapters": "1,2,3,4,5,6,7,8,9", "count": QUESTIONS, "duration": 24, "unseen_only": "on"} + ).encode() + r = opener.open(urllib.request.Request(f"{BASE}/build", data=form, method="POST")) + paper = r.geturl().rsplit("/", 1)[-1].split("?")[0] + + r = opener.open(urllib.request.Request(f"{BASE}/attempt/{paper}", data=b"", method="POST")) + attempt = r.geturl().split("run=")[-1] + + con = sqlite3.connect(f"file:{DB}?mode=ro", uri=True) + ids = [x[0] for x in con.execute( + "SELECT question_id FROM paper_questions WHERE paper_id=? ORDER BY ord", (paper,) + )] + con.close() + + # Autosave each answer, which is what the exam screen does while a student works. + saves = [] + for q in ids: + payload = b'{"answers":[{"question_id":%d,"selected":"A","marked_review":false,"time_secs":30}]}' % q + t0 = time.perf_counter() + opener.open( + urllib.request.Request( + f"{BASE}/attempt/{attempt}/answer", data=payload, + headers={"content-type": "application/json"}, method="POST", + ) + ).read() + saves.append((time.perf_counter() - t0) * 1000) + + t0 = time.perf_counter() + opener.open(urllib.request.Request(f"{BASE}/attempt/{attempt}/submit", data=b"", method="POST")).read() + submit_ms = (time.perf_counter() - t0) * 1000 + return saves, submit_ms + + +t0 = time.perf_counter() +with ThreadPoolExecutor(max_workers=STUDENTS) as pool: + results = list(pool.map(run, range(STUDENTS))) +elapsed = time.perf_counter() - t0 + +saves = [ms for r, _ in results for ms in r] +submits = [ms for _, ms in results] +saves.sort() +total_saves = len(saves) + +print(f"=== {STUDENTS} concurrent students x {QUESTIONS} questions ===") +print(f" wall clock {elapsed:.2f}s") +print(f" autosaves {total_saves} in {elapsed:.2f}s = {total_saves/elapsed:,.0f} writes/s") +print(f" autosave latency p50={statistics.median(saves):.1f}ms " + f"p95={saves[int(len(saves)*.95)]:.1f}ms max={saves[-1]:.1f}ms") +print(f" submit latency p50={statistics.median(submits):.1f}ms max={max(submits):.1f}ms") \ No newline at end of file diff --git a/src/main.rs b/src/main.rs index 1d7665b..02f796e 100644 --- a/src/main.rs +++ b/src/main.rs @@ -29,7 +29,12 @@ fn hx(body: String, code: StatusCode) -> impl IntoResponse { #[tokio::main] async fn main() -> anyhow::Result<()> { - tracing_subscriber::fmt().with_max_level(tracing::Level::DEBUG).init(); + // Defaults to info; RUST_LOG=debug adds the query log. + tracing_subscriber::fmt() + .with_env_filter( + tracing_subscriber::EnvFilter::try_from_default_env().unwrap_or_else(|_| "zenith_pyq_clone=info,sqlx=warn".into()), + ) + .init(); let db_path = std::env::var("PYQ_DB").unwrap_or_else(|_| "pyq.db".into()); let base = std::env::var("PYQ_BASE").unwrap_or_else(|_| String::new()); let addr = std::env::var("PYQ_ADDR").unwrap_or_else(|_| "127.0.0.1:8080".into());