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.
This commit is contained in:
dev
parent
3f88f6c388
commit
c6269ad3dd
6 changed files with 361 additions and 2 deletions
39
Cargo.lock
generated
39
Cargo.lock
generated
|
|
@ -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",
|
||||
]
|
||||
|
|
|
|||
|
|
@ -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]
|
||||
|
|
|
|||
68
scripts/bench.py
Executable file
68
scripts/bench.py
Executable file
|
|
@ -0,0 +1,68 @@
|
|||
#!/usr/bin/env python3
|
||||
"""Load check for the PYQ server.
|
||||
|
||||
scripts/bench.py <base-url> [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")
|
||||
164
scripts/bench_scale.py
Executable file
164
scripts/bench_scale.py
Executable file
|
|
@ -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)")
|
||||
83
scripts/bench_write.py
Executable file
83
scripts/bench_write.py
Executable file
|
|
@ -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 <base-url> <students> <questions>
|
||||
"""
|
||||
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")
|
||||
|
|
@ -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());
|
||||
|
|
|
|||
Loading…
Add table
Reference in a new issue