Add per-stage throughput instrumentation; fix memory-benchmark accuracy
End-to-end throughput says how fast the pipeline is, not which stage is the reason. The four stages run concurrently behind their own queues, so the pipeline's rate *is* the slowest stage's rate and the others are invisible in it. Nothing outside the server can recover them either: known/, unknown/ and text/ are transient, and a file can cross one between two directory polls, so an external sampler misses exactly the stages worth measuring. So the pipeline counts its own work, and bin/bench.jl turns two scrapes into rates. - src/stats.jl: per-stage counters (completed/failed, bytes, busy_ns, blocked_ns, in_flight) plus intake counters, monotonic since startup in the Prometheus style — rates are the reader's job, so a scrape is stateless and two readers can't disturb each other. Recorded in worker_loop, the one place every stage's work passes through, so a new stage is instrumented the moment it is wired up and never on the read path. - src/server.jl: GET /stats. An ordinary Oxygen route (no body to stream), unlike /upload. Intake counts files at the point they become stage 1's problem, so intake totals and stage-1 arrivals refer to the same files. - src/queue.jl: capacity(q) joins length on the introspection seam — a depth of 900 means nothing without knowing whether the limit is 1000 or 1_000_000. utilization = (busy - blocked) / (window * workers) is the number that names the bottleneck: throughput alone can't tell a saturated stage from one starved by the stage ahead of it, since both report the same files/s. blocked_ns is what keeps that true. Stages 1 and 3 apply blocking backpressure — a full downstream queue means parking, not dropping — and that wait is inside the handler, so counting it as busy would pin stage 1 at 1.0 whenever stage 2 is the real jam, making every stage upstream of a jam look like the jam. enqueue_blocking! wraps the retry loop so the wait is measurable at all, and keeps the three routing paths from drifting into three different backoff behaviours. Measured (400 mixed files, 16 KiB, concurrency 16): stage 4 is the constraint at 0.87 utilization and 853 ms/file — github-linguist is a process spawn per file — while stages 1 and 3 idle under 0.10. Verified the blocked accounting against a deliberately starved server (FS_TEXT_WORKERS=1, FS_TEXT_QUEUE_CAPACITY=2): stage 3 reported 100% blocked at 0.0 utilization rather than looking saturated too. bin/bench_model.jl: the classifier alone, no server or queue in the way, because stage 1's 38.7 ms/file cannot plausibly be a 32-64-16-2 MLP. It isn't: Lux.apply is 2.3 us, read_features 4.2-6.0 us (flat across 1 KiB - 256 MiB, as the seek-to-tail design intends), classify() 8.4 us — so ~99.98% of stage 1 is rename, logging and contention, and the file read costs 3x the inference. Two findings: batching would buy ~13x (179 ns/file at batch 512 vs 2.34 us at batch 1), and inference does not scale past ~4 threads. A pure-compute control kernel runs the same sweep to place the blame — it reaches 14.3x at 16 tasks on this box, so the machine parallelizes and Lux.apply does not. BLAS threads and GC are both ruled out; the cause is inside Lux and is not diagnosed here. Three bugs in the memory measurement, all of which produced wrong answers that looked plausible: - detect_pid matched any process with the launch command in its argv, including the shell that started the server — one run reported 3.64 MiB as the server's memory. Candidates are now filtered by /proc/<pid>/comm, what the process is rather than what its arguments say; no pattern over argv can do that. - Baseline RSS was read *before* clear_refs reset the peak counter, so the two numbers had different origins. The 2 GiB run reported -1.01 MiB of growth; reading the baseline after the reset makes it 31.3 MiB. - Negative growth is now reported as "none measurable" rather than a negative figure, which reads as a memory saving. Re-measuring with those fixed keeps the claim that matters — growth is flat in file size (14-31 MiB from 256 MiB to 2 GiB), so nothing is buffering — but the concurrency coefficient does not survive: a freshly started server settles anywhere in an ~860-985 MiB band, so baseline variance is comparable to the growth being measured, and the old table quoted megabyte precision the measurement never supported. README now states the shape, requires a ~30s settle before a memory run, and says plainly that linear-in-concurrency is undemonstrated rather than leaving an authoritative-looking number. README also gains a single runnable sequence for all three harnesses: the server prerequisite was never shown inline, so following the benchmarking section top-to-bottom just produced "cannot reach /health". Tests: 276 pass (41 new) — the blocked-vs-busy split, worker_loop draining in_flight through a throwing handler, and the JSON round-trip of the field names bench.jl reads.
This commit is contained in:
169
test/runtests.jl
169
test/runtests.jl
@@ -5,10 +5,12 @@ using JSON3
|
||||
# Pull internals into scope. These aren't exported (only `run` is), but the
|
||||
# whole risk profile of this pipeline lives in these functions, so we test them
|
||||
# directly rather than only through the HTTP surface.
|
||||
using FileServer: Job, Config, ChannelQueue, enqueue!, dequeue!, length,
|
||||
using FileServer: Job, Config, ChannelQueue, enqueue!, dequeue!, close!, length,
|
||||
sanitize_filename, recover_dir!, normalize_metadata,
|
||||
build_metadata, finalize_known!, run_exiftool,
|
||||
is_binary, handle_unknown_job,
|
||||
is_binary, handle_unknown_job, worker_loop,
|
||||
capacity, StageStats, IntakeStats, Metrics, METRICS, reset_metrics!,
|
||||
record_job!, enqueue_blocking!, stats_snapshot, STAGE_KEYS,
|
||||
detect_natural_language, run_linguist, detect_programming_language,
|
||||
read_text_sample, build_text_metadata, finalize_text!, handle_text_job,
|
||||
linguist_available,
|
||||
@@ -384,12 +386,13 @@ end
|
||||
mktempdir() do root
|
||||
cfg = tmp_config(root)
|
||||
text_queue = ChannelQueue(10)
|
||||
stats = StageStats()
|
||||
|
||||
# A binary file (embedded NUL) lands in binary/ and is NOT enqueued.
|
||||
bpath = joinpath(cfg.unknown_dir, "id-b-blob.dat")
|
||||
write(bpath, UInt8[0x00, 0xFF, 0x10])
|
||||
bjob = Job("id-b", "blob.dat", bpath, filesize(bpath), 0.0)
|
||||
handle_unknown_job(bjob, cfg, 1, text_queue)
|
||||
handle_unknown_job(bjob, cfg, 1, text_queue, stats)
|
||||
@test isfile(joinpath(cfg.binary_dir, "id-b-blob.dat"))
|
||||
@test !isfile(bpath)
|
||||
@test length(text_queue) == 0
|
||||
@@ -399,7 +402,7 @@ end
|
||||
tpath = joinpath(cfg.unknown_dir, "id-t-notes.log")
|
||||
write(tpath, "just some log text\n")
|
||||
tjob = Job("id-t", "notes.log", tpath, filesize(tpath), 0.0)
|
||||
handle_unknown_job(tjob, cfg, 1, text_queue)
|
||||
handle_unknown_job(tjob, cfg, 1, text_queue, stats)
|
||||
moved = joinpath(cfg.text_dir, "id-t-notes.log")
|
||||
@test isfile(moved)
|
||||
@test !isfile(tpath)
|
||||
@@ -874,4 +877,162 @@ end
|
||||
end
|
||||
end
|
||||
|
||||
# ---------------------------------------------------------------- stats
|
||||
#
|
||||
# The counters exist to answer "which stage is the bottleneck", and every
|
||||
# wrong answer they could give is a wrong *attribution*: time credited to the
|
||||
# stage that was waiting rather than the stage that was slow. So these tests
|
||||
# care less about exact numbers than about what is charged to whom.
|
||||
|
||||
@testset "per-stage stats" begin
|
||||
@testset "record_job! separates completions from quarantines" begin
|
||||
s = StageStats()
|
||||
record_job!(s, true, 100, 5_000_000)
|
||||
record_job!(s, true, 200, 5_000_000)
|
||||
record_job!(s, false, 50, 1_000_000)
|
||||
@test s.completed[] == 2
|
||||
@test s.failed[] == 1
|
||||
@test s.bytes[] == 350 # a quarantined job still moved bytes
|
||||
@test s.busy_ns[] == 11_000_000
|
||||
end
|
||||
|
||||
@testset "reset_metrics! zeroes counters and restarts the window" begin
|
||||
m = Metrics()
|
||||
Threads.atomic_add!(m.intake.files, 7)
|
||||
record_job!(m.stages.enrich, true, 10, 1000)
|
||||
m.since[] = 0.0
|
||||
reset_metrics!(m)
|
||||
@test m.intake.files[] == 0
|
||||
@test m.stages.enrich.completed[] == 0
|
||||
@test m.since[] > 0.0
|
||||
end
|
||||
|
||||
@testset "worker_loop records service time, failures, and drains in_flight" begin
|
||||
mktempdir() do root
|
||||
cfg = tmp_config(root)
|
||||
q = ChannelQueue(10)
|
||||
stats = StageStats()
|
||||
|
||||
# Two jobs that succeed, one that throws. The thrower is
|
||||
# quarantined by worker_loop, and must still be counted.
|
||||
for (i, name) in enumerate(("ok-1", "ok-2", "boom"))
|
||||
p = joinpath(cfg.spool_dir, "id-$i-$name")
|
||||
write(p, "x" ^ 10)
|
||||
@test enqueue!(q, Job("id-$i", name, p, filesize(p), 0.0))
|
||||
end
|
||||
close!(q)
|
||||
|
||||
worker_loop(1, cfg, q, (job, _, _) -> begin
|
||||
sleep(0.02)
|
||||
job.original_name == "boom" && error("handler blew up")
|
||||
nothing
|
||||
end, stats)
|
||||
|
||||
@test stats.completed[] == 2
|
||||
@test stats.failed[] == 1
|
||||
@test stats.bytes[] == 30
|
||||
# Each of the three handlers slept 20ms before its outcome, so
|
||||
# busy time covers the failure too — the work was done either way.
|
||||
@test stats.busy_ns[] > 3 * 15_000_000
|
||||
@test stats.blocked_ns[] == 0 # nothing downstream to block on
|
||||
@test stats.in_flight[] == 0 # the finally in worker_loop
|
||||
@test isfile(joinpath(cfg.failed_dir, "id-3-boom"))
|
||||
end
|
||||
end
|
||||
|
||||
@testset "enqueue_blocking! charges only the parked time to blocked_ns" begin
|
||||
s = StageStats()
|
||||
q = ChannelQueue(1)
|
||||
job = Job("id-1", "a.bin", "/tmp/a.bin", 1, 0.0)
|
||||
|
||||
# Room available → no wait, and nothing charged. This is the common
|
||||
# case, and it must not pay for the instrumentation.
|
||||
enqueue_blocking!(q, job, s; retry_seconds = 0.01)
|
||||
@test length(q) == 1
|
||||
@test s.blocked_ns[] == 0
|
||||
|
||||
# Queue full → the call parks until a consumer makes room, and that
|
||||
# time lands in blocked_ns, NOT in the caller's service time (which
|
||||
# worker_loop measures separately around the whole handler).
|
||||
drainer = Threads.@spawn begin
|
||||
sleep(0.1)
|
||||
dequeue!(q)
|
||||
end
|
||||
enqueue_blocking!(q, Job("id-2", "b.bin", "/tmp/b.bin", 1, 0.0), s;
|
||||
retry_seconds = 0.01)
|
||||
wait(drainer)
|
||||
@test length(q) == 1
|
||||
@test s.blocked_ns[] > 50_000_000 # parked for ~100ms
|
||||
end
|
||||
|
||||
@testset "a routing handler charges a full downstream queue as blocked" begin
|
||||
mktempdir() do root
|
||||
cfg = tmp_config(root)
|
||||
stats = StageStats()
|
||||
|
||||
# Stage 3 routing a text file with the stage-4 queue already
|
||||
# full: it must park rather than drop, and the wait must land in
|
||||
# blocked_ns instead of masquerading as slow triage work.
|
||||
text_queue = ChannelQueue(1)
|
||||
@test enqueue!(text_queue, Job("filler", "f", "/tmp/f", 1, 0.0))
|
||||
|
||||
p = joinpath(cfg.unknown_dir, "id-t-notes.log")
|
||||
write(p, "plain text\n")
|
||||
job = Job("id-t", "notes.log", p, filesize(p), 0.0)
|
||||
|
||||
drainer = Threads.@spawn begin
|
||||
sleep(0.1)
|
||||
dequeue!(text_queue)
|
||||
end
|
||||
handle_unknown_job(job, cfg, 1, text_queue, stats)
|
||||
wait(drainer)
|
||||
@test stats.blocked_ns[] > 50_000_000
|
||||
@test length(text_queue) == 1 # the file did get through
|
||||
@test isfile(joinpath(cfg.text_dir, "id-t-notes.log"))
|
||||
end
|
||||
end
|
||||
|
||||
@testset "stats_snapshot reports depth against capacity" begin
|
||||
mktempdir() do root
|
||||
cfg = tmp_config(root; worker_count = 3, known_worker_count = 4,
|
||||
unknown_worker_count = 5, text_worker_count = 6,
|
||||
queue_capacity = 11, known_queue_capacity = 12,
|
||||
unknown_queue_capacity = 13, text_queue_capacity = 14)
|
||||
m = Metrics()
|
||||
queues = (classify = ChannelQueue(11),
|
||||
enrich = ChannelQueue(12), triage = ChannelQueue(13),
|
||||
language = ChannelQueue(14))
|
||||
@test enqueue!(queues.enrich, Job("id", "n", "/tmp/n", 1, 0.0))
|
||||
record_job!(m.stages.enrich, true, 4096, 2_000_000_000)
|
||||
Threads.atomic_add!(m.intake.files, 9)
|
||||
|
||||
snap = stats_snapshot(cfg, queues, m)
|
||||
@test length(snap.stages) == 4
|
||||
@test [s.name for s in snap.stages] == ["classify", "enrich", "triage", "language"]
|
||||
@test [s.stage for s in snap.stages] == [1, 2, 3, 4]
|
||||
@test [s.workers for s in snap.stages] == [3, 4, 5, 6]
|
||||
@test [s.queue_capacity for s in snap.stages] == [11, 12, 13, 14]
|
||||
|
||||
enrich = snap.stages[2]
|
||||
@test enrich.queue_depth == 1
|
||||
@test enrich.completed == 1
|
||||
@test enrich.bytes == 4096
|
||||
@test enrich.busy_seconds ≈ 2.0
|
||||
@test snap.intake.files == 9
|
||||
@test snap.uptime_seconds >= 0
|
||||
|
||||
# It has to survive the trip through JSON — /stats is the only
|
||||
# consumer, and bin/bench.jl reads these exact field names.
|
||||
round_tripped = JSON3.read(JSON3.write(snap))
|
||||
@test round_tripped.stages[2].busy_seconds ≈ 2.0
|
||||
@test round_tripped.stages[2].blocked_seconds == 0.0
|
||||
@test round_tripped.stages[2].queue_depth == 1
|
||||
end
|
||||
end
|
||||
|
||||
@testset "capacity is part of the queue seam" begin
|
||||
@test capacity(ChannelQueue(7)) == 7
|
||||
end
|
||||
end
|
||||
|
||||
end
|
||||
|
||||
Reference in New Issue
Block a user