jeff/file-server
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Compare commits

base: jeff:d9f32d9aaff5b12d04eba1cd84ab3ffad645a000
Branches Tags
jeff:main
...
compare: jeff:main
Branches Tags
jeff:main

7 Commits
d9f32d9aaf ... main

Author SHA1 Message Date
Jeffrey Ward
341b61f806 Add stage-2 decomposition benchmark; fix run_with_timeout latency and enforceability 
bin/bench.jl reports stage 2 as a single throughput number, which can't
distinguish slow extraction from a slow spawn — and those have opposite fixes.
bin/bench_stage2.jl times each component in isolation, then times the real
handle_known_job end to end. It draws its corpus from real files (default
data/done) because random bytes make exiftool bail out early and understate the
stage by ~10x, and it prices both fork-free alternatives (batched, -stay_open)
so the cost of one-fork-per-file is a measurement rather than a guess.

The benchmark found stage 2 to be ~98% exiftool, and found two problems in
run_with_timeout, which stages 2 and 4 share:

1. The watchdog polled with sleep(0.1) and then joined the polling task, so
   every call paid the remainder of an in-flight sleep after the child had
   already exited: ~25 ms per file, and a measured 101 ms on a process that
   exits instantly. Replaced with a one-shot Timer cancelled when the child
   exits. Stage 2 goes from 164.6 ms to 138.3 ms per file (6 -> 8 files/s on one
   worker); the wrapper is now within noise of a bare Base.run.

2. Writing the missing tests showed the timeout was never enforceable, in the
   old implementation as much as the new. wait(proc) returns only once the
   captured stdout pipe closes, and grandchildren inherit that pipe, so
   signalling the child alone left the worker blocked until the whole process
   tree finished on its own — a `sh -c "trap '' TERM; sleep 30"` child ran the
   full 30 s against a 1 s timeout. The child now runs in its own process group
   and the timeout signals the group. The trade is that a hard crash of the
   server orphans an in-flight child rather than taking it down with it.

Three new tests cover the fast path, the timeout, and the SIGTERM-ignoring
escalation; the second was previously unexercised, which is why the bug stood.

Not addressed here, but measured and documented in the README: Perl interpreter
startup is 76.7 ms of the remaining 135.9 ms call, so a persistent exiftool
(-stay_open, 40.1 ms/file) would cut the stage by roughly another 70%. And
fsync_dir measures 1.75 us, too fast to be a real flush — commit_enriched!'s
durability may not hold on this filesystem, which is a correctness question
left open.

Claude-Session: https://claude.ai/code/session_01Xy9At7HNLHWNmfh1yw71Uy
 2026-08-03 11:28:36 -04:00
Jeffrey Ward
c692d14a2c Demote stage-1 per-file logging to @debug; add stage-1 decomposition benchmark 
bin/bench_stage1.jl takes handle_classify_job apart — filesize, read_features,
Lux.apply, classify, move_to, enqueue_blocking!, and the log lines — times each
in isolation, then times the real handler end to end under four loggers so the
parts can be checked against the whole.

It found that logging was stage 1's dominant cost: as @info the two per-file
lines cost ~71 us of the handler's ~118 us, roughly 6x the classifier (10.6 us)
and 6x the rename (11.6 us). Nearly all of it is ConsoleLogger formatting
(~64 us), not the FlushLogger's per-message flush (~8 us).

Demoting them to @debug takes stage 1 from 8.5k files/s to 35.3k files/s on one
worker (4.2x). The messages are still available with JULIA_DEBUG=FileServer,
which the benchmark also prices (133 us/file). What remains splits evenly
between the rename (11.7 us) and classify (10.7 us, itself 74% feature read),
so stage 1 is now filesystem-bound; its thread sweep peaks at ~4 workers.
 2026-08-03 00:10:32 -04:00
Jeffrey Ward
c5d488d9b4 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.
 2026-08-02 23:49:16 -04:00
Jeffrey Ward
0d8eba05b8 Stream multipart intake; add throughput/memory benchmark harness 
Adds a benchmark harness, which showed that intake buffered each upload
whole, then makes intake streaming so the service's flat-memory property
holds end to end rather than only for the queue and workers.

The measurement problem first: /upload returns 202 once bytes are spooled
and a reference is enqueued, so HTTP latency measures intake, not the
pipeline. bin/bench.jl instead uploads a corpus and polls the terminal
sinks until the count stops moving, reporting intake rate and end-to-end
rate separately, sampling server RSS (kernel VmHWM, reset per run) and
the intermediate stage depths so the bottleneck stage names itself.

That exposed the buffering: HTTP.jl read the body into req.body,
parse_multipart_form materialized each part, and read(p.data) copied
again before spool_file wrote it — a 256 MiB upload grew RSS ~700 MiB,
and 4 concurrent ones pushed a 950 MiB baseline past 2 GiB.

- src/multipart.jl: incremental multipart/form-data reader. Pulls fixed
  chunks off the socket and hands each part's bytes straight to a sink,
  so memory is bounded by FS_UPLOAD_CHUNK_BYTES (64 KiB), not file size.
  Interface is two calls in a loop (next_part! then write_part_body! /
  skip_part_body!) so the handler keeps ordinary control flow. Retains
  the last length(delimiter)-1 bytes so a delimiter split across chunks
  still parses; part headers are bounded by policy, not by chunking.
- src/server.jl: /upload is served by a stream handler. Oxygen's root
  handler wraps HTTP.streamhandler, which does request.body =
  read(stream) before dispatching — so no Oxygen route, not even a
  @stream route, can stream a body. root_stream_handler intercepts
  POST /upload at the stream level and delegates the rest to Oxygen
  unchanged; /upload is therefore absent from Oxygen's metrics and docs.
  A client hangup is classified as routine (info, not error) and answered
  best-effort; every exit path drains the body so keep-alive still works.
- src/spool.jl: spool_file(bytes) -> spool_stream(write_body!, ...),
  which removes a partial file on a failed or abandoned write, so restart
  recovery can never pick up a truncated upload as if it were complete.
- config.jl: FS_UPLOAD_CHUNK_BYTES, the intake memory dial.

Streaming changes the 503 contract: a buffered handler knew up front how
many files a request held, this one discovers them as they arrive. When
the queue fills mid-request it no longer abandons the connection — it
stops spooling (discarding remaining parts rather than writing files it
cannot queue), drains, and answers 503 with the accepted list. Files
already queued stay queued.

Measured after (fresh server, 64 KiB chunk): 256 MiB +21.8 MiB, 1 GiB
+20.8 MiB, 2 GiB +17.0 MiB at concurrency 1 — flat across a 32x size
range; 4 concurrent 256 MiB uploads +86.9 MiB, linear in concurrency.
A 2 GiB upload sustains 334 MiB/s. Small files did not regress (intake
107 -> 133 files/s, end-to-end 27.6 -> 32.9 files/s, p95 1930 -> 776 ms).
A --size sweep that slopes upward is now the regression signal.

- Tests (235 pass, 55 new): byte-exact round-trip of 10 files in one
  request, sizes straddling the chunk boundary (0/1/63/65535/65536/65537/
  131072/196615/1e6) plus a payload stuffed with near-boundary sequences;
  the same body parsed at chunk sizes 1..10000 to put the delimiter split
  at every offset; bounded allocation on a 16 MiB part; malformed and
  truncated bodies; spool_stream cleanup on a failed write.
- Known cosmetic caveat, documented: when a body is cut short, HTTP.jl's
  own closeread logs an EOFError after the handler returns, because
  Content-Length promised more than arrived. Not reachable from a
  handler; the old code logged the same thing without replying.
 2026-08-02 22:22:35 -04:00
Jeffrey Ward
e18ac45d70 Updated README 2026-07-25 09:59:04 -04:00
Jeffrey Ward
f4e3f5be0b Update README for stage-5 phase B (durable catalog + sweep runner) 2026-07-03 17:04:37 -04:00
Jeffrey Ward
584bad02a7 Add stage-5 phase B: durable single-owner format catalog 
Wraps the assign_file scoring core (cluster.jl) in the live catalog the
design's phase B calls for (DESIGN §5B/§9):

- src/catalog.jl: Catalog durable state (frozen-id clusters + sufficient
  stats + processed set + examples); sparse, sidecar-first durable
  save/load; incremental catalog_sweep! (deterministic CRP-predictive
  assignment of new binary/ files); offline compact! that seeds on first
  run and recompacts later; write_nominations! emitting one JSON per
  promotable cluster with a hex magic template.
- bin/cluster_sweep.jl: cron/periodic single-owner runner (--compact
  forces a recluster; first run auto-compacts to seed).
- config.jl: cluster_catalog_path + nominated_dir knobs (FS_CLUSTER_CATALOG,
  FS_NOMINATED_DIR), wired into config_from_env and ensure_dirs.
- Tests: durable round-trip, incremental sweep growth + idempotency,
  §10.1 nothing-from-noise end-to-end (zero promotions), a recurring
  format self-nominating, seed-then-live-assign (165 pass).
- DESIGN_clustering.md: mark phase B built.
 2026-07-03 17:03:33 -04:00
18 changed files with 4837 additions and 115 deletions
Expand all files Collapse all files

486
README.md
View File

@@ -20,9 +20,9 @@ enrichment mixes CPU with a subprocess):
POST /upload (multipart)
│
▼
┌─────────────────┐ spool bytes to disk
┌─────────────────┐ stream bytes to disk (never buffered)
│ HTTP handler │────────────────────────► data/spool/<uuid>-<name>
│ (Oxygen.jl) │
│ (streaming) │
└────────┬─────────┘ enqueue reference (non-blocking)
│ │
▼ ▼
@@ -70,7 +70,12 @@ enrichment) for every file it sorts as text.
Key properties:
- **Fast intake:** the queue only ever carries small references; file bytes live
on disk, so memory stays flat regardless of file size.
on disk, so memory stays flat regardless of file size. This holds end to end:
intake **streams** each upload from the socket to the spool file a chunk at a
time (`FS_UPLOAD_CHUNK_BYTES`, default 64 KiB) rather than buffering the body,
and every worker reads only a bounded prefix. Measured: uploads of 256 MiB,
1 GiB and 2 GiB each grow resident memory by ~20 MiB — a flat line in file
size. See "Streaming intake" and "Benchmarking" below.
- **Backpressure:** each queue is bounded (default 1000). When the *intake* queue
is full, uploads get `503 Service Unavailable`. When the *known* queue is full,
the stage-1 worker blocks and retries (a classified file is never dropped).
@@ -90,6 +95,46 @@ Key properties:
- **Safe filenames:** client-supplied names are sanitized and prefixed with a
server-minted UUID before touching the filesystem (no path traversal).
### Streaming intake
The upload endpoint never holds a file in memory. Bytes go socket → spool file in
`FS_UPLOAD_CHUNK_BYTES` chunks, so resident memory per in-flight upload is set by
the chunk size, not the file size — a 2 GiB upload costs about what a 2 KiB one
does. Two pieces make that work, and both are deliberate:
- **`src/multipart.jl` — an incremental multipart parser.** HTTP.jl's
`parse_multipart_form` takes the *complete* body as a byte vector, so using it
means every file in the request is in memory at once (and copied again per
part). The reader here pulls fixed-size chunks and hands each part's bytes
straight to its spool file. Its interface is two calls in a loop —
`next_part!` then `write_part_body!` (or `skip_part_body!`) — so the handler
keeps ordinary control flow instead of inverting into callbacks. The subtle
part is that a boundary delimiter can straddle two chunks, so the buffer always
retains the last `length(delimiter)-1` bytes; the test suite parses the same
body at chunk sizes from 1 byte upward to put that split at every offset.
- **`/upload` bypasses Oxygen's router.** Oxygen's root handler wraps
`HTTP.streamhandler`, which does `request.body = read(stream)` *before*
dispatching — even for an Oxygen `@stream` route, so no route can stream an
upload. `run` therefore passes its own `handler` to `serve`
(`root_stream_handler`), which intercepts `POST /upload` at the stream level and
delegates everything else to Oxygen unchanged. The trade-off: `/upload` is
absent from Oxygen's built-in metrics and docs.
Streaming also changes what the endpoint can promise. A buffered handler knows up
front how many files a request holds; this one discovers them as they arrive. So
when the intake queue fills mid-request it does not abandon the connection: it
stops spooling (discarding the remaining parts rather than writing files it can't
queue), drains the body, and answers `503` with the `accepted` list of whatever
got in first. Files already queued stay queued, and the client can retry the rest.
A client that hangs up mid-upload is treated as routine: the partial spool file is
removed (so restart recovery can never pick up a truncated upload as if it were
complete) and the event is logged `upload aborted by client`. One cosmetic caveat,
like the SIGTERM one below: when a request body is cut short, HTTP.jl's own
`closeread` logs an `EOFError` after the handler returns, because the connection
promised more bytes via `Content-Length` than arrived. It's harmless noise from
inside HTTP.jl — the partial file is already cleaned up and the connection closed.
### Metadata enrichment (stage 2)
Files the classifier labels **known** are handed to a second pool that extracts
@@ -223,9 +268,30 @@ clusters. A cluster's spiked positions become a libmagic-style signature;
clusters with enough members and enough fixed positions self-**nominate** for
promotion (a human does the one irreversible step, redefining "known").
**Status:** the offline science (phase A) is implemented and calibrated; the live
catalog process (phase B) is designed and its scoring core (`assign_file`) is in
place, but its batch-runner plumbing is not yet built.
**Status:** both phases are implemented and calibrated. Phase A (offline Gibbs)
is the science; phase B (`src/catalog.jl`) is the live catalog: a durable
single-owner state that sweeps `binary/`, folds each new file into a cluster with
the deterministic CRP-predictive rule, and writes promotion nominations.
The catalog process is run periodically (cron), single-threaded — it is the
**only** writer of the catalog, so it needs no locking:
```bash
julia --project=. bin/cluster_sweep.jl # incremental live sweep of new binary/ files
julia --project=. bin/cluster_sweep.jl --compact # offline Gibbs re-cluster (seed / recompact)
```
The catalog is a single durable file (`FS_CLUSTER_CATALOG`, default
`data/catalog.json`) committed with the same sidecar-first
temp→fsync→rename→fsync-dir discipline as the stage-2 sidecars, so a crash can
neither corrupt it nor lose a write. On the **first** run (empty catalog) the
sweep auto-promotes to a `--compact` pass to seed clusters; later runs assign
incrementally, touching only files they have not seen. A cluster that clears the
member/magic thresholds writes a nomination — a hex magic template, member count,
and example filenames — into `FS_NOMINATED_DIR` (default `data/nominated/`) for a
human to glance at and promote. Under the calibrated `bg_mass > α`, the live
sweep never mints single-file clusters; genuinely new formats surface from the
periodic `--compact` re-clustering of the background residue, not the live path.
Calibration is its own offline script (like training — never in the request
path), scored against magic-collapsed ground truth (so `docx`≡`zip` and the whole
@@ -299,9 +365,12 @@ tell you "PDF", just "this looks like something I was trained on, or not".
- **Artifact:** trained weights live in `model/classifier.jld2` (committed), so
the server just loads them at startup. Missing/unreadable ⇒ the server fails
fast rather than run without classification.
- **Effect today:** *annotate-only*. The class is logged
(`classification=known|unknown`) but every file still moves to `done/`; the
classifier can't misroute real files while it's unproven.
- **Effect today:** *active routing*. The class is logged
(`classification=known|unknown`) and drives the pipeline split: `:known` files
go to `known/` for metadata enrichment (stage 2), `:unknown` files go to
`unknown/` for content triage (stage 3). The class chooses the downstream
stage; what's still unproven is the model's *accuracy*, not whether the routing
path runs.
The architecture and byte→feature mapping are defined once in `src/model.jl` and
shared by the trainer and the server, so they can't drift apart.
@@ -350,6 +419,7 @@ init, so the artifact is exactly regenerable from the same inputs.
| `FS_TEXT_DONE_DIR` | `data/text_done` | Enriched text files (+ `.meta.json`) |
| `FS_FAILED_DIR` | `data/failed` | Files whose processing threw |
| `FS_MODEL_PATH` | `model/classifier.jld2` | Classifier artifact loaded at startup |
| `FS_UPLOAD_CHUNK_BYTES` | `65536` | Socket read size at intake; bounds intake memory per in-flight upload |
| `FS_EXIFTOOL_TIMEOUT` | `30` | Seconds before a stuck exiftool is killed |
| `FS_LINGUIST_TIMEOUT` | `30` | Seconds before a stuck github-linguist is killed |
| `FS_CLUSTER_DIR` | `data/binary` | Stage-5 input: the unknown/binary pile to sweep |
@@ -359,6 +429,8 @@ init, so the artifact is exactly regenerable from the same inputs.
| `FS_CLUSTER_BG_MASS` | `5.0` | Mass of the uniform background component |
| `FS_PROMOTE_MIN_MEMBERS` | `20` | Cluster size threshold for promotion nomination |
| `FS_PROMOTE_MIN_MAGIC` | `3` | Required fixed signature positions to nominate |
| `FS_CLUSTER_CATALOG` | `data/catalog.json` | Durable stage-5 catalog file (single-owner) |
| `FS_NOMINATED_DIR` | `data/nominated` | One JSON per self-nominated cluster (human promote gate) |
> To get real parallelism, start Julia with enough threads (`-t N`) to cover all
> pools. If `FS_WORKERS + FS_KNOWN_WORKERS + FS_UNKNOWN_WORKERS + FS_TEXT_WORKERS`
@@ -375,6 +447,9 @@ curl http://127.0.0.1:8080/health
# upload one or more files (multipart/form-data)
curl -F "a=@report.pdf" -F "b=@data.csv" http://127.0.0.1:8080/upload
# 202 {"accepted":[{"id":"<uuid>","name":"report.pdf"}, ...]}
# per-stage counters
curl http://127.0.0.1:8080/stats
```
Each file in a request becomes its own job. Responses:
@@ -384,6 +459,386 @@ Each file in a request becomes its own job. Responses:
- `503 Service Unavailable` — queue full, retry later
- `500 Internal Server Error` — failed to write a file to disk
### `GET /stats` — per-stage counters
The pipeline counts its own work (`src/stats.jl`), because nothing outside it
can: `known/`, `unknown/` and `text/` are *transient*, so a file can cross one
between two directory polls and an external sampler will miss exactly the stages
you most want to measure.
```jsonc
{
"now": 1785725300.5, "since": 1785725291.9, "uptime_seconds": 8.5,
"intake": { "requests": 400, "files": 400, "bytes": 6553600, "rejected": 0 },
"stages": [
{ "stage": 4, "name": "language", "workers": 16,
"queue_depth": 184, "queue_capacity": 1000,
"completed": 200, "failed": 0, "bytes": 3276800,
"busy_seconds": 170.5, // summed handler time across the pool
"blocked_seconds": 0.0, // of that, time parked on a full downstream queue
"in_flight": 3 }
]
}
```
Counters are monotonic since startup, Prometheus-style — rates are the reader's
job, so a scrape is stateless and two readers can't disturb each other. Take two
scrapes Δt apart and subtract:
```
throughput = Δcompleted / Δt
utilization = (Δbusy_seconds − Δblocked_seconds) / (Δt × workers)
```
**Utilization is the number that names the bottleneck.** In a pipeline every
stage completes the same files, so at steady state they all report near-identical
files/s no matter which one is the constraint; what separates them is how hard
each pool worked to keep up. The bottleneck sits near 1.0 with its queue backing
up while its neighbours idle.
`blocked_seconds` is what keeps that true. Stages 1 and 3 apply *blocking*
backpressure — a full downstream queue means the handler parks and retries rather
than dropping the file — and that wait happens inside the handler. 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. Subtracted out, utilization means
"doing its own work", and a high blocked share becomes its own signal: a stage
blocked 90% of the time is naming its successor.
The counters are a handful of atomic adds per file, 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.
## Benchmarking (throughput + memory)
There are five harnesses. Only the first needs a running server:
| script | measures | server? |
|---|---|---|
| `bin/bench.jl` (below) | intake, end-to-end and per-stage throughput; server RSS | **yes** |
| [`bin/bench_stage1.jl`](#stage-1-component-benchmark-binbench_stage1jl) | stage 1 taken apart: classify vs. rename vs. enqueue vs. logging | no |
| [`bin/bench_stage2.jl`](#stage-2-component-benchmark-binbench_stage2jl) | stage 2 taken apart: exiftool spawn vs. extraction vs. commit | no |
| [`bin/bench_model.jl`](#model-microbenchmark-binbench_modeljl) | the classifier alone: inference, feature reads, thread scaling | no |
| [`bin/cluster_calibrate.jl`](#unknown-format-discovery-stage-5-offline) | stage-5 clustering quality vs. an NCD baseline | no |
Running all of them from a clean checkout:
```bash
julia --project=. -e 'using Pkg; Pkg.instantiate()' # once
# 1. the model, on its own — no server involved
julia --project=. -t auto bin/bench_model.jl
# 1b. stage 1 taken apart — also no server
julia --project=. -t auto bin/bench_stage1.jl
# 1c. stage 2 taken apart — needs a directory of real files, not generated ones
julia --project=. -t auto bin/bench_stage2.jl
# 2. the pipeline. Start the server in one terminal…
julia --project=. -t auto bin/server.jl
# …and drive it from another. Restart the server between memory runs: Julia's
# GC returns memory to the OS lazily, so a second run starts inflated.
julia --project=. -t auto bin/bench.jl --files 2000 --size 8k --concurrency 32
julia --project=. -t auto bin/bench.jl --files 2 --size 1g --concurrency 1 # memory
julia --project=. -t auto bin/bench.jl --corpus ../training_set --concurrency 16
# 3. stage-5 clustering quality (offline, needs a labelled corpus)
julia --project=. bin/cluster_calibrate.jl ../training_set
```
The test suite is `julia --project=. -t auto -e 'using Pkg; Pkg.test()'`.
`bin/bench.jl` must run on the same machine as the server (it reads the sink dirs
and `/proc`); otherwise it only speaks HTTP — `/upload`, `/health`, and `/stats`
for the per-stage numbers.
Three properties of this design dictate how it measures:
- **HTTP latency is not throughput.** `/upload` returns `202` once the bytes are
spooled and a reference is enqueued — all four stages run *after* the response,
so `ab`/`hey`/`wrk` would only ever measure intake. The bench instead uploads a
corpus and polls the terminal sinks (`done/`, `text_done/`, `binary/`,
`failed/`) until the count stops moving, and reports both numbers separately:
intake rate *and* end-to-end completion rate. It also samples the intermediate
stage dirs, so the peak depth of `spool/`/`known/`/`unknown/`/`text/` shows
where work piles up.
- **End-to-end throughput doesn't name the slow stage.** 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. The bench scrapes
[`/stats`](#get-stats--per-stage-counters) before and after the run and
subtracts, giving each stage its own throughput, mean service time and
utilization:
```
PER-STAGE (server counters, delta over the end-to-end window)
stage files/s MiB/s svc ms util blocked peak queue failed
1 classify 32.52 0.51 38.7 0.08 0.0% 209/1000 0
2 enrich 0.24 0.0 541.0 0.01 0.0% 0/1000 0
3 triage 32.27 0.5 33.9 0.07 0.0% 83/1000 0
4 language 16.26 0.25 852.6 0.87 0.0% 184/1000 0
bottleneck stage 4 (language) at 87.0% utilization of 16 worker(s)
```
(400 mixed files, 16 KiB each, concurrency 16. Stage 4 is the constraint —
`github-linguist` is a process spawn per file at ~850 ms — and the 200 text
files queue up behind it while stages 1 and 3 idle at under 10%.) Read *down*
the util column, not the files/s column: each stage sees a different subset of
the corpus, so a low rate can just mean little work was routed there.
- **Memory should be flat in file size, and the sweep is what proves it.** Both
halves of the pipeline are bounded: the workers read bounded prefixes (16+16
bytes to classify, 8 KB to sniff, 64 KB to language-detect), and intake streams
each upload to disk a chunk at a time. So peak RSS should track *concurrency*,
not size. Measured on this machine (16 threads, 64 KiB chunk):
| upload size | concurrency | RSS growth |
|---|---|---|
| 256 MiB × 4 | 1 | 14.0 / 20.4 MiB (two runs) |
| 1 GiB × 2 | 1 | 22.3 MiB |
| 2 GiB × 1 | 1 | 31.3 MiB |
| 256 MiB × 4 | 4 | none measurable (peak stayed under the baseline) |
**Read the shape, not the digits.** Growth is flat across an 8× range of file
sizes — 14–31 MiB whether the upload is 256 MiB or 2 GiB — which is the claim
that matters: nothing scales with file size, so nothing is buffering. The
absolute figures are *not* precise to the megabyte. A freshly started server
settles anywhere in an ~860–985 MiB band, so run-to-run variance in the
baseline is comparable to the growth being measured; the residual is GC churn
from the chunk reads, not retained buffers.
Two consequences worth knowing before quoting these numbers:
- **Let the server settle ~30s after startup** before a memory run, or the
baseline is sampled mid-fall and the run reports less growth than it caused
(or none at all, as the concurrency-4 row above did).
- **Linear-in-concurrency is not currently demonstrated.** An earlier
measurement put 4 concurrent 256 MiB uploads at 86.9 MiB (21.7 per in-flight
upload), but that run predates a fix to how the baseline was sampled — it was
read *before* the peak counter was reset, against a different origin — and the
re-measurement above cannot reproduce it: the growth sits under the noise
floor. Expect concurrency to cost memory; don't trust a specific coefficient
without a quieter machine or many more runs.
Before intake
was streamed, the same 256 MiB upload grew RSS by ~700 MiB and 4 concurrent ones
pushed a 950 MiB baseline past 2 GiB, so **a `--size` sweep that slopes upward is
the regression signal** — it means something has started buffering bodies again.
Flags: `--files`, `--size` (`8k`/`64m`/`1g`), `--concurrency`, `--kind`
(`binary`/`text`/`mixed` — chooses which stages get loaded), `--corpus DIR` (real
files, the only way to exercise stage 2's exiftool path), `--pid`, `--no-mem`,
`--no-stats`, `--sample-ms`, `--timeout`, `--json PATH`. Full list in the script
header. The `--json` output carries the per-stage numbers too, so a sweep can be
compared run to run.
Two caveats the script reports rather than hides: it counts sink *deltas*, so it
warns if the pipeline isn't idle at the start (in-flight leftovers would be
counted as its own throughput); and because Julia's GC returns memory to the OS
lazily, a second run in the same process starts from an inflated baseline — it
resets the kernel's peak-RSS counter (`/proc/<pid>/clear_refs`) per run and flags
a drifted baseline, but for a clean growth figure restart the server between
memory runs.
### Stage-1 component benchmark (`bin/bench_stage1.jl`)
`bin/bench.jl` reports stage 1 as one number and `bin/bench_model.jl` takes the
*classifier* apart — but stage 1 is more than the model. Per file it also
renames the file into its stage directory, pushes a reference onto the
downstream queue, and logs. `bin/bench_stage1.jl` times each of those in
isolation, then times the real `handle_classify_job` end to end so the parts can
be checked against the whole:
```bash
julia --project=. -t auto bin/bench_stage1.jl
```
Measured on this machine (Ryzen 7 2700X, 8 cores/16 threads, Julia 1.12; 2000 ×
64 KiB files, minimum of 5 trials):
| component | per file | share of the handler |
|---|---|---|
| `classify()` | 10.7 µs | 38% |
| ↳ `read_features` | 7.9 µs | 28% |
| ↳ `Lux.apply` | 2.3 µs | 8% |
| `move_to` (rename) | 11.7 µs | 41% |
| `enqueue_blocking!` | 0.12 µs | 0.4% |
| per-file logging (disabled `@debug`) | 0.29 µs | 1% |
| **`handle_classify_job`** | **28.3 µs** | 100% |
**This benchmark is why stage 1's per-file log lines are `@debug` rather than
`@info`.** As `@info` they cost ~71 µs of the handler's ~118 µs — about 6× the
classifier and 6× the rename — and nearly all of it was `ConsoleLogger`
*formatting* (~64 µs), not the `FlushLogger`'s per-message flush (~8 µs on top).
Demoting them took stage 1 from 8.5k files/s to 35.3k files/s on a single worker,
a 4.2× speedup for no algorithmic change. The script still prices a formatted
line, so the cost of turning them back on is visible: running the handler under
`JULIA_DEBUG=FileServer` measures 133 µs per file, a 4.7× slowdown. That is the
trade — per-file tracing is available when you want it, and off by default,
with `GET /stats` giving per-file observability that is counted rather than
formatted.
What's left is evenly split between the rename and the classifier, and neither
has an easy 2×. Two things worth knowing:
- **The rename, not the model, is the single largest component** (11.7 µs), and
it's a plain `mv` within one filesystem. Inside `classify`, the same pattern
holds: 7.9 µs of the 10.7 µs is `read_features` — the `open`, the two reads
and the `seek` — against 2.3 µs of actual inference. Stage 1 is now a
filesystem-bound stage with a neural network attached, not the reverse.
- **Stage 1 now peaks at ~4 workers.** With the logger removed from the hot path
the sweep reads 35.0k/s at 1 worker, 66.6k/s at 2, **73.3k/s at 4**, then
*falls back* to 60.1k/s at 8 and 53.3k/s at 16 — every worker renaming into the
same two directories contends on the same directory inode. That ceiling
coincides with the one `bin/bench_model.jl` finds for inference, so ~4 is the
number from both directions: raising `FS_WORKERS` past it costs throughput.
Reported times are the **minimum** over trials. Flags: `--files`, `--reps`,
`--trials`, `--size`, `--dir`, `--model`, `--threads`, `--no-threads`,
`--json PATH`.
### Stage-2 component benchmark (`bin/bench_stage2.jl`)
Stage 2 is the one stage whose cost is dominated by something outside Julia
entirely: it forks `exiftool`, a Perl program, once per file. `bin/bench.jl`
reports the stage as a single throughput number, which can't distinguish "the
extraction is slow" from "the *spawn* is slow" — and those have opposite fixes.
`bin/bench_stage2.jl` times each piece in isolation, then times the real
`handle_known_job` end to end:
```bash
julia --project=. -t auto bin/bench_stage2.jl
```
Two things make this benchmark different from the stage-1 one:
- **The corpus must be real files.** exiftool's cost depends on what it finds; a
file of random bytes bails out early and understates the stage by ~10×. The
default corpus is `data/done` — files that already went through stage 2 on this
machine. `--corpus PATH` points it elsewhere.
- **It prices the alternatives to one-fork-per-file**, because if the fork
dominates then the only fixes are to stop paying it per file. `exiftool
(batched Nx)` runs the whole corpus through one process; `exiftool
(-stay_open)` keeps one process alive and feeds it one file at a time over a
pipe — the shape a streaming pipeline could actually adopt. Both are measured,
not assumed.
Measured on this machine (Ryzen 7 2700X, 8 cores/16 threads, Julia 1.12,
exiftool 12.40; 150 real files / 102 MiB, minimum of 2 trials):
| component | per file | share of the handler |
|---|---|---|
| `run_exiftool()` | 135.9 ms | 98% |
| ↳ bare fork + Perl boot (`exiftool -ver`) | 76.7 ms | 55% |
| ↳ `JSON3.read` + tag map | 10 µs | 0.0% |
| `normalize_metadata` | 1.7 µs | 0.0% |
| `commit_enriched!` (sidecar + fsyncs + rename) | 2.0 ms | 1.5% |
| per-file logging (`@info`, flush→file) | 47 µs | 0.0% |
| **`handle_known_job`** | **138.3 ms** | 100% |
| *alt:* `exiftool -stay_open` | 40.1 ms | 29% |
| *alt:* `exiftool` batched 150× | 37.3 ms | 27% |
**Stage 2 is exiftool and nothing else.** Everything the Julia code does —
parsing, normalizing, the durable sidecar-first commit, the log line — sums to
about 1.5% of the stage. There is no point optimizing any of it.
**More than half the stage is interpreter startup, not metadata extraction.**
The bare `exiftool -ver` (fork, Perl boot, module loads, read no file) costs
76.7 ms against a 135.9 ms full call. Both fork-free alternatives agree on what's
left: ~37–40 ms of actual work per file. So a persistent exiftool would cut the
stage by ~70%, and `-stay_open` gets there without giving up the one-file-in,
one-result-out shape the pipeline needs. That remains the single biggest
available win in this stage; it is measured here but not yet implemented.
**This benchmark is also why `run_with_timeout` no longer polls.** The original
watchdog polled with `sleep(0.1)` and then joined the polling task, so every call
paid the remainder of an in-flight sleep *after* the child had already exited —
~25 ms per file here, and a measured 101 ms on a process that exits instantly.
Replacing it with a one-shot `Timer` took the stage from 164.6 ms to 138.3 ms per
file (6→8 files/s on one worker) and cost nothing in behavior. Stage 4 shares the
wrapper and got the same fix for free.
Writing the missing tests for that wrapper turned up a second, worse problem:
**the timeout was never enforceable.** `wait(proc)` returns only once the
captured stdout pipe closes, and any grandchild inherits that pipe — so
signalling the child alone left the worker blocked until the whole process tree
finished on its own (a `sh -c "trap '' TERM; sleep 30"` child ran the full 30 s
against a 1 s timeout, under both the old and new watchdog). The child now runs
in its own process group and the timeout signals the group. The trade is that a
hard crash of the server orphans an in-flight child rather than taking it down;
these children are short-lived and timeout-bounded, which is the cheaper side of
it.
**Stage 2 scales to ~8 workers, then flattens**: 8 files/s at 1 worker, 14 at 2,
28 at 4, **49 at 8**, and 49 at 16 — the machine runs out of cores to run Perl
on, which is exactly what you'd expect of a stage that is ~100% subprocess. Note
that the sweep pulls from a shared counter rather than splitting the corpus into
contiguous slices: per-file exiftool time spans two orders of magnitude on a real
corpus (one 2.1 s archive among 48 files), and a static split reports a scaling
ceiling that is really just load imbalance.
One caveat the numbers raise but don't answer: **`fsync_dir` measures 1.75 µs**,
which is far too fast to be a real disk flush. The durability that
`commit_enriched!` is written for may not survive power loss on this filesystem,
even though the code is correct. That's a correctness question, not a speed one,
and it is not yet resolved.
Reported times are the **minimum** over trials. Flags: `--files`, `--reps`,
`--trials`, `--corpus`, `--dir`, `--timeout`, `--threads`, `--no-threads`,
`--no-stay-open`, `--json PATH`.
### Model microbenchmark (`bin/bench_model.jl`)
`bin/bench.jl` reports stage 1 as a single number — the wall time of
`handle_classify_job`, which is a feature read, an inference, a rename, a
(disabled) debug line, and whatever contention the other three pools create.
That's the right number for capacity planning and the wrong one for "is the
model slow?".
`bin/bench_model.jl` answers that separately, with no server, queue, or HTTP
involved:
```bash
julia --project=. -t auto bin/bench_model.jl
```
Measured on this machine (Ryzen 7 2700X, 8 cores/16 threads, Julia 1.12):
| what | per file | notes |
|---|---|---|
| `Lux.apply`, batch 1 | **2.3 µs** | 768 B allocated per call |
| `read_features` | **4.2–6.0 µs** | flat across a 262,144× size range (1 KiB → 256 MiB) |
| `classify()` | **8.4 µs** | 73% feature read, 27% inference |
So the model is **not** the pipeline's problem, by three orders of magnitude: the
same run measured stage 1 at 38.7 ms per file, ~4,500× the 8.4 µs `classify()`
costs. Whatever stage 1 spends its time on, it isn't the network. (That 38.7 ms
predates the `@debug` demotion above and is a whole-pipeline figure — it includes
time the stage-1 worker spends *blocked* on a full downstream queue, which is why
it is three orders of magnitude above the 28.3 µs the handler costs in
isolation. For the uncontended split, see
[the stage-1 decomposition](#stage-1-component-benchmark-binbench_stage1jl).)
Two findings worth acting on if stage 1 ever *does* become the constraint:
- **Batching would buy ~13×.** A 32×1 matmul wastes most of a BLAS call:
batch 64 costs 280 ns/file and batch 512 costs 179 ns/file, against 2.34 µs
one at a time. The pipeline classifies strictly one file per job today, so it
pays the worst row in that table.
- **Inference does not scale past ~4 threads.** Concurrent `Lux.apply` on the
shared read-only `Classifier` peaks around 1.2M files/s at 4 tasks and then
*falls back* to single-thread throughput at 16. The script runs a pure-compute
control kernel through the same sweep to place the blame: the control reaches
14.3× at 16 tasks (90% efficiency) on the same box, so the machine
parallelizes and `Lux.apply` doesn't. GC is only ~1% of it, so allocation
pressure isn't the explanation either — the cause is inside Lux/BLAS and is
not diagnosed here. The practical consequence: raising `FS_WORKERS` past ~4
adds no classification throughput.
Reported times are the **minimum** over trials — for a microbenchmark the floor
is the signal and everything above it is scheduler and GC noise — and every timed
loop stores its result in a sink so a pure call can't be hoisted out of the loop.
Flags: `--model`, `--reps`, `--trials`, `--batches`, `--sizes`, `--no-threads`,
`--json PATH`.
## Layout
```
@@ -392,19 +847,26 @@ src/
config.jl Config struct + env parsing
job.jl Job (the queue reference)
queue.jl JobQueue seam + in-process ChannelQueue
spool.jl filename sanitizing, spool/move, startup recovery
stats.jl per-stage counters behind GET /stats (throughput, utilization)
multipart.jl streaming multipart/form-data reader (intake never buffers a file)
spool.jl filename sanitizing, streaming spool/move, startup recovery
model.jl NN architecture + byte→feature mapping (shared with trainer)
classify.jl load artifact + classify a file at inference time
metadata.jl exiftool extraction + normalized sidecar (stage 2)
content.jl binary-vs-text sniff for unknown files (stage 3)
language.jl natural + programming language enrichment for text (stage 4)
cluster.jl header-byte clustering for unknown-format discovery (stage 5, offline)
cluster.jl header-byte clustering model + Gibbs + scoring core (stage 5, science)
catalog.jl durable single-owner format catalog + sweep + nominations (stage 5, phase B)
worker.jl parametrized worker loop + classify/enrich/triage/language handlers
server.jl HTTP routes/handlers
server.jl HTTP routes + the streaming /upload handler
bin/
server.jl entry point
bench.jl throughput + memory harness against a running server
bench_model.jl classifier microbenchmark (inference, feature reads, scaling)
bench_stage1.jl stage-1 decomposition (classify vs. rename vs. enqueue vs. logging)
train.jl offline training script → model/classifier.jld2
cluster_calibrate.jl offline stage-5 hyperparameter calibration + NCD baseline
cluster_sweep.jl stage-5 phase-B runner: sweep binary/, update catalog, write nominations
model/
classifier.jld2 committed trained weights (loaded at startup)
DESIGN_clustering.md stage-5 design rationale + calibration results

783
bin/bench.jl Executable file
View File

@@ -0,0 +1,783 @@
#!/usr/bin/env julia
#
# bench.jl — measure end-to-end throughput and server memory for a running FileServer.
#
# Two things make this pipeline awkward to benchmark with off-the-shelf tools
# (ab/hey/wrk), and both shape what this script does:
#
# 1. HTTP latency is not throughput. /upload returns 202 as soon as the bytes
# are spooled and a reference is enqueued — all four stages run afterwards.
# So real throughput is the *arrival rate at the terminal sinks*
# (done/, text_done/, binary/, failed/), not the response rate. We upload a
# corpus, then poll the sinks until the file count stops moving.
#
# 2. End-to-end throughput doesn't name the slow stage. 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. Directory polling can't
# recover them either — known/, unknown/ and text/ are transient, and a file
# can cross one between two samples. So the server keeps per-stage counters
# (src/stats.jl) and we scrape GET /stats before and after: the deltas give
# each stage's throughput, mean service time, and worker utilization, and
# utilization is what actually names the bottleneck (see `stage_report`).
#
# 3. Memory should be flat in file size, and that claim needs checking on two
# axes. The workers read bounded prefixes (16+16 bytes to classify, 8 KB to
# sniff, 64 KB to language-detect), and intake streams each upload from the
# socket to the spool file a chunk at a time (FS_UPLOAD_CHUNK_BYTES, see
# src/multipart.jl). So peak RSS should track *concurrency*, not file size:
# sweeping --size at fixed --concurrency should be a flat line, and that is
# the regression this measures. We sample the server's RSS throughout and
# report the high-water mark.
#
# (Before intake was streamed it buffered each upload whole, several times
# over, and a 256 MiB upload grew RSS by ~700 MiB. If a --size sweep ever
# slopes upward again, something has started buffering.)
#
# The harness talks to the server only over HTTP (/upload, /health, /stats) and
# reads the on-disk sink layout; it must run on the same machine (sink dirs and
# /proc). If /stats is missing — an older build — everything else still works and
# the per-stage section is skipped.
#
# Usage:
# julia --project=. -t auto bin/bench.jl [options]
#
# --url URL server base URL (default: $FS_URL or http://127.0.0.1:8080)
# --files N number of files to upload (default: 200)
# --size S size of each generated file, e.g. 4k, 512k, 8m, 1g (default: 64k)
# --concurrency J uploads in flight at once (default: 8)
# --kind K binary | text | mixed — what to generate (default: binary)
# --corpus DIR upload an existing directory instead of generating
# (the only way to exercise stage 2: point it at real known files)
# --keep-corpus don't delete the generated corpus on exit
# --pid PID server pid for memory sampling (default: autodetect)
# --no-mem skip memory sampling entirely
# --no-stats skip the per-stage /stats scrape and its table
# --sample-ms MS sink/RSS sampling interval (default: 200)
# --timeout SEC give up after this long with no drain progress (default: 120)
# --json PATH also write the results as JSON
# --force skip the corpus-size safety check
#
# Examples:
# # throughput: many small files, high concurrency
# julia --project=. -t auto bin/bench.jl --files 2000 --size 8k --concurrency 32
#
# # memory: flat in file size? sweep --size with concurrency pinned
# julia --project=. -t auto bin/bench.jl --files 4 --size 256m --concurrency 1
# julia --project=. -t auto bin/bench.jl --files 2 --size 1g --concurrency 1
# julia --project=. -t auto bin/bench.jl --files 8 --size 1g --concurrency 8
#
# # stage 2 (exiftool) with real known files
# julia --project=. -t auto bin/bench.jl --corpus ../training_set --concurrency 16
using HTTP
using JSON3
using Random
# ---------------------------------------------------------------- option parsing
const DEFAULTS = Dict{String,Any}(
"url" => get(ENV, "FS_URL", "http://127.0.0.1:8080"),
"files" => 200,
"size" => 64 * 1024,
"concurrency" => 8,
"kind" => "binary",
"corpus" => nothing,
"keep-corpus" => false,
"pid" => nothing,
"no-mem" => false,
"no-stats" => false,
"sample-ms" => 200,
"timeout" => 120,
"json" => nothing,
"force" => false,
)
const FLAGS = ("keep-corpus", "no-mem", "no-stats", "force")
# Approximate RSS of a freshly started server (Lux + the loaded classifier + the
# language detector, measured on Julia 1.12 / -t auto). Only used to notice that
# a baseline is inflated by a previous run's un-returned GC memory, so a rough
# figure is enough.
const FRESH_RSS_HINT = 950 * 1024^2
"Parse `4k`/`8M`/`1g`/`4096` into a byte count."
function parse_size(s::AbstractString)::Int
m = match(r"^(\d+(?:\.\d+)?)\s*([kKmMgG]?)[bB]?$", strip(s))
m === nothing && error("bad --size: $s (expected e.g. 512, 64k, 8m, 1g)")
mult = Dict('k' => 1024, 'm' => 1024^2, 'g' => 1024^3)
scale = isempty(m[2]) ? 1 : mult[lowercase(m[2])[1]]
return round(Int, parse(Float64, m[1]) * scale)
end
function parse_args(argv)::Dict{String,Any}
opts = copy(DEFAULTS)
i = 1
while i <= length(argv)
a = argv[i]
startswith(a, "--") || error("unexpected argument: $a (see the header of $(PROGRAM_FILE))")
key = a[3:end]
haskey(opts, key) || error("unknown option: $a")
if key in FLAGS
opts[key] = true
i += 1
continue
end
i + 1 <= length(argv) || error("option --$key needs a value")
val = argv[i+1]
opts[key] = key == "size" ? parse_size(val) :
key in ("files", "concurrency", "sample-ms") ? parse(Int, val) :
key == "timeout" ? parse(Float64, val) :
key == "pid" ? parse(Int, val) :
val
i += 2
end
opts["kind"] in ("binary", "text", "mixed") ||
error("--kind must be binary, text or mixed (got $(opts["kind"]))")
opts["files"] >= 1 || error("--files must be >= 1")
opts["concurrency"] >= 1 || error("--concurrency must be >= 1")
return opts
end
# ------------------------------------------------------------------------- dirs
#
# Resolved from the same environment variables src/config.jl reads, so a server
# started with custom dirs is benchmarked correctly. Kept as a standalone table
# rather than `using FileServer` so the harness doesn't pay to load Lux.
sinkdirs() = (
done = get(ENV, "FS_DONE_DIR", "data/done"),
text_done = get(ENV, "FS_TEXT_DONE_DIR", "data/text_done"),
binary = get(ENV, "FS_BINARY_DIR", "data/binary"),
failed = get(ENV, "FS_FAILED_DIR", "data/failed"),
)
stagedirs() = (
spool = get(ENV, "FS_SPOOL_DIR", "data/spool"),
known = get(ENV, "FS_KNOWN_DIR", "data/known"),
unknown = get(ENV, "FS_UNKNOWN_DIR", "data/unknown"),
text = get(ENV, "FS_TEXT_DIR", "data/text"),
)
"Count work items in `dir`, ignoring the .meta.json sidecars stages 2/4 write."
function count_files(dir::AbstractString)::Int
isdir(dir) || return 0
n = 0
for name in readdir(dir)
endswith(name, ".meta.json") && continue
isfile(joinpath(dir, name)) && (n += 1)
end
return n
end
counts(dirs) = NamedTuple{keys(dirs)}(map(count_files, values(dirs)))
total(c) = sum(values(c))
deltas(now_, base) = NamedTuple{keys(now_)}(map(-, values(now_), values(base)))
# ----------------------------------------------------------------------- memory
"Read (VmRSS, VmHWM) in bytes for `pid`, or `nothing` if unreadable."
function read_rss(pid::Int)
rss = hwm = nothing
try
for line in eachline("/proc/$pid/status")
if startswith(line, "VmRSS:")
rss = parse(Int, split(line)[2]) * 1024
elseif startswith(line, "VmHWM:")
hwm = parse(Int, split(line)[2]) * 1024
end
end
catch
return nothing
end
return (rss === nothing || hwm === nothing) ? nothing : (rss, hwm)
end
"""
Find the running server process, or `nothing`.
`pgrep -f` matches against the whole command line, which catches more than the
server: any shell launched with the command in its own argv (`sh -c 'julia …
bin/server.jl > log'`, a `setsid`/`nohup` wrapper, even the terminal running the
benchmark) matches the same pattern. Sampling one of those reports a few MiB of
shell as the server's memory — a wrong answer that looks plausible, which is the
worst kind.
So candidates are filtered by what each process *is* (`/proc/<pid>/comm`, the
executable name) rather than by what its arguments say. No pattern over argv can
make that distinction.
"""
function detect_pid()
out = try
readchomp(`pgrep -f "bin/server.jl"`)
catch
return nothing
end
candidates = parse.(Int, split(out))
pids = filter(candidates) do pid
comm = try
readchomp("/proc/$pid/comm")
catch
return false # exited between pgrep and here
end
startswith(comm, "julia")
end
isempty(pids) && return nothing
length(pids) > 1 && @warn "multiple server processes matched; sampling the first" pids
return first(pids)
end
"""
Reset the kernel's peak-RSS counter so VmHWM reflects only this run.
Without it, VmHWM carries the high-water mark from startup (model load) or from
an earlier benchmark, which would silently dominate a small run's result.
Requires the server to run as the same user; on failure we say so and fall back
to sampled VmRSS, which can miss a spike between samples.
"""
function reset_peak_rss(pid::Int)::Bool
try
write("/proc/$pid/clear_refs", "5")
return true
catch
return false
end
end
# ------------------------------------------------------------- per-stage counters
#
# The server exposes monotonic counters at GET /stats (src/stats.jl). Rates are
# ours to compute: scrape once before the run and once after, subtract, divide by
# the elapsed *server* clock so a slow scrape doesn't distort the window.
"Fetch and parse GET /stats, or `nothing` if the server doesn't serve it."
function scrape_stats(url::String)
try
resp = HTTP.get(string(rstrip(url, '/'), "/stats");
status_exception = false, retry = false, readtimeout = 5)
resp.status == 200 || return nothing
return JSON3.read(String(resp.body))
catch
return nothing
end
end
"One stage's activity between two scrapes."
struct StageDelta
stage::Int
name::String
workers::Int
completed::Int
failed::Int
bytes::Int
busy::Float64 # summed handler seconds across all workers in the pool
blocked::Float64 # of `busy`, seconds parked on a full downstream queue
peak_depth::Int # deepest its queue got, from the sampler
capacity::Int
end
files_per_sec(d::StageDelta, window) = d.completed / max(window, 1e-9)
mib_per_sec(d::StageDelta, window) = d.bytes / max(window, 1e-9) / 1024^2
"Mean wall time one file spends in one worker of this stage."
service_ms(d::StageDelta) = d.completed == 0 ? NaN :
(d.busy - d.blocked) / d.completed * 1000
"""
Fraction of the pool's capacity spent doing this stage's own work.
Blocked time is subtracted first: a stage parked on a full downstream queue is
waiting, not working, and leaving it in would light up every stage upstream of a
jam as though each were the jam.
"""
utilization(d::StageDelta, window) =
(d.busy - d.blocked) / max(window * d.workers, 1e-9)
blocked_share(d::StageDelta) = d.busy <= 0 ? 0.0 : d.blocked / d.busy
"Subtract two scrapes into per-stage deltas, folding in sampled peak depths."
function stage_deltas(before, after, peak_depth::Dict{Int,Int})
out = StageDelta[]
for (b, a) in zip(before.stages, after.stages)
push!(out, StageDelta(a.stage, String(a.name), a.workers,
a.completed - b.completed,
a.failed - b.failed,
a.bytes - b.bytes,
a.busy_seconds - b.busy_seconds,
a.blocked_seconds - b.blocked_seconds,
get(peak_depth, Int(a.stage), 0),
a.queue_capacity))
end
return out
end
"JSON has no NaN. A stage that completed nothing has no service time, and `null`
is the honest way to say that — writing NaN just makes JSON3 throw."
json_num(x::Real) = isfinite(x) ? x : nothing
pad(s, n) = rpad(string(s), n)
lpad_(s, n) = lpad(string(s), n)
"""
Print the per-stage table and say which stage is the bottleneck.
The verdict reads utilization, not throughput: in a pipeline every stage
completes the same files, so at steady state they all report nearly the same
files/s regardless of which one is the constraint. What separates them is how
hard each pool had to work to keep up — the bottleneck is pinned near 1.0 while
its neighbours idle.
"""
function stage_report(deltas::Vector{StageDelta}, window::Float64)
println("PER-STAGE (server counters, delta over the end-to-end window)")
println(" stage files/s MiB/s svc ms util blocked peak queue failed")
for d in deltas
svc = service_ms(d)
println(" $(d.stage) $(pad(d.name, 10)) " *
lpad_(fmt(files_per_sec(d, window)), 8) * " " *
lpad_(fmt(mib_per_sec(d, window)), 8) * " " *
lpad_(isnan(svc) ? "—" : fmt(svc, 1), 8) * " " *
lpad_(fmt(utilization(d, window)), 6) * " " *
lpad_(fmt(blocked_share(d) * 100, 0) * "%", 7) * " " *
lpad_("$(d.peak_depth)/$(d.capacity)", 11) * " " *
lpad_(d.failed, 7))
end
# Per-stage files/s are not comparable across rows and saying so costs one
# line: the stages process different subsets (stage 2 only known files,
# stage 4 only text), so a low rate can mean "little work arrived here"
# rather than "slow". Utilization is the column that compares.
println(" (files/s counts only files routed to that stage; svc is per-file wall time in")
println(" one worker; util = (busy − blocked) / (window × workers))")
worked = filter(d -> d.completed > 0, deltas)
if isempty(worked)
println(" (no stage completed a file in this window)")
return nothing
end
top = argmax(d -> utilization(d, window), worked)
println(" bottleneck stage $(top.stage) ($(top.name)) at " *
"$(fmt(utilization(top, window) * 100, 0))% utilization of " *
"$(top.workers) worker(s)")
if utilization(top, window) < 0.5
println(" — but no stage is near saturated: the pipeline is " *
"waiting on intake,\n not on itself. Raise --concurrency " *
"or --files to load it properly.")
end
for d in worked
blocked_share(d) > 0.25 && println(" ! stage $(d.stage) ($(d.name)) spent " *
"$(fmt(blocked_share(d) * 100, 0))% of its time parked on a full downstream " *
"queue —\n it is being held up by the stage after it, not doing that work itself.")
end
return nothing
end
# ------------------------------------------------------------------------ corpus
const WORDS = split("the quick brown fox jumps over a lazy dog while parsing " *
"headers and spooling bytes onto disk for later enrichment " *
"because throughput matters more than latency here")
"Write one file of exactly `size` bytes, in bounded chunks so the generator
itself never holds a whole 1 GB file in memory."
function write_file(path::AbstractString, size::Int, kind::Symbol, rng)
chunk = 1024 * 1024
open(path, "w") do io
remaining = size
while remaining > 0
n = min(chunk, remaining)
if kind === :binary
write(io, rand(rng, UInt8, n))
else
buf = IOBuffer()
while buf.size < n
print(buf, rand(rng, WORDS), rand(rng) < 0.06 ? ".\n" : " ")
end
write(io, take!(buf)[1:n])
end
remaining -= n
end
end
return nothing
end
"Generate the corpus and return (dir, paths, total_bytes)."
function make_corpus(opts)
n, size, kind = opts["files"], opts["size"], opts["kind"]
totalbytes = n * size
if totalbytes > 16 * 1024^3 && !opts["force"]
error("corpus would be $(human(totalbytes)) on disk; pass --force if that's intended")
end
dir = mktempdir(; prefix = "fsbench-")
rng = MersenneTwister(1234)
paths = String[]
for i in 1:n
k = kind == "mixed" ? (isodd(i) ? :binary : :text) :
kind == "text" ? :text : :binary
ext = k === :text ? "txt" : "bin"
path = joinpath(dir, "bench-$(lpad(i, 6, '0')).$ext")
write_file(path, size, k, rng)
push!(paths, path)
end
return dir, paths, totalbytes
end
function existing_corpus(dir::AbstractString)
isdir(dir) || error("--corpus is not a directory: $dir")
paths = sort(filter(isfile, readdir(dir; join = true)))
isempty(paths) && error("--corpus directory is empty: $dir")
return paths, sum(filesize, paths)
end
# ----------------------------------------------------------------------- upload
struct Upload
status::Int # HTTP status, or 0 if the request threw
accepted::Int # jobs the server actually queued (from the 202/503 body)
seconds::Float64
end
"POST one file as multipart/form-data and report what the server accepted."
function upload_one(url::String, path::String)::Upload
t0 = time()
try
form = HTTP.Form(["file" => HTTP.Multipart(basename(path), open(path, "r"),
"application/octet-stream")])
resp = HTTP.post(url, [], form; status_exception = false, retry = false)
# 202 and 503 both carry an `accepted` array: a partially-accepted batch
# still queued those jobs, and they will show up in the sinks.
acc = try
length(JSON3.read(String(resp.body)).accepted)
catch
resp.status == 202 ? 1 : 0
end
return Upload(resp.status, acc, time() - t0)
catch e
e isa InterruptException && rethrow()
@warn "upload failed" file = basename(path) exception = e
return Upload(0, 0, time() - t0)
end
end
"""
Upload every path, at most `concurrency` in flight.
A bounded set of worker tasks pulling from a shared index keeps exactly
`concurrency` requests in flight for the whole run — unlike batching, where each
batch stalls on its slowest (largest) file and the real concurrency sags.
"""
function upload_all(url::String, paths::Vector{String}, concurrency::Int)
endpoint = string(rstrip(url, '/'), "/upload")
results = Vector{Upload}(undef, length(paths))
next = Threads.Atomic{Int}(1)
@sync for _ in 1:min(concurrency, length(paths))
Threads.@spawn while true
i = Threads.atomic_add!(next, 1)
i > length(paths) && break
results[i] = upload_one(endpoint, paths[i])
end
end
return results
end
# ------------------------------------------------------------------- formatting
function human(bytes::Real)
b = Float64(bytes)
for unit in ("B", "KiB", "MiB", "GiB", "TiB")
(abs(b) < 1024 || unit == "TiB") && return "$(round(b; digits = 2)) $unit"
b /= 1024
end
end
fmt(x::Real, digits::Int = 2) = string(round(Float64(x); digits = digits))
function percentile(sorted::Vector{Float64}, p::Float64)
isempty(sorted) && return NaN
idx = clamp(ceil(Int, p * length(sorted)), 1, length(sorted))
return sorted[idx]
end
# ------------------------------------------------------------------------- main
function main(argv)
opts = parse_args(argv)
url = string(opts["url"])
# Fail fast and clearly if there's no server, rather than reporting a run of zeros.
try
HTTP.get(string(rstrip(url, '/'), "/health"); retry = false, readtimeout = 5)
catch e
println(stderr, "cannot reach $url/health — is the server running?")
println(stderr, " start it with: julia --project=. -t auto bin/server.jl")
return 1
end
sinks, stages = sinkdirs(), stagedirs()
# Leftovers mid-pipeline would land in the sinks during our window and be
# counted as our throughput, so say so up front rather than quietly skewing.
pending = total(counts(stages))
pending > 0 && @warn "pipeline is not idle: $pending file(s) in the stage dirs; " *
"throughput will include their completions"
# --- corpus
generated = opts["corpus"] === nothing
corpusdir, paths, corpusbytes = if generated
print("generating corpus: $(opts["files"]) × $(human(opts["size"])) ($(opts["kind"]))… ")
t = time()
d, p, b = make_corpus(opts)
println("done in $(fmt(time() - t))s → $d")
d, p, b
else
p, b = existing_corpus(String(opts["corpus"]))
println("using corpus: $(length(p)) file(s), $(human(b)) from $(opts["corpus"])")
String(opts["corpus"]), p, b
end
try
pid = opts["no-mem"] ? nothing : something(opts["pid"], detect_pid(), Some(nothing))
if pid === nothing && !opts["no-mem"]
@warn "could not find the server process; skipping memory (pass --pid PID)"
end
baseline_rss = nothing
peak_reset = false
if pid !== nothing
r = read_rss(pid)
r === nothing && (@warn "cannot read /proc/$pid/status; skipping memory"; pid = nothing)
if pid !== nothing
peak_reset = reset_peak_rss(pid)
peak_reset || @warn "could not reset the peak-RSS counter (/proc/$pid/clear_refs); " *
"reporting sampled RSS only"
# Baseline is read *after* the reset, not before. VmHWM restarts
# from whatever RSS is at the moment of the reset, so a baseline
# sampled earlier is measured against a different origin — and if
# the GC hands memory back in between, the run reports negative
# growth, which is nonsense on its face.
r2 = read_rss(pid)
baseline_rss = r2 === nothing ? r[1] : r2[1]
end
end
if Threads.nthreads() == 1 && opts["size"] > 64 * 1024^2
@warn "running with 1 thread and large files: the sampler shares a thread with " *
"blocking file reads, so the RSS curve will be coarse. Prefer -t auto."
end
base_sinks = counts(sinks)
interval = opts["sample-ms"] / 1000
# --- per-stage counters: the "before" half of the delta.
stats_before = opts["no-stats"] ? nothing : scrape_stats(url)
if stats_before === nothing && !opts["no-stats"]
@warn "no /stats endpoint on this server; skipping the per-stage table " *
"(the server predates src/stats.jl)"
end
# --- sampler: RSS curve, stage dir depths, and queue depths.
stop = Threads.Atomic{Bool}(false)
rss_samples = Float64[]
depth_max = Dict(k => 0 for k in keys(stages))
queue_peak = Dict{Int,Int}()
sampler = Threads.@spawn begin
while !stop[]
if pid !== nothing
r = read_rss(pid)
r !== nothing && push!(rss_samples, Float64(r[1]))
end
d = counts(stages)
for k in keys(d)
depth_max[k] = max(depth_max[k], getfield(d, k))
end
# Queue depth, unlike directory depth, can't be missed by a slow
# sample in the same way — a file's *reference* sits in the queue
# for the whole time it waits — so this is the depth the stage
# table reports.
if stats_before !== nothing
s = scrape_stats(url)
s === nothing || for st in s.stages
k = Int(st.stage)
queue_peak[k] = max(get(queue_peak, k, 0), Int(st.queue_depth))
end
end
sleep(interval)
end
end
# --- intake
println("uploading $(length(paths)) file(s) at concurrency $(opts["concurrency"])…")
t_start = time()
ups = upload_all(url, paths, opts["concurrency"])
t_intake_end = time()
accepted = sum(u.accepted for u in ups)
n_202 = count(u -> u.status == 202, ups)
n_503 = count(u -> u.status == 503, ups)
n_err = count(u -> !(u.status in (202, 503)), ups)
intake_secs = t_intake_end - t_start
lat = sort([u.seconds for u in ups])
println(" intake: $accepted job(s) accepted in $(fmt(intake_secs))s " *
"($(fmt(accepted / max(intake_secs, 1e-9))) files/s, " *
"$(fmt(corpusbytes / max(intake_secs, 1e-9) / 1024^2)) MiB/s)")
n_503 > 0 && println(" backpressure: $n_503 request(s) got 503 (intake queue full)")
n_err > 0 && println(" errors: $n_err request(s) failed or returned an unexpected status")
# --- drain: poll the terminal sinks until they stop moving.
println("draining (polling sinks every $(opts["sample-ms"])ms)…")
completed = 0
t_last_progress = time()
t_last_completion = t_intake_end
timed_out = false
while completed < accepted
sleep(interval)
c = total(deltas(counts(sinks), base_sinks))
if c > completed
completed = c
t_last_completion = time()
t_last_progress = t_last_completion
elseif time() - t_last_progress > opts["timeout"]
timed_out = true
break
end
end
# Scrape before stopping the sampler, so the window closes as near the
# last completion as we can manage.
stats_after = stats_before === nothing ? nothing : scrape_stats(url)
stop[] = true
wait(sampler)
sink_delta = deltas(counts(sinks), base_sinks)
e2e_secs = t_last_completion - t_start
# The stage window is the server's own clock across the two scrapes, not
# e2e_secs: it starts a scrape earlier and ends a scrape later, and using
# our wall time against its counters would misattribute the difference.
stage_window, stage_delta = if stats_after === nothing
(0.0, StageDelta[])
else
(Float64(stats_after.now - stats_before.now),
stage_deltas(stats_before, stats_after, queue_peak))
end
final_rss = pid === nothing ? nothing : read_rss(pid)
peak_rss = if final_rss !== nothing && peak_reset
final_rss[2] # kernel VmHWM: catches spikes between samples
elseif !isempty(rss_samples)
maximum(rss_samples)
else
nothing
end
# --- report
println()
println("=" ^ 68)
println("corpus $(length(paths)) file(s), $(human(corpusbytes)) total, " *
"$(human(corpusbytes / length(paths))) avg")
println("concurrency $(opts["concurrency"])")
println()
println("INTAKE (HTTP 202 — bytes spooled, not processed)")
println(" accepted $accepted of $(length(paths)) [202: $n_202, 503: $n_503, error: $n_err]")
println(" wall $(fmt(intake_secs))s")
println(" rate $(fmt(accepted / max(intake_secs, 1e-9))) files/s, " *
"$(fmt(corpusbytes / max(intake_secs, 1e-9) / 1024^2)) MiB/s")
println(" latency p50 $(fmt(percentile(lat, 0.5) * 1000, 1))ms " *
"p95 $(fmt(percentile(lat, 0.95) * 1000, 1))ms " *
"max $(fmt(percentile(lat, 1.0) * 1000, 1))ms")
println()
println("END-TO-END (files reaching a terminal sink)")
println(" completed $completed of $accepted accepted" * (timed_out ? " ** TIMED OUT **" : ""))
println(" wall $(fmt(e2e_secs))s (first upload → last completion)")
println(" throughput $(fmt(completed / max(e2e_secs, 1e-9))) files/s, " *
"$(fmt(corpusbytes / max(e2e_secs, 1e-9) / 1024^2)) MiB/s")
println(" sinks done $(sink_delta.done) text_done $(sink_delta.text_done) " *
"binary $(sink_delta.binary) failed $(sink_delta.failed)")
println(" peak dir depth spool $(depth_max[:spool]) known $(depth_max[:known]) " *
"unknown $(depth_max[:unknown]) text $(depth_max[:text])")
println()
if !isempty(stage_delta)
stage_report(stage_delta, stage_window)
println()
end
if peak_rss !== nothing
println("SERVER MEMORY (pid $pid)")
println(" baseline RSS $(human(baseline_rss))")
println(" peak RSS $(human(peak_rss))" *
(peak_reset ? " (kernel VmHWM, reset at start)" : " (sampled — may miss spikes)"))
growth = peak_rss - baseline_rss
if growth <= 0
# RSS never got back to where it started, so the run's own cost
# is below the noise floor of the server settling after startup.
# Printing a negative "growth" would invite reading a memory
# *saving* into what is really "too small to measure here".
println(" growth none measurable (peak never exceeded the baseline)")
println(" The baseline was still falling when we sampled it — give the")
println(" server ~30s to settle after startup for a comparable figure.")
else
println(" growth $(human(growth))")
println(" per in-flight $(human(growth / opts["concurrency"])) " *
"at $(human(corpusbytes / length(paths))) avg file size")
println(" (should not grow with file size — intake streams to disk)")
end
# Julia's GC returns memory to the OS lazily, so a second run on the
# same process starts from an inflated baseline and under-reports
# growth. Absolute peak is the number to trust across runs.
baseline_rss > 1.3 * FRESH_RSS_HINT &&
println(" ! baseline is well above a fresh start ($(human(FRESH_RSS_HINT))): the GC " *
"has not\n returned memory from earlier work. Compare " *
"absolute peak, or restart\n the server for a clean growth figure.")
else
println("SERVER MEMORY not sampled")
end
println("=" ^ 68)
sink_delta.failed > 0 &&
println("\nnote: $(sink_delta.failed) file(s) landed in $(sinks.failed) — check the server log.")
timed_out &&
println("\nnote: drain stalled with $(accepted - completed) file(s) outstanding. " *
"Check the server log and the stage dirs; raise --timeout if the pipeline is just slow.")
if opts["json"] !== nothing
result = (
url, concurrency = opts["concurrency"], kind = opts["kind"],
files = length(paths), corpus_bytes = corpusbytes,
avg_file_bytes = corpusbytes / length(paths),
intake = (; accepted, n_202, n_503, n_err, seconds = intake_secs,
files_per_sec = accepted / max(intake_secs, 1e-9),
p50_ms = json_num(percentile(lat, 0.5) * 1000),
p95_ms = json_num(percentile(lat, 0.95) * 1000),
max_ms = json_num(percentile(lat, 1.0) * 1000)),
end_to_end = (; completed, seconds = e2e_secs, timed_out,
files_per_sec = completed / max(e2e_secs, 1e-9),
mib_per_sec = corpusbytes / max(e2e_secs, 1e-9) / 1024^2,
sinks = sink_delta, peak_stage_depth = depth_max),
stages = [(; stage = d.stage, name = d.name, workers = d.workers,
completed = d.completed, failed = d.failed, bytes = d.bytes,
busy_seconds = d.busy, blocked_seconds = d.blocked,
window_seconds = stage_window,
files_per_sec = files_per_sec(d, stage_window),
mib_per_sec = mib_per_sec(d, stage_window),
service_ms = json_num(service_ms(d)),
utilization = utilization(d, stage_window),
blocked_share = blocked_share(d),
peak_queue_depth = d.peak_depth,
queue_capacity = d.capacity) for d in stage_delta],
memory = (; pid, baseline_rss, peak_rss, peak_is_kernel_hwm = peak_reset,
growth = peak_rss === nothing ? nothing : peak_rss - baseline_rss,
samples = rss_samples),
)
open(String(opts["json"]), "w") do io
JSON3.write(io, result)
end
println("\nwrote $(opts["json"])")
end
return timed_out ? 1 : 0
finally
if generated && !opts["keep-corpus"]
rm(corpusdir; recursive = true, force = true)
elseif generated
println("\nkept corpus: $corpusdir")
end
end
end
if abspath(PROGRAM_FILE) == @__FILE__
exit(main(ARGS))
end

427
bin/bench_model.jl Executable file
View File

@@ -0,0 +1,427 @@
#!/usr/bin/env julia
#
# bench_model.jl — microbenchmark the classifier in isolation, with no server,
# no queue, and no disk in the way.
#
# bin/bench.jl measures the *pipeline*: it reports stage 1 as one number, the
# wall time of `handle_classify_job`, which is feature reads + inference + a
# rename + a log line, under whatever thread contention the other three pools are
# creating. That number is the right one for capacity planning and the wrong one
# for answering "is the model slow?". This script answers that question by taking
# the model apart:
#
# read_features open, read 16 bytes, seek, read 16 bytes, scale
# Lux.apply the network itself, on a feature vector already in memory
# classify both together — what stage 1 actually calls per file
#
# Three properties are worth checking beyond the raw per-file cost:
#
# * Feature reads should be flat in file size. read_features seeks to the tail
# rather than slurping, so a 1 GiB file should cost the same as a 1 KiB one.
# (This is the same claim bin/bench.jl makes about memory, on the CPU axis.)
# * Batching should be much cheaper per file. A 32x1 matmul wastes most of a
# BLAS call; if batch-64 inference is many times cheaper per file, that is
# the headroom a batching stage-1 would buy — worth knowing before building
# one, since today the pipeline classifies strictly one file at a time.
# * Inference should scale across threads. `Classifier` is shared read-only by
# the whole stage-1 pool on the claim that Lux inference is pure. If per-file
# cost degrades as tasks are added, that claim holds but BLAS threading is
# fighting the worker pool, and stage-1 workers are contending, not scaling.
#
# Usage:
# julia --project=. -t auto bin/bench_model.jl [options]
#
# --model PATH classifier artifact (default: $FS_MODEL_PATH or model/classifier.jld2)
# --reps N inference calls per timed trial (default: 20000)
# --trials N timed trials; the minimum is reported (default: 5)
# --batches LIST batch sizes to sweep, comma-separated (default: 1,8,64,512)
# --sizes LIST file sizes for the read_features sweep (default: 1k,64k,4m,256m)
# --no-threads skip the thread-scaling sweep
# --json PATH also write the results as JSON
#
# Reported times are the *minimum* over trials: for a microbenchmark the floor is
# the signal and everything above it is scheduler and GC noise.
using JSON3
using Random
using Statistics
using Printf
# The script is run directly, not as part of the package, so pull in exactly the
# pieces the classifier needs. `Lux`/`JLD2` first — model.jl and classify.jl both
# assume the including scope already has them (see the note at the top of model.jl).
using Lux
using JLD2
using LinearAlgebra
const SRC = joinpath(dirname(@__DIR__), "src")
include(joinpath(SRC, "model.jl"))
include(joinpath(SRC, "classify.jl"))
# ---------------------------------------------------------------- option parsing
const DEFAULTS = Dict{String,Any}(
"model" => get(ENV, "FS_MODEL_PATH", "model/classifier.jld2"),
"reps" => 20_000,
"trials" => 5,
"batches" => "1,8,64,512",
"sizes" => "1k,64k,4m,256m",
"no-threads" => false,
"json" => nothing,
)
const FLAGS = ("no-threads",)
function parse_size(s::AbstractString)::Int
m = match(r"^(\d+(?:\.\d+)?)\s*([kKmMgG]?)[bB]?$", strip(s))
m === nothing && error("bad size: $s (expected e.g. 512, 64k, 8m, 1g)")
mult = Dict('k' => 1024, 'm' => 1024^2, 'g' => 1024^3)
scale = isempty(m[2]) ? 1 : mult[lowercase(m[2])[1]]
return round(Int, parse(Float64, m[1]) * scale)
end
function parse_args(argv)
opts = copy(DEFAULTS)
i = 1
while i <= length(argv)
a = argv[i]
startswith(a, "--") || error("unexpected argument: $a")
key = a[3:end]
haskey(opts, key) || error("unknown option: $a")
if key in FLAGS
opts[key] = true; i += 1; continue
end
i + 1 <= length(argv) || error("option --$key needs a value")
opts[key] = key in ("reps", "trials") ? parse(Int, argv[i+1]) : argv[i+1]
i += 2
end
return opts
end
# ------------------------------------------------------------------- measurement
# Every timed loop stores its result here. Without a visible side effect the
# compiler is free to hoist a pure call out of the loop and we would be timing an
# empty `for`.
const SINK = Ref{Any}(nothing)
"""
measure(f, reps; trials) -> (ns_per_op, bytes_per_op)
Time `f` over `reps` calls, `trials` times, and report the fastest trial.
The first call is thrown away: it pays Julia's JIT compilation, which on a
function this small is orders of magnitude more than the thing being measured.
"""
function measure(f, reps::Int; trials::Int = 5)
SINK[] = f() # warm up (compile), and keep the result
best = Inf
for _ in 1:trials
GC.gc()
t0 = time_ns()
for _ in 1:reps
SINK[] = f()
end
best = min(best, (time_ns() - t0) / reps)
end
bytes = @allocated(SINK[] = f()) # one call, after warmup
return (Float64(best), Float64(bytes))
end
# ------------------------------------------------------------------- formatting
function human_time(ns::Real)
ns < 1_000 && return @sprintf("%.0f ns", ns)
ns < 1_000_000 && return @sprintf("%.2f µs", ns / 1e3)
ns < 1e9 && return @sprintf("%.2f ms", ns / 1e6)
return @sprintf("%.2f s", ns / 1e9)
end
human_bytes(b::Real) = b < 1024 ? @sprintf("%.0f B", b) :
b < 1024^2 ? @sprintf("%.1f KiB", b / 1024) :
@sprintf("%.1f MiB", b / 1024^2)
rate(ns::Real) = 1e9 / max(ns, 1e-9) # calls per second
function human_rate(r::Real)
r >= 1e6 && return @sprintf("%.2fM/s", r / 1e6)
r >= 1e3 && return @sprintf("%.1fk/s", r / 1e3)
return @sprintf("%.0f/s", r)
end
fmt2(x::Real) = @sprintf("%.2f", x)
# ------------------------------------------------------------- scaling control
"""
control_kernel(x) -> Float64
Pure arithmetic, no allocation, no library call — deliberately dependent
(each step needs the last) so the compiler can't vectorize it away, and sized to
land in the same microsecond neighbourhood as one `Lux.apply`.
"""
function control_kernel(x::Float64)
a = x
@inbounds for i in 1:600
a = sqrt(a + i)
end
return a
end
"""
control_scaling(trials) -> Vector
Run `control_kernel` over the same task counts as the model sweep. This is the
machine's own ceiling for perfectly parallel work: if the control scales and the
model doesn't, the shortfall is the model's, and no amount of `FS_WORKERS` will
recover it.
"""
function control_scaling(trials::Int)
rows = []
base = 0.0
per_task = 200_000
for k in unique([1; 2; 4; 8; Threads.nthreads()])
k > Threads.nthreads() && continue
best = Inf
for _ in 1:trials
GC.gc()
t0 = time_ns()
@sync for _ in 1:k
Threads.@spawn begin
local acc = 0.0
for i in 1:per_task
acc += control_kernel(i % 97 + 1.0)
end
SINK[] = acc
end
end
best = min(best, Float64(time_ns() - t0))
end
r = k * per_task / (best / 1e9)
k == 1 && (base = r)
push!(rows, (; tasks = k, ops_per_sec = r, speedup = r / base))
end
return rows
end
# ------------------------------------------------------------------------- corpus
"""
Write a file of exactly `size` random bytes, in bounded chunks.
Content is random rather than zeros so the classifier sees a realistic input —
and so the filesystem can't cheat with a sparse file, which would make the tail
`seek` unrepresentatively fast.
"""
function write_file(path::AbstractString, size::Int, rng)
chunk = 1024 * 1024
open(path, "w") do io
remaining = size
while remaining > 0
n = min(chunk, remaining)
write(io, rand(rng, UInt8, n))
remaining -= n
end
end
return path
end
# ------------------------------------------------------------------------- main
function main(argv)
opts = parse_args(argv)
modelpath = String(opts["model"])
isfile(modelpath) || (println(stderr, "model artifact not found: $modelpath"); return 1)
reps, trials = opts["reps"], opts["trials"]
batches = [parse(Int, s) for s in split(String(opts["batches"]), ",")]
sizes = [parse_size(s) for s in split(String(opts["sizes"]), ",")]
clf = load_classifier(modelpath)
println("model $modelpath")
println("architecture $(FEATURE_DIM) → 64 → 16 → 2 (Dense/relu, raw logits)")
println("julia threads $(Threads.nthreads()) BLAS threads $(BLAS.get_num_threads())")
println("timing min of $trials trials × $reps reps")
println("=" ^ 72)
results = Dict{String,Any}()
# --- 1. inference alone, one file at a time: the number the pipeline pays.
x1 = rand(Float32, FEATURE_DIM, 1)
infer_ns, infer_bytes = measure(reps; trials) do
Lux.apply(clf.model, x1, clf.ps, clf.st)
end
println()
println("INFERENCE (Lux.apply, batch 1 — features already in memory)")
println(" per call $(human_time(infer_ns)) $(human_rate(rate(infer_ns)))")
println(" allocations $(human_bytes(infer_bytes)) per call")
results["inference_batch1"] = (; ns = infer_ns, bytes = infer_bytes, per_sec = rate(infer_ns))
# --- 2. batching: how much of that is per-call overhead rather than math?
println()
println("INFERENCE BATCHED (same net, N files per apply)")
println(" batch per batch per file files/s speedup")
batch_rows = []
for b in batches
xb = rand(Float32, FEATURE_DIM, b)
ns, _ = measure(max(1, reps ÷ b); trials) do
Lux.apply(clf.model, xb, clf.ps, clf.st)
end
per_file = ns / b
@printf(" %8d %13s %12s %13s %7.1fx\n",
b, human_time(ns), human_time(per_file),
human_rate(rate(per_file)), infer_ns / per_file)
push!(batch_rows, (; batch = b, ns_per_batch = ns, ns_per_file = per_file,
files_per_sec = rate(per_file), speedup = infer_ns / per_file))
end
results["batched"] = batch_rows
println(" (a large speedup is headroom a batching stage 1 could claim; the pipeline")
println(" classifies one file per job today, so it pays the batch-1 row above)")
# --- 3. feature reads: should be flat in file size (seek, not slurp).
println()
println("FEATURE READS (read_features: 16 head + 16 tail bytes, scaled)")
println(" file size per call calls/s allocations")
read_rows = []
dir = mktempdir(; prefix = "fsmodel-")
try
rng = MersenneTwister(1234)
for sz in sizes
path = write_file(joinpath(dir, "f-$sz.bin"), sz, rng)
# Fewer reps for the big files: this touches the page cache, and the
# point is the shape of the curve, not another digit of precision.
r = max(200, reps ÷ 20)
ns, bytes = measure(() -> read_features(path), r; trials)
@printf(" %13s %14s %14s %14s\n",
human_bytes(sz), human_time(ns), human_rate(rate(ns)), human_bytes(bytes))
push!(read_rows, (; size_bytes = sz, ns, bytes, per_sec = rate(ns)))
end
finally
rm(dir; recursive = true, force = true)
end
results["read_features"] = read_rows
flat = length(read_rows) > 1 ?
maximum(r.ns for r in read_rows) / minimum(r.ns for r in read_rows) : 1.0
@printf(" spread across a %.0fx size range: %.1fx — %s\n",
maximum(sizes) / minimum(sizes), flat,
flat < 3 ? "flat, as designed (it seeks to the tail)" :
"NOT flat: something is reading more than 32 bytes")
# --- 4. classify(): what stage 1 calls, I/O and inference together.
println()
println("CLASSIFY (read_features + Lux.apply — one whole stage-1 file)")
dir2 = mktempdir(; prefix = "fsmodel-")
classify_ns = 0.0
try
path = write_file(joinpath(dir2, "sample.bin"), 64 * 1024, MersenneTwister(7))
classify_ns, classify_bytes = measure(() -> classify(clf, path), max(200, reps ÷ 20); trials)
println(" per file $(human_time(classify_ns)) $(human_rate(rate(classify_ns)))")
println(" allocations $(human_bytes(classify_bytes)) per file")
@printf(" split %.0f%% feature read, %.0f%% inference\n",
100 * (classify_ns - infer_ns) / classify_ns, 100 * infer_ns / classify_ns)
results["classify"] = (; ns = classify_ns, bytes = classify_bytes, per_sec = rate(classify_ns))
finally
rm(dir2; recursive = true, force = true)
end
# --- 5. thread scaling: does the shared read-only Classifier actually scale?
if !opts["no-threads"] && Threads.nthreads() > 1
println()
println("THREAD SCALING (concurrent Lux.apply on the one shared Classifier)")
println(" tasks files/s per file speedup efficiency GC")
thread_rows = []
base = 0.0
for k in unique([1; 2; 4; 8; Threads.nthreads()])
k > Threads.nthreads() && continue
# Work per task is held *constant* as tasks are added, so total work
# scales with `k`. Splitting a fixed total instead would shrink each
# task as the pool grows until `@spawn`/`@sync` overhead dominated,
# and the resulting curve would show a collapse that is the
# measurement's fault rather than the model's.
per_task = max(reps, 20_000)
# Each task gets its own input so we measure the model, not cache
# line ping-pong on a shared buffer.
xs = [rand(Float32, FEATURE_DIM, 1) for _ in 1:k]
best, best_gc = Inf, 0.0
for _ in 1:trials
GC.gc()
# Julia's GC stops the world, so it is the one cost that cannot
# be parallelized away: measuring its share here is what turns a
# bad efficiency number into a diagnosis (see the note below).
gc0 = Base.gc_num().total_time
t0 = time_ns()
@sync for t in 1:k
Threads.@spawn begin
local acc = 0.0f0
for _ in 1:per_task
y, _ = Lux.apply(clf.model, xs[t], clf.ps, clf.st)
acc += y[1] # consume the result
end
SINK[] = acc
end
end
elapsed = Float64(time_ns() - t0)
if elapsed < best
best = elapsed
best_gc = Float64(Base.gc_num().total_time - gc0)
end
end
files = k * per_task
fps = files / (best / 1e9)
k == 1 && (base = fps)
@printf(" %8d %13s %11s %7.2fx %10.0f%% %5.0f%%\n",
k, human_rate(fps), human_time(best / files), fps / base,
100 * fps / base / k, 100 * best_gc / best)
push!(thread_rows, (; tasks = k, files_per_sec = fps,
ns_per_file = best / files, speedup = fps / base,
gc_fraction = best_gc / best))
end
results["thread_scaling"] = thread_rows
# A poor scaling curve has two possible authors — the model or the box —
# and the table alone can't tell them apart. So run the same sweep on a
# kernel that is pure arithmetic with no allocation and no library
# underneath: whatever *it* achieves is this machine's ceiling for
# embarrassingly parallel work, and the gap between the two curves is
# the part that belongs to Lux.apply.
ctrl = control_scaling(trials)
results["control_scaling"] = ctrl
top = last(ctrl)
println(" control pure-compute kernel, same sweep: " *
"$(fmt2(top.speedup))x at $(top.tasks) tasks " *
"($(round(Int, 100 * top.speedup / top.tasks))% efficiency)")
model_top = last(thread_rows)
if model_top.speedup < 0.6 * top.speedup
println(" → the machine parallelizes; Lux.apply does not. Stage-1")
println(" workers past ~4 buy little, whatever FS_WORKERS says.")
else
println(" → inference tracks the machine's own scaling ceiling.")
end
gc_top = maximum(r.gc_fraction for r in thread_rows)
gc_top > 0.15 && println(" ! GC is $(round(Int, 100 * gc_top))% of the " *
"worst case: apply allocates per call, and\n" *
" collection stops every thread.")
end
println()
println("=" ^ 72)
println("Stage 1's cost per file in bin/bench.jl is this classify() figure plus a")
println("rename, a log line, and whatever contention the other three pools create.")
println("A large gap between the two is pipeline overhead, not the model.")
if opts["json"] !== nothing
results["meta"] = (; model = modelpath, feature_dim = FEATURE_DIM,
julia_threads = Threads.nthreads(),
blas_threads = BLAS.get_num_threads(),
reps, trials)
open(String(opts["json"]), "w") do io
JSON3.write(io, results)
end
println("\nwrote $(opts["json"])")
end
return 0
end
if abspath(PROGRAM_FILE) == @__FILE__
exit(main(ARGS))
end

556
bin/bench_stage1.jl Normal file
View File

@@ -0,0 +1,556 @@
#!/usr/bin/env julia
#
# bench_stage1.jl — take stage 1 apart and find the slowest component.
#
# bin/bench.jl reports stage 1 as a single number (the wall time of
# `handle_classify_job` under whole-pipeline contention) and bin/bench_model.jl
# takes the *classifier* apart. Neither answers "which part of stage 1 costs the
# most?", because stage 1 is more than the model. Per file it does:
#
# classify filesize + two 16-byte reads + a 32x1 forward pass
# read_features open, read head, seek, read tail, scale to Float32
# Lux.apply the network on a feature vector already in memory
# move_to rename spool/<f> -> known/<f> or unknown/<f>
# enqueue push a Job reference onto the downstream bounded queue
# logging two @info lines ("classified file", "routed to ...")
#
# This script times each of those in isolation, then times the real
# `handle_classify_job` end to end so the parts can be checked against the whole.
# The two knobs that most change the answer get their own sweeps:
#
# * Logger. The server runs `FlushLogger(ConsoleLogger(stderr))` — it formats
# and flushes every message. Under redirect (a log file, journald) that is a
# syscall per line, two lines per file, on the hot path. We time the handler
# under a null logger, a formatting-but-discarding logger, and the real
# flushing-to-file logger, so the cost of logging is a subtraction, not a
# guess. This sweep is what demoted stage 1's per-file lines to `@debug`
# (see the note in src/worker.jl); the standalone `logging (...)` rows below
# still price a *formatted* line, i.e. what those lines cost when switched
# back on with `JULIA_DEBUG=FileServer`, while the handler rows show what the
# stage pays with them off.
# * Concurrency. Components that own a lock (the queue's condition, the
# logger's stream) don't scale, and the ranking at one worker need not be the
# ranking at sixteen. The `--threads` sweep runs the full handler across
# worker counts.
#
# Usage:
# julia --project=. -t auto bin/bench_stage1.jl [options]
#
# --files N files per timed pass for consuming benchmarks (default: 2000)
# --reps N calls per timed pass for non-consuming benchmarks (default: 20000)
# --trials N timed passes; the minimum is reported (default: 5)
# --size SPEC corpus file size (default: 64k)
# --dir PATH working directory for the corpus (default: a temp dir under data/)
# --model PATH classifier artifact (default: $FS_MODEL_PATH or model/classifier.jld2)
# --threads LIST worker counts for the concurrency sweep (default: 1,2,4,8,nthreads)
# --no-threads skip the concurrency sweep
# --json PATH also write the results as JSON
#
# Reported times are the *minimum* over trials: the floor is the signal and
# everything above it is scheduler, page-cache and GC noise.
using FileServer
using Lux
using JSON3
using Logging
using Printf
using Random
const FS = FileServer
# ---------------------------------------------------------------- option parsing
const DEFAULTS = Dict{String,Any}(
"files" => 2000,
"reps" => 20_000,
"trials" => 5,
"size" => "64k",
"dir" => nothing,
"model" => get(ENV, "FS_MODEL_PATH", "model/classifier.jld2"),
"threads" => nothing,
"no-threads" => false,
"json" => nothing,
)
const FLAGS = ("no-threads",)
const INTS = ("files", "reps", "trials")
function parse_size(s::AbstractString)::Int
m = match(r"^(\d+(?:\.\d+)?)\s*([kKmMgG]?)[bB]?$", strip(s))
m === nothing && error("bad size: $s (expected e.g. 512, 64k, 8m, 1g)")
mult = Dict('k' => 1024, 'm' => 1024^2, 'g' => 1024^3)
scale = isempty(m[2]) ? 1 : mult[lowercase(m[2])[1]]
return round(Int, parse(Float64, m[1]) * scale)
end
function parse_args(argv)
opts = copy(DEFAULTS)
i = 1
while i <= length(argv)
a = argv[i]
startswith(a, "--") || error("unexpected argument: $a")
key = a[3:end]
haskey(opts, key) || error("unknown option: $a")
if key in FLAGS
opts[key] = true; i += 1; continue
end
i + 1 <= length(argv) || error("option --$key needs a value")
opts[key] = key in INTS ? parse(Int, argv[i+1]) : argv[i+1]
i += 2
end
return opts
end
# ------------------------------------------------------------------- measurement
# Every timed loop stores its result here. Without a visible side effect the
# compiler is free to hoist a pure call out of the loop and we would be timing an
# empty `for`.
const SINK = Ref{Any}(nothing)
"""
best_of(pass, prepare; trials) -> ns_per_op
Run `pass()` `trials` times and report the fastest, in nanoseconds per operation
(`pass` returns the number of operations it performed). `prepare()` runs before
each pass and is *not* timed — that is where a consuming benchmark puts the file
back where it started. `pass` comes first so callers can pass it as a `do` block.
The first pass is thrown away: it pays Julia's JIT compilation, which on calls
this small is orders of magnitude more than the thing being measured.
"""
function best_of(pass, prepare; trials::Int)
best = Inf
for t in 0:trials
prepare()
GC.gc()
t0 = time_ns()
n = pass()
dt = Float64(time_ns() - t0)
t == 0 && continue # warm-up: compiled, not measured
best = min(best, dt / n)
end
return best
end
noop() = nothing
# ------------------------------------------------------------------- formatting
function human_time(ns::Real)
ns < 1_000 && return @sprintf("%.0f ns", ns)
ns < 1_000_000 && return @sprintf("%.2f µs", ns / 1e3)
ns < 1e9 && return @sprintf("%.2f ms", ns / 1e6)
return @sprintf("%.2f s", ns / 1e9)
end
function human_rate(r::Real)
r >= 1e6 && return @sprintf("%.2fM/s", r / 1e6)
r >= 1e3 && return @sprintf("%.1fk/s", r / 1e3)
return @sprintf("%.0f/s", r)
end
rate(ns::Real) = 1e9 / max(ns, 1e-9)
rule(n = 78) = println("-" ^ n)
function header(title)
println()
println(title)
rule()
end
# ------------------------------------------------------------------------- corpus
"""
Write a file of exactly `size` random bytes, in bounded chunks.
Content is random rather than zeros so the classifier sees a realistic input —
and so the filesystem can't cheat with a sparse file, which would make the tail
`seek` unrepresentatively fast.
"""
function write_file(path::AbstractString, size::Int, rng)
chunk = 1024 * 1024
open(path, "w") do io
remaining = size
while remaining > 0
n = min(chunk, remaining)
write(io, rand(rng, UInt8, n))
remaining -= n
end
end
return path
end
"""
make_corpus(cfg, n, size, rng) -> Vector{Job}
Create `n` spooled files and the `Job` references a stage-1 worker would dequeue
for them — the exact input `handle_classify_job` sees.
"""
function make_corpus(cfg::FS.Config, n::Int, size::Int, rng)
jobs = FS.Job[]
for i in 1:n
id, path = FS.spool_path(cfg, @sprintf("bench-%06d.bin", i))
write_file(path, size, rng)
push!(jobs, FS.Job(id, basename(path), path, size, time()))
end
return jobs
end
"""
respool!(cfg, jobs)
Put every corpus file back in `spool/`, wherever the last pass left it (known/,
unknown/, or already home). This is the untimed `prepare` step for benchmarks
that consume their input by moving it.
"""
function respool!(cfg::FS.Config, jobs::Vector{FS.Job})
for job in jobs
isfile(job.path) && continue
for dir in (cfg.known_dir, cfg.unknown_dir, cfg.failed_dir)
candidate = joinpath(dir, basename(job.path))
if isfile(candidate)
mv(candidate, job.path; force = true)
break
end
end
end
return nothing
end
"Drain a queue without blocking, so the next pass starts from empty."
function drain!(q::FS.ChannelQueue)
while length(q) > 0
FS.dequeue!(q)
end
return nothing
end
# --------------------------------------------------------------------- loggers
"""
with_logger_named(name, path, f)
Run `f` under one of the three loggers the cost of logging is bracketed by:
* `:null` — `NullLogger`: the `@info` macro's own overhead, nothing else.
* `:format` — `ConsoleLogger` to `devnull`: message formatting and key/value
interpolation, but no I/O.
* `:flush` — `FlushLogger(ConsoleLogger(io))` to a real file: what
`FileServer.run` installs, under the redirect it was written for.
* `:debug` — the same, at `Debug` level: the stage's per-file lines are
`@debug`, so this is the equivalent of running the server with
`JULIA_DEBUG=FileServer` and the only setting under which they
are emitted at all.
"""
function with_logger_named(f, which::Symbol, path::AbstractString)
if which === :null
return with_logger(f, NullLogger())
elseif which === :format
return with_logger(f, ConsoleLogger(devnull))
elseif which === :flush || which === :debug
level = which === :debug ? Logging.Debug : Logging.Info
return open(path, "w") do io
with_logger(f, FS.FlushLogger(ConsoleLogger(io, level)))
end
end
error("unknown logger: $which")
end
# ------------------------------------------------------------------ components
"""
component_rows(cfg, clf, jobs, opts) -> Vector
Time each piece of stage 1 on its own. Non-consuming pieces (`filesize`,
`read_features`, `Lux.apply`, `classify`, the log lines) run `reps` times over
the corpus; consuming pieces (`move_to`, the full handler) run once per corpus
file with an untimed reset between passes.
"""
function component_rows(cfg::FS.Config, clf::FS.Classifier, jobs::Vector{FS.Job}, opts)
reps, trials = opts["reps"], opts["trials"]
nfiles = length(jobs)
paths = [j.path for j in jobs]
rows = []
# A feature vector already in memory, so the inference row measures the net
# and not the disk read in front of it.
feats = FS.read_features(paths[1])
x = reshape(feats, FS.FEATURE_DIM, 1)
logger = ConsoleLogger(devnull) # components other than the log rows: quiet
# --- filesize: the stat() read_features does before touching the bytes
push!(rows, (; name = "filesize (stat)", part = "classify",
ns = best_of(noop; trials) do
@inbounds for i in 1:reps
SINK[] = filesize(paths[(i - 1) % nfiles + 1])
end
reps
end))
# --- read_features: open + head read + seek + tail read + scale
push!(rows, (; name = "read_features", part = "classify",
ns = best_of(noop; trials) do
@inbounds for i in 1:reps
SINK[] = FS.read_features(paths[(i - 1) % nfiles + 1])
end
reps
end))
# --- Lux.apply: the network alone, features already in memory
push!(rows, (; name = "Lux.apply (1x32)", part = "classify",
ns = best_of(noop; trials) do
for _ in 1:reps
SINK[] = Lux.apply(clf.model, x, clf.ps, clf.st)
end
reps
end))
# --- classify: read_features + apply + argmax, what the handler calls
push!(rows, (; name = "classify (total)", part = "classify",
ns = best_of(noop; trials) do
@inbounds for i in 1:reps
SINK[] = FS.classify(clf, paths[(i - 1) % nfiles + 1])
end
reps
end))
# --- move_to: the rename out of spool/. Consuming: reset before each pass.
push!(rows, (; name = "move_to (rename)", part = "route",
ns = best_of(() -> respool!(cfg, jobs); trials) do
@inbounds for job in jobs
SINK[] = FS.move_to(cfg.unknown_dir, job)
end
nfiles
end))
# --- enqueue: lock, push, notify on an uncontended, non-full queue
q = FS.ChannelQueue(nfiles + 1)
stats = FS.StageStats()
push!(rows, (; name = "enqueue_blocking!", part = "route",
ns = best_of(() -> drain!(q); trials) do
@inbounds for job in jobs
SINK[] = FS.enqueue_blocking!(q, job, stats;
retry_seconds = FS.ROUTE_ENQUEUE_RETRY_SECONDS)
end
nfiles
end))
drain!(q)
# --- the two @info lines, under each of the three loggers
job1 = jobs[1]
logfile = joinpath(cfg.spool_dir, "..", "bench_stage1.log")
for (which, label) in ((:null, "logging (NullLogger)"),
(:format, "logging (format only)"),
(:flush, "logging (flush→file)"))
ns = with_logger_named(which, logfile) do
best_of(noop; trials) do
for _ in 1:reps
@info "classified file" worker=1 id=job1.id name=job1.original_name size=job1.size classification=:unknown
@info "routed to content triage" worker=1 id=job1.id dest=job1.path
end
reps
end
end
push!(rows, (; name = label, part = "log", ns))
end
rm(logfile; force = true)
return rows, logger
end
"""
handler_rows(cfg, jobs, opts) -> Vector
Time the real `handle_classify_job` end to end under each logger. The difference
between the rows is the cost logging adds to a file; the `:flush` row is what the
running server actually pays.
"""
function handler_rows(cfg::FS.Config, jobs::Vector{FS.Job}, opts)
trials = opts["trials"]
nfiles = length(jobs)
logfile = joinpath(dirname(cfg.spool_dir), "bench_stage1.log")
known = FS.ChannelQueue(nfiles + 1)
unknown = FS.ChannelQueue(nfiles + 1)
stats = FS.StageStats()
rows = []
for (which, label) in ((:null, "handle_classify_job (NullLogger)"),
(:format, "handle_classify_job (format only)"),
(:flush, "handle_classify_job (flush→file)"),
(:debug, "handle_classify_job (JULIA_DEBUG)"))
ns = with_logger_named(which, logfile) do
best_of(() -> (respool!(cfg, jobs); drain!(known); drain!(unknown)); trials) do
@inbounds for job in jobs
FS.handle_classify_job(job, cfg, 1, known, unknown, stats)
end
nfiles
end
end
push!(rows, (; name = label, part = "total", ns))
end
respool!(cfg, jobs); drain!(known); drain!(unknown)
rm(logfile; force = true)
return rows
end
"""
thread_rows(cfg, jobs, opts) -> Vector
Run the full handler across worker counts, under the server's real logger. A
component that owns a lock — the queue's condition variable, the logger's
stream — stops scaling here even though it looked cheap single-threaded, so this
is where the single-thread ranking gets checked against the deployed one.
"""
function thread_rows(cfg::FS.Config, jobs::Vector{FS.Job}, opts)
trials = opts["trials"]
nfiles = length(jobs)
counts = opts["threads"] === nothing ?
unique([1; 2; 4; 8; Threads.nthreads()]) :
[parse(Int, s) for s in split(String(opts["threads"]), ",")]
counts = sort(unique(filter(k -> 1 <= k <= Threads.nthreads(), counts)))
logfile = joinpath(dirname(cfg.spool_dir), "bench_stage1.log")
known = FS.ChannelQueue(nfiles + 1)
unknown = FS.ChannelQueue(nfiles + 1)
stats = FS.StageStats()
rows = []
base = 0.0
for k in counts
ns = with_logger_named(:flush, logfile) do
best_of(() -> (respool!(cfg, jobs); drain!(known); drain!(unknown)); trials) do
# Static split: each task takes a contiguous slice, so the only
# sharing between workers is the state the server also shares —
# the classifier, the queues, the logger, the filesystem.
chunk = cld(nfiles, k)
@sync for t in 1:k
lo = (t - 1) * chunk + 1
hi = min(t * chunk, nfiles)
lo > hi && continue
Threads.@spawn begin
@inbounds for i in lo:hi
FS.handle_classify_job(jobs[i], cfg, t, known, unknown, stats)
end
end
end
nfiles
end
end
r = rate(ns) # files/sec aggregate (ns is already per file, wall-clock)
k == counts[1] && (base = r)
push!(rows, (; workers = k, ns, files_per_sec = r, speedup = r / base))
end
respool!(cfg, jobs); drain!(known); drain!(unknown)
rm(logfile; force = true)
return rows
end
# ------------------------------------------------------------------- reporting
function print_components(rows, total_ns)
@printf("%-34s %-9s %12s %10s %9s\n", "component", "part", "per file", "rate", "% total")
rule()
for r in rows
@printf("%-34s %-9s %12s %10s %8.1f%%\n", r.name, r.part, human_time(r.ns),
human_rate(rate(r.ns)), 100 * r.ns / total_ns)
end
end
function print_threads(rows)
@printf("%-9s %12s %12s %9s\n", "workers", "per file", "throughput", "speedup")
rule()
for r in rows
@printf("%-9d %12s %12s %8.2fx\n", r.workers, human_time(r.ns),
human_rate(r.files_per_sec), r.speedup)
end
end
# ------------------------------------------------------------------------- main
function main(argv)
opts = parse_args(argv)
modelpath = String(opts["model"])
isfile(modelpath) || (println(stderr, "model artifact not found: $modelpath"); return 1)
size = parse_size(String(opts["size"]))
nfiles, trials = opts["files"], opts["trials"]
root = opts["dir"] === nothing ?
mktempdir(pwd(); prefix = "bench_stage1_") : String(opts["dir"])
owned = opts["dir"] === nothing
cfg = FS.Config(
spool_dir = joinpath(root, "spool"),
known_dir = joinpath(root, "known"),
unknown_dir = joinpath(root, "unknown"),
failed_dir = joinpath(root, "failed"),
model_path = modelpath,
)
for d in (cfg.spool_dir, cfg.known_dir, cfg.unknown_dir, cfg.failed_dir)
mkpath(d)
end
clf = FS.load_classifier(modelpath)
FS.CLASSIFIER[] = clf # handle_classify_job reads the global, as in the server
println("stage-1 component benchmark")
rule()
@printf("%-22s %s\n", "julia threads", Threads.nthreads())
@printf("%-22s %s\n", "model", modelpath)
@printf("%-22s %s\n", "corpus", "$(nfiles) files x $(size) B in $(root)")
@printf("%-22s %s\n", "reps / trials", "$(opts["reps"]) / $(trials)")
rng = MersenneTwister(0x5741524d)
jobs = make_corpus(cfg, nfiles, size, rng)
try
comps, _ = component_rows(cfg, clf, jobs, opts)
handlers = handler_rows(cfg, jobs, opts)
# The denominator is the handler as the server actually runs it: the real
# flushing logger at Info level, one worker. Percentages are shares of
# that, so they are directly comparable and the parts can be checked
# against the whole. The JULIA_DEBUG row is deliberately *not* the
# baseline — it is the opt-in configuration, and letting it set the scale
# would make every other component look free.
total = only(r.ns for r in handlers if r.name == "handle_classify_job (flush→file)")
header("Components (single worker)")
print_components(comps, total)
header("Whole handler, by logger")
print_components(handlers, total)
# Stage 1's own log lines are `@debug`, so what the deployed handler pays
# for them is the disabled-macro cost, not a formatted line.
accounted = sum(r.ns for r in comps if r.name in
("classify (total)", "move_to (rename)", "enqueue_blocking!", "logging (NullLogger)"))
println()
@printf("accounted: %s of %s (%.0f%%); unaccounted overhead %s\n",
human_time(accounted), human_time(total), 100 * accounted / total,
human_time(max(total - accounted, 0)))
threads = nothing
if !opts["no-threads"] && Threads.nthreads() > 1
threads = thread_rows(cfg, jobs, opts)
header("Full handler across workers (server logger)")
print_threads(threads)
end
if opts["json"] !== nothing
open(String(opts["json"]), "w") do io
JSON3.write(io, (;
julia_threads = Threads.nthreads(),
file_size = size, files = nfiles, reps = opts["reps"], trials,
components = comps, handlers, threads,
))
end
println("\nwrote ", opts["json"])
end
finally
owned && rm(root; recursive = true, force = true)
end
return 0
end
exit(main(ARGS))

699
bin/bench_stage2.jl Normal file
View File

@@ -0,0 +1,699 @@
#!/usr/bin/env julia
#
# bench_stage2.jl — take stage 2 apart and find the slowest component.
#
# bin/bench.jl reports stage 2 as a single number (its throughput and worker
# utilization under whole-pipeline contention). It doesn't say *which part* of
# the stage costs the most, and stage 2 is the one stage whose cost is dominated
# by something outside Julia entirely: it forks `exiftool`, a Perl program, once
# per file. Per file the stage does:
#
# build_metadata
# run_exiftool fork/exec exiftool -json -G -n, capture stdout
# run_with_timeout the watchdog wrapper around the subprocess
# JSON3.read parse the dump
# normalize_metadata coalesce ~20 tag names into the sidecar schema
# finalize_known! (commit_enriched!)
# JSON3.write serialize the sidecar payload
# write + fsync durably persist the sidecar bytes to a temp name
# mv + fsync_dir commit the sidecar, then persist the rename itself
# move_to rename known/<f> -> done/<f>, the commit point
# logging one @info line ("enriched")
#
# This script times each of those in isolation, then times the real
# `handle_known_job` end to end so the parts can be checked against the whole.
#
# Three things here that the stage-1 benchmark has no equivalent of:
#
# * The corpus must be real files. exiftool's cost depends on what it finds;
# random bytes exit early and would understate the stage by a lot. The
# default corpus is `data/done` — files that already went through stage 2 on
# this machine — copied back into a scratch known/ dir.
# * Two rows price the *alternatives* to one-fork-per-file, because if the
# fork dominates then the only fixes are to stop paying it per file:
# `exiftool (batched Nx)` runs the whole corpus through one process, and
# `exiftool (-stay_open)` keeps a single process alive and feeds it one file
# at a time over a pipe — the shape a streaming pipeline could actually use.
# Both are measured, not assumed.
# * `run_with_timeout` gets its own row *next to* a bare `Base.run` of the same
# command. The difference is what the watchdog costs, and its polling loop
# (`sleep(0.1)`) is a suspicious enough design to want measured rather than
# reasoned about.
#
# The `--threads` sweep runs the full handler across worker counts: subprocess
# spawning contends on things (the kernel's fork path, page cache, the logger's
# stream) that a single-threaded ranking can't reveal.
#
# Usage:
# julia --project=. -t auto bin/bench_stage2.jl [options]
#
# --files N corpus files per timed pass (default: 48). The concurrency
# sweep wants more than the component rows do — with a single
# 2 s file in the corpus, 48 files can't show more than ~4x no
# matter how many workers run, so pass --files 150 when the
# question is scaling.
# --reps N calls per timed pass for cheap, non-consuming benchmarks (default: 2000)
# --trials N timed passes; the minimum is reported (default: 3)
# --corpus PATH directory of real files to draw the corpus from (default: data/done)
# --dir PATH working directory for the corpus (default: a temp dir under data/)
# --timeout SEC exiftool timeout, as Config.exiftool_timeout (default: 30)
# --threads LIST worker counts for the concurrency sweep (default: 1,2,4,8,nthreads)
# --no-threads skip the concurrency sweep
# --no-stay-open skip the persistent-exiftool probe
# --json PATH also write the results as JSON
#
# Reported times are the *minimum* over trials: the floor is the signal and
# everything above it is scheduler, page-cache and GC noise.
using FileServer
using JSON3
using Logging
using Printf
using Random
const FS = FileServer
# ---------------------------------------------------------------- option parsing
const DEFAULTS = Dict{String,Any}(
"files" => 48,
"reps" => 2000,
"trials" => 3,
"corpus" => "data/done",
"dir" => nothing,
"timeout" => 30,
"threads" => nothing,
"no-threads" => false,
"no-stay-open" => false,
"json" => nothing,
)
const FLAGS = ("no-threads", "no-stay-open")
const INTS = ("files", "reps", "trials", "timeout")
function parse_args(argv)
opts = copy(DEFAULTS)
i = 1
while i <= length(argv)
a = argv[i]
startswith(a, "--") || error("unexpected argument: $a")
key = a[3:end]
haskey(opts, key) || error("unknown option: $a")
if key in FLAGS
opts[key] = true; i += 1; continue
end
i + 1 <= length(argv) || error("option --$key needs a value")
opts[key] = key in INTS ? parse(Int, argv[i+1]) : argv[i+1]
i += 2
end
return opts
end
# ------------------------------------------------------------------- measurement
# Every timed loop stores its result here. Without a visible side effect the
# compiler is free to hoist a pure call out of the loop and we would be timing an
# empty `for`.
const SINK = Ref{Any}(nothing)
"""
best_of(pass, prepare; trials) -> ns_per_op
Run `pass()` `trials` times and report the fastest, in nanoseconds per operation
(`pass` returns the number of operations it performed). `prepare()` runs before
each pass and is *not* timed — that is where a consuming benchmark puts the file
back where it started. `pass` comes first so callers can pass it as a `do` block.
The first pass is thrown away: it pays Julia's JIT compilation, which on calls
this small is orders of magnitude more than the thing being measured.
"""
function best_of(pass, prepare; trials::Int)
best = Inf
for t in 0:trials
prepare()
GC.gc()
t0 = time_ns()
n = pass()
dt = Float64(time_ns() - t0)
t == 0 && continue # warm-up: compiled, not measured
best = min(best, dt / n)
end
return best
end
noop() = nothing
# ------------------------------------------------------------------- formatting
function human_time(ns::Real)
ns < 1_000 && return @sprintf("%.0f ns", ns)
ns < 1_000_000 && return @sprintf("%.2f µs", ns / 1e3)
ns < 1e9 && return @sprintf("%.2f ms", ns / 1e6)
return @sprintf("%.2f s", ns / 1e9)
end
function human_rate(r::Real)
r >= 1e6 && return @sprintf("%.2fM/s", r / 1e6)
r >= 1e3 && return @sprintf("%.1fk/s", r / 1e3)
return @sprintf("%.0f/s", r)
end
rate(ns::Real) = 1e9 / max(ns, 1e-9)
rule(n = 84) = println("-" ^ n)
function header(title)
println()
println(title)
rule()
end
# ------------------------------------------------------------------------- corpus
"""
make_corpus(cfg, corpus_dir, n) -> Vector{Job}
Copy up to `n` real files from `corpus_dir` into `known/` and build the `Job`
references a stage-2 worker would dequeue for them — the exact input
`handle_known_job` sees.
Real files, not generated ones: exiftool's cost is a function of what it can
parse, and a file of random bytes bails out early enough to understate the stage
by an order of magnitude. `.meta.json` sidecars are skipped — they are stage-2
*output*, and enriching them would measure the wrong population.
"""
function make_corpus(cfg::FS.Config, corpus_dir::AbstractString, n::Int)
isdir(corpus_dir) || error("corpus dir not found: $corpus_dir")
names = filter(readdir(corpus_dir)) do f
!endswith(f, ".meta.json") && isfile(joinpath(corpus_dir, f))
end
isempty(names) && error("no usable files in corpus dir: $corpus_dir")
sort!(names) # deterministic selection across runs
length(names) > n && (names = names[1:n])
jobs = FS.Job[]
for (i, name) in enumerate(names)
src = joinpath(corpus_dir, name)
# Give it a fresh id/spool-style filename so nothing collides with the
# corpus the file came from.
id, spooled = FS.spool_path(cfg, @sprintf("s2-%04d-%s", i, basename(name)))
cp(src, spooled; force = true)
dest = joinpath(cfg.known_dir, basename(spooled))
mv(spooled, dest; force = true)
push!(jobs, FS.Job(id, basename(name), dest, filesize(dest), time()))
end
return jobs
end
"""
reknown!(cfg, jobs)
Put every corpus file back in `known/`, wherever the last pass left it (done/ or
already home), and delete any sidecar it produced. This is the untimed `prepare`
step for benchmarks that consume their input by committing it.
"""
function reknown!(cfg::FS.Config, jobs::Vector{FS.Job})
for job in jobs
base = basename(job.path)
for dir in (cfg.done_dir, cfg.failed_dir)
sidecar = joinpath(dir, string(base, ".meta.json"))
rm(sidecar; force = true)
rm(string(sidecar, ".tmp"); force = true)
end
isfile(job.path) && continue
for dir in (cfg.done_dir, cfg.failed_dir)
candidate = joinpath(dir, base)
if isfile(candidate)
mv(candidate, job.path; force = true)
break
end
end
end
return nothing
end
# --------------------------------------------------------------------- loggers
"""
with_logger_named(f, which, path)
Run `f` under one of the loggers the cost of logging is bracketed by:
* `:null` — `NullLogger`: the `@info` macro's own overhead, nothing else.
* `:format` — `ConsoleLogger` to `devnull`: message formatting and key/value
interpolation, but no I/O.
* `:flush` — `FlushLogger(ConsoleLogger(io))` to a real file: what
`FileServer.run` installs, under the redirect it was written
for. Stage 2's per-file line is `@info`, not `@debug`, so this
row is what the deployed server actually pays.
"""
function with_logger_named(f, which::Symbol, path::AbstractString)
if which === :null
return with_logger(f, NullLogger())
elseif which === :format
return with_logger(f, ConsoleLogger(devnull))
elseif which === :flush
return open(path, "w") do io
with_logger(f, FS.FlushLogger(ConsoleLogger(io, Logging.Info)))
end
end
error("unknown logger: $which")
end
# --------------------------------------------------- exiftool spawn alternatives
"""
capture(cmd) -> Vector{UInt8}
Run `cmd` and return its stdout, tolerating a non-zero exit the way
`run_with_timeout` does. `read(cmd, String)` would throw instead, and a real
corpus makes that a question of when, not whether: exiftool exits 1 on a file
whose type it can't recognize, which in this pipeline is a routine outcome (it
yields a degraded sidecar, not a failure). This is `run_with_timeout` minus the
watchdog, so the gap between the two rows prices the watchdog exactly.
"""
function capture(cmd::Cmd)
out = IOBuffer()
proc = Base.run(pipeline(cmd; stdout = out, stderr = devnull); wait = false)
wait(proc)
return take!(out)
end
"""
batched_ns(paths, trials) -> ns_per_file
Run the whole corpus through *one* `exiftool` process and divide by the file
count. This is the floor for "what does exiftool cost if you stop paying the
interpreter startup per file" — the fork, the Perl boot and the module loads are
paid once for the batch instead of once per file.
"""
function batched_ns(paths::Vector{String}, trials::Int)
return best_of(noop; trials) do
SINK[] = capture(`exiftool -json -G -n $paths`)
length(paths)
end
end
"""
stay_open_ns(paths, trials) -> ns_per_file (or nothing if unsupported)
Feed files one at a time to a single long-lived `exiftool -stay_open True -@ -`
process over a pipe, reading its `{ready}` sentinel after each. Unlike the
batched row this preserves the pipeline's actual shape — one file in, one result
out, arriving whenever it arrives — so it prices the realistic fix rather than
an unrealistic one.
"""
function stay_open_ns(paths::Vector{String}, trials::Int)
inp, outp = Pipe(), Pipe()
proc = Base.run(pipeline(`exiftool -stay_open True -@ -`;
stdin = inp, stdout = outp, stderr = devnull); wait = false)
close(inp.out); close(outp.in)
ask(path) = begin
write(inp, "-json\n-G\n-n\n", path, "\n-execute\n")
flush(inp)
readuntil(outp, "{ready}")
end
try
ask(paths[1]) # pay the one-time process startup untimed
return best_of(noop; trials) do
for p in paths
SINK[] = ask(p)
end
length(paths)
end
finally
try
write(inp, "-stay_open\nFalse\n"); flush(inp); close(inp)
wait(proc)
catch
kill(proc, Base.SIGKILL)
end
end
end
# ------------------------------------------------------------------ components
"""
component_rows(cfg, jobs, opts) -> Vector
Time each piece of stage 2 on its own. The subprocess rows run once per corpus
file (they cost milliseconds and don't need repetition); the in-memory and
filesystem rows run `reps` times; the committing rows run once per corpus file
with an untimed reset between passes.
"""
function component_rows(cfg::FS.Config, jobs::Vector{FS.Job}, opts)
reps, trials = opts["reps"], opts["trials"]
timeout = opts["timeout"]
nfiles = length(jobs)
paths = String[j.path for j in jobs]
rows = []
add!(name, part, ns) = push!(rows, (; name, part, ns))
# --- the bare interpreter: fork/exec + Perl boot, reading no file at all.
# Everything the real call does beyond this is actual work.
add!("exiftool -ver (spawn)", "extract", best_of(noop; trials) do
for _ in 1:nfiles
SINK[] = capture(`exiftool -ver`)
end
nfiles
end)
# --- the real command, run directly: spawn + parse the file, no watchdog.
add!("exiftool -json (raw run)", "extract", best_of(noop; trials) do
@inbounds for p in paths
SINK[] = capture(`exiftool -json -G -n $p`)
end
nfiles
end)
# --- the same command through the watchdog wrapper the stage actually uses.
# The gap to the row above is what the timeout costs.
add!("run_with_timeout", "extract", best_of(noop; trials) do
@inbounds for p in paths
SINK[] = FS.run_with_timeout(`exiftool -json -G -n $p`, timeout)
end
nfiles
end)
# --- run_exiftool: the wrapper plus JSON3.read plus the group-stripped Dict.
add!("run_exiftool (total)", "extract", best_of(noop; trials) do
@inbounds for p in paths
SINK[] = FS.run_exiftool(p, timeout)
end
nfiles
end)
# --- what a fork-free exiftool would cost, two ways (see the docstrings).
add!("exiftool (batched $(nfiles)x)", "alt", batched_ns(paths, trials))
if !opts["no-stay-open"]
try
add!("exiftool (-stay_open)", "alt", stay_open_ns(paths, trials))
catch e
@warn "persistent-exiftool probe failed; skipping" exception = e
end
end
# --- parsing alone, from bytes already captured: isolates JSON3 from the fork.
raw = [FS.run_with_timeout(`exiftool -json -G -n $p`, timeout) for p in paths]
valid = [b for b in raw if b !== nothing]
if !isempty(valid)
add!("JSON3.read (parse dump)", "extract", best_of(noop; trials) do
@inbounds for i in 1:reps
SINK[] = JSON3.read(String(copy(valid[(i - 1) % length(valid) + 1])))
end
reps
end)
end
# --- normalize_metadata: the ~20 tag coalesces, on a tag map already in memory.
bytags = [FS.run_exiftool(p, timeout) for p in paths]
good = [(j, b) for (j, b) in zip(jobs, bytags) if b !== nothing]
isempty(good) && error("exiftool produced no parseable output for any corpus file")
add!("normalize_metadata", "extract", best_of(noop; trials) do
@inbounds for i in 1:reps
j, b = good[(i - 1) % length(good) + 1]
SINK[] = FS.normalize_metadata(j, b)
end
reps
end)
# The sidecar payloads, built once, untimed: the commit rows below measure
# committing, not extracting.
metas = [FS.normalize_metadata(j, b) for (j, b) in good]
# --- serializing the sidecar (the raw dump makes this bigger than it looks).
add!("JSON3.write (sidecar)", "commit", best_of(noop; trials) do
@inbounds for i in 1:reps
SINK[] = JSON3.write(metas[(i - 1) % length(metas) + 1])
end
reps
end)
# --- sidecar bytes: open + write + flush + fsync, to a temp name.
# Non-consuming: same path rewritten each rep, as commit_enriched! does.
tmp = joinpath(cfg.done_dir, "bench_stage2_sidecar.tmp")
blobs = [JSON3.write(m) for m in metas]
# One pass over the real sidecar population, not `reps` of them. Two reasons,
# and the first is a correctness trap: thousands of back-to-back fsyncs
# saturate the device's write cache and each one starts waiting on the
# queue, which reported this row at 16 ms/file — eight times the whole
# `commit_enriched!` that contains it. The real stage fsyncs once per file
# with ~160 ms of exiftool between, and never queues that way. Second, real
# sidecars vary hugely in size (a zip's raw dump dwarfs a jpeg's), so the
# honest per-file number is one pass over all of them, not a cycle.
nio = length(blobs)
add!("write + fsync (sidecar)", "commit", best_of(noop; trials) do
@inbounds for i in 1:nio
open(tmp, "w") do io
write(io, blobs[(i - 1) % length(blobs) + 1])
flush(io)
FS.fsync_fd(fd(io))
end
end
nio
end)
rm(tmp; force = true)
# --- fsync_dir: persisting the rename itself, once per file in the real path.
add!("fsync_dir (done/)", "commit", best_of(noop; trials) do
for _ in 1:nio
SINK[] = FS.fsync_dir(cfg.done_dir)
end
nio
end)
# --- move_to: the rename known/<f> -> done/<f>. Consuming: reset each pass.
add!("move_to (rename)", "commit", best_of(() -> reknown!(cfg, jobs); trials) do
@inbounds for job in jobs
SINK[] = FS.move_to(cfg.done_dir, job)
end
nfiles
end)
# --- commit_enriched!: the whole sidecar-first commit, extraction excluded.
committable = [j for (j, _) in good]
add!("commit_enriched! (total)", "commit",
best_of(() -> reknown!(cfg, jobs); trials) do
@inbounds for (k, job) in enumerate(committable)
SINK[] = FS.commit_enriched!(cfg.done_dir, job, metas[k])
end
length(committable)
end)
reknown!(cfg, jobs)
# --- the one @info line, under each logger.
job1, meta1 = good[1][1], metas[1]
logfile = joinpath(dirname(cfg.known_dir), "bench_stage2.log")
for (which, label) in ((:null, "logging (NullLogger)"),
(:format, "logging (format only)"),
(:flush, "logging (flush→file)"))
ns = with_logger_named(which, logfile) do
best_of(noop; trials) do
for _ in 1:reps
@info "enriched" worker=1 id=job1.id dest=job1.path sidecar="x.meta.json" file_type=meta1.file_type created_by=meta1.created_by degraded=(meta1.error !== nothing)
end
reps
end
end
add!(label, "log", ns)
end
rm(logfile; force = true)
return rows
end
"""
handler_rows(cfg, jobs, opts) -> Vector
Time the real `handle_known_job` end to end under each logger. The difference
between the rows is the cost logging adds to a file; the `:flush` row is what the
running server actually pays.
"""
function handler_rows(cfg::FS.Config, jobs::Vector{FS.Job}, opts)
trials = opts["trials"]
nfiles = length(jobs)
logfile = joinpath(dirname(cfg.known_dir), "bench_stage2.log")
rows = []
for (which, label) in ((:null, "handle_known_job (NullLogger)"),
(:format, "handle_known_job (format only)"),
(:flush, "handle_known_job (flush→file)"))
ns = with_logger_named(which, logfile) do
best_of(() -> reknown!(cfg, jobs); trials) do
@inbounds for job in jobs
FS.handle_known_job(job, cfg, 1)
end
nfiles
end
end
push!(rows, (; name = label, part = "total", ns))
end
reknown!(cfg, jobs)
rm(logfile; force = true)
return rows
end
"""
thread_rows(cfg, jobs, opts) -> Vector
Run the full handler across worker counts, under the server's real logger. Stage
2 spends most of its time in a child process, so this is the sweep that matters
most: whether the stage scales is a question about the kernel's fork path and the
machine's cores, not about Julia.
Workers pull from a shared atomic counter rather than taking a contiguous slice.
That matches the server (its pool pulls from one queue), and it matters here in a
way it doesn't for stage 1: per-file exiftool time spans two orders of magnitude
on a real corpus — a single 2 s archive among 48 files — so a static split leaves
whichever worker drew it running alone while the rest idle, and the sweep would
report a scaling ceiling that is really just load imbalance.
"""
function thread_rows(cfg::FS.Config, jobs::Vector{FS.Job}, opts)
trials = opts["trials"]
nfiles = length(jobs)
counts = opts["threads"] === nothing ?
unique([1; 2; 4; 8; Threads.nthreads()]) :
[parse(Int, s) for s in split(String(opts["threads"]), ",")]
counts = sort(unique(filter(k -> 1 <= k <= Threads.nthreads(), counts)))
logfile = joinpath(dirname(cfg.known_dir), "bench_stage2.log")
rows = []
base = 0.0
for k in counts
ns = with_logger_named(:flush, logfile) do
next = Threads.Atomic{Int}(1)
best_of(() -> (reknown!(cfg, jobs); next[] = 1); trials) do
# Shared counter, not a contiguous slice: every worker takes the
# next unclaimed file the moment it frees up, exactly as the
# server's pool takes the next job off the known queue.
@sync for t in 1:k
Threads.@spawn begin
while true
i = Threads.atomic_add!(next, 1)
i > nfiles && break
@inbounds FS.handle_known_job(jobs[i], cfg, t)
end
end
end
nfiles
end
end
r = rate(ns) # files/sec aggregate (ns is already per file, wall-clock)
k == counts[1] && (base = r)
push!(rows, (; workers = k, ns, files_per_sec = r, speedup = r / base))
end
reknown!(cfg, jobs)
rm(logfile; force = true)
return rows
end
# ------------------------------------------------------------------- reporting
function print_components(rows, total_ns)
@printf("%-34s %-9s %12s %10s %9s\n", "component", "part", "per file", "rate", "% total")
rule()
for r in rows
@printf("%-34s %-9s %12s %10s %8.1f%%\n", r.name, r.part, human_time(r.ns),
human_rate(rate(r.ns)), 100 * r.ns / total_ns)
end
end
function print_threads(rows)
@printf("%-9s %12s %12s %9s\n", "workers", "per file", "throughput", "speedup")
rule()
for r in rows
@printf("%-9d %12s %12s %8.2fx\n", r.workers, human_time(r.ns),
human_rate(r.files_per_sec), r.speedup)
end
end
# ------------------------------------------------------------------------- main
function main(argv)
opts = parse_args(argv)
try
FS.assert_exiftool()
catch e
println(stderr, sprint(showerror, e)); return 1
end
root = opts["dir"] === nothing ?
mktempdir(pwd(); prefix = "bench_stage2_") : String(opts["dir"])
owned = opts["dir"] === nothing
cfg = FS.Config(
spool_dir = joinpath(root, "spool"),
known_dir = joinpath(root, "known"),
done_dir = joinpath(root, "done"),
failed_dir = joinpath(root, "failed"),
exiftool_timeout = opts["timeout"],
)
for d in (cfg.spool_dir, cfg.known_dir, cfg.done_dir, cfg.failed_dir)
mkpath(d)
end
jobs = try
make_corpus(cfg, String(opts["corpus"]), opts["files"])
catch e
owned && rm(root; recursive = true, force = true)
println(stderr, sprint(showerror, e)); return 1
end
bytes = sum(j.size for j in jobs)
println("stage-2 component benchmark")
rule()
@printf("%-22s %s\n", "julia threads", Threads.nthreads())
@printf("%-22s %s\n", "exiftool", strip(read(`exiftool -ver`, String)))
@printf("%-22s %s\n", "corpus", "$(length(jobs)) files ($(round(bytes / 1024^2; digits=1)) MiB) from $(opts["corpus"])")
@printf("%-22s %s\n", "scratch", root)
@printf("%-22s %s\n", "reps / trials", "$(opts["reps"]) / $(opts["trials"])")
@printf("%-22s %s\n", "exiftool timeout", "$(opts["timeout"]) s")
try
comps = component_rows(cfg, jobs, opts)
handlers = handler_rows(cfg, jobs, opts)
# The denominator is the handler as the server actually runs it: the real
# flushing logger, one worker. Percentages are shares of that, so they are
# directly comparable and the parts can be checked against the whole.
total = only(r.ns for r in handlers if r.name == "handle_known_job (flush→file)")
header("Components (single worker)")
print_components(comps, total)
header("Whole handler, by logger")
print_components(handlers, total)
pick(name) = only(r.ns for r in comps if r.name == name)
accounted = pick("run_exiftool (total)") + pick("commit_enriched! (total)") +
pick("logging (flush→file)")
println()
@printf("accounted: %s of %s (%.0f%%); unaccounted overhead %s\n",
human_time(accounted), human_time(total), 100 * accounted / total,
human_time(max(total - accounted, 0)))
threads = nothing
if !opts["no-threads"] && Threads.nthreads() > 1
threads = thread_rows(cfg, jobs, opts)
header("Full handler across workers (server logger)")
print_threads(threads)
end
if opts["json"] !== nothing
open(String(opts["json"]), "w") do io
JSON3.write(io, (;
julia_threads = Threads.nthreads(),
files = length(jobs), corpus_bytes = bytes,
reps = opts["reps"], trials = opts["trials"],
exiftool_timeout = opts["timeout"],
components = comps, handlers, threads,
))
end
println("\nwrote ", opts["json"])
end
finally
owned && rm(root; recursive = true, force = true)
end
return 0
end
exit(main(ARGS))

19
bin/cluster_sweep.jl Normal file
View File

@@ -0,0 +1,19 @@
#!/usr/bin/env julia
#
# Stage-5 phase-B runner (model/DESIGN_clustering.md §9): the single-owner,
# periodic/cron process that sweeps `binary/`, folds new files into the durable
# format catalog by sequential CRP-predictive assignment, and (re)writes
# promotion nominations. Run it single-threaded on a schedule — it is the ONLY
# writer of the catalog, so no locking is needed.
#
# julia --project=. bin/cluster_sweep.jl # incremental live sweep
# julia --project=. bin/cluster_sweep.jl --compact # offline Gibbs (seed / recompact)
#
# On a fresh catalog (nothing processed yet) the incremental sweep would send
# every file to background — there are no clusters to match — so the first run
# auto-promotes to a compaction pass to seed the catalog. Configure via the
# FS_CLUSTER_* / FS_NOMINATED_DIR env vars (see src/config.jl).
using FileServer
FileServer.cluster_sweep_cli(ARGS)

17
model/DESIGN_clustering.md
View File

@@ -1,8 +1,10 @@
# Stage-5: Unknown-format discovery by Bayesian header clustering
Status: **phase A implemented and calibrated** (`src/cluster.jl`,
`bin/cluster_calibrate.jl`, tests in `test/runtests.jl`); phase-B core scoring
implemented (`assign_file`), its live batch-process plumbing still to do. Product
Status: **phases A and B implemented and calibrated** (`src/cluster.jl` +
`src/catalog.jl`, `bin/cluster_calibrate.jl` + `bin/cluster_sweep.jl`, tests in
`test/runtests.jl`). Phase A (offline Gibbs) is calibrated; phase B's durable
single-owner catalog, incremental sweep, and nomination writer are now built on
top of the `assign_file` scoring core. Product
of a design interview; captures the decisions and — as important — the
assumptions we *rejected* so they don't get silently reintroduced. §11 records
what building it actually taught us, including three assumptions in this document
@@ -291,7 +293,14 @@ model-free gzip similarity.
a MAP-style stand-in for the VI/Binder posterior summary §5 defers — adequate
because the formats are strongly separated; revisit if compaction (§5) needs it.
- Phase B's **live single-owner batch process** (§9) and the durable catalog file
are not yet built; `assign_file` is the scoring core they will wrap.
are implemented in `src/catalog.jl` (the `Catalog` durable state, the
incremental `catalog_sweep!`, the offline `compact!` seed/recompaction, and
`write_nominations!`), driven by `bin/cluster_sweep.jl` (cron/periodic; the
first run auto-compacts to seed, subsequent runs sweep incrementally). The
catalog is persisted with the stage-2 sidecar-first temp→fsync→rename→fsync-dir
discipline. As §5B predicts, under the calibrated `bg_mass > α` the live sweep
never mints single-file clusters — new formats are discovered by the offline
`compact!` re-clustering the background residue, not by the live path.
## Open items (deferred, intentionally)

32
src/FileServer.jl
View File

@@ -10,16 +10,19 @@ using Lux
using JLD2
using Languages
include("multipart.jl") # streaming multipart reader (defines UPLOAD_CHUNK_BYTES, used by config.jl)
include("config.jl")
include("job.jl")
include("queue.jl")
include("stats.jl") # per-stage counters behind GET /stats (needs Config/Job/JobQueue)
include("spool.jl")
include("model.jl") # build_model() + read_features(); shared with bin/train.jl
include("classify.jl") # Classifier + load_classifier/classify (needs model.jl)
include("metadata.jl") # exiftool extraction + sidecar enrichment (stage 2)
include("content.jl") # binary-vs-text triage for unknown files (stage 3)
include("language.jl") # natural + programming language enrichment for text (stage 4)
include("cluster.jl") # unknown-format discovery by header clustering (stage 5)
include("cluster.jl") # unknown-format discovery by header clustering (stage 5, science)
include("catalog.jl") # durable single-owner format catalog (stage 5, phase B; needs cluster.jl + metadata.jl fsync)
include("worker.jl")
# Globals the HTTP handlers read at request time. Set once in `run`, before the
@@ -123,20 +126,37 @@ function run(; overrides...)
recovered_text = recover_dir!(cfg.text_dir, text_queue)
@info "starting file-server" host=cfg.host port=cfg.port workers=cfg.worker_count known_workers=cfg.known_worker_count unknown_workers=cfg.unknown_worker_count text_workers=cfg.text_worker_count capacity=cfg.queue_capacity known_capacity=cfg.known_queue_capacity unknown_capacity=cfg.unknown_queue_capacity text_capacity=cfg.text_queue_capacity recovered=recovered recovered_known=recovered_known recovered_unknown=recovered_unknown recovered_text=recovered_text
# Zero the counters here, not at module load: `since` should mean "serving
# since", so a scrape's totals cover the run, not the minutes spent loading
# the classifier. Nothing has been processed yet — recovery only enqueues.
reset_metrics!()
# Each pool gets its stage's counters (src/stats.jl); `worker_loop` records
# into them, `GET /stats` reads them out. Stage 1 and 3 also hand theirs to
# their handler, which charges time parked on a full downstream queue to
# `blocked_ns` so it isn't mistaken for work.
st = METRICS.stages
workers = [Threads.@spawn worker_loop(i, cfg, queue,
(job, c, wid) -> handle_classify_job(job, c, wid, known_queue, unknown_queue))
(job, c, wid) -> handle_classify_job(job, c, wid, known_queue, unknown_queue, st.classify),
st.classify)
for i in 1:cfg.worker_count]
known_workers = [Threads.@spawn worker_loop(i, cfg, known_queue, handle_known_job)
known_workers = [Threads.@spawn worker_loop(i, cfg, known_queue, handle_known_job, st.enrich)
for i in 1:cfg.known_worker_count]
unknown_workers = [Threads.@spawn worker_loop(i, cfg, unknown_queue,
(job, c, wid) -> handle_unknown_job(job, c, wid, text_queue))
(job, c, wid) -> handle_unknown_job(job, c, wid, text_queue, st.triage),
st.triage)
for i in 1:cfg.unknown_worker_count]
text_workers = [Threads.@spawn worker_loop(i, cfg, text_queue,
(job, c, wid) -> handle_text_job(job, c, wid, DETECTOR[]))
(job, c, wid) -> handle_text_job(job, c, wid, DETECTOR[]),
st.language)
for i in 1:cfg.text_worker_count]
register_routes()
serve(; host = cfg.host, port = cfg.port, async = true, show_banner = false)
# `handler` replaces Oxygen's root stream handler so POST /upload can read its
# body incrementally instead of having it buffered into memory first; every
# other route still goes through Oxygen (see `root_stream_handler`).
serve(; host = cfg.host, port = cfg.port, async = true, show_banner = false,
handler = root_stream_handler)
# Idempotent graceful drain: stop accepting uploads, let workers finish the
# buffered jobs, then exit. Called from two places:

403
src/catalog.jl Normal file
View File

@@ -0,0 +1,403 @@
# Stage-5 phase B: the live, single-owner format catalog (DESIGN §5B/§9).
#
# `cluster.jl` is the *science* — feature extraction, the collapsed Gibbs sampler
# (phase A, offline), and `assign_file` (the phase-B scoring core). This file is
# the *plumbing* that turns that core into a durable, growing catalog:
#
# * a `Catalog` = the surviving clusters' sufficient statistics + a record of
# which files have already been folded in + a few example filenames each;
# * `catalog_sweep!` = the phase-B loop — for every *new* file in `binary/`,
# run the deterministic CRP-predictive `assign_file` and fold it into the
# chosen cluster's stats (DESIGN §5B);
# * `compact!` = the offline Gibbs pass that *seeds* the catalog on first run
# and periodically re-clusters the pile (DESIGN §5, "seed the initial
# catalog" / "periodic compaction");
# * `write_nominations!` = surface promotable clusters to a human (DESIGN §6).
#
# Concurrency model is the deliberate opposite of the stateless classify workers
# (DESIGN §9): exactly ONE process owns the catalog, so there are no locks and no
# torn reads of sufficient stats. The catalog is a single durable file mutated by
# that one process; it is committed with the same sidecar-first temp→fsync→rename
# →fsync-dir discipline as the stage-2 sidecars (`commit_enriched!`), so a crash
# mid-write can neither corrupt it nor lose the rename. This file lives in the
# module (not dependency-flat like cluster.jl) because it needs JSON3 + the fsync
# helpers from metadata.jl.
"How many example filenames to retain per cluster (for the human promotion gate,
DESIGN §6). A handful is plenty to eyeball; the count/signature carry the weight."
const CATALOG_EXAMPLE_CAP = 8
"""
Catalog
The mutable phase-B state owned by the single sweep process:
* `n` — header window these clusters were built at (must match the
feature window used to score new files; frozen once seeded).
* `clusters` — id → `ClusterStats` (per-position 257-counts + member count).
Ids are **frozen at birth** — never renumbered — so there is no
label switching across sweeps (DESIGN §5).
* `examples` — id → up to `CATALOG_EXAMPLE_CAP` member filenames, for the
human nomination glance.
* `next_id` — the next fresh cluster id to hand out (monotone; retired ids are
never reused, keeping ids globally unique over the catalog's life).
* `processed` — basenames of every `binary/` file already folded in, so a sweep
is incremental: it touches only files it has not seen. This set
grows with the `binary/` pile it mirrors — the same population,
no faster — which is acceptable for v1 (DESIGN §9).
"""
mutable struct Catalog
n::Int
clusters::Dict{Int,ClusterStats}
examples::Dict{Int,Vector{String}}
next_id::Int
processed::Set{String}
end
"An empty catalog at header window `n` (no clusters seen yet)."
Catalog(n::Integer) = Catalog(Int(n), Dict{Int,ClusterStats}(),
Dict{Int,Vector{String}}(), 1, Set{String}())
"Record `name` as an example of cluster `id`, capped at `CATALOG_EXAMPLE_CAP`."
function record_example!(cat::Catalog, id::Integer, name::AbstractString)
ex = get!(cat.examples, id, String[])
length(ex) < CATALOG_EXAMPLE_CAP && push!(ex, String(name))
return nothing
end
# ---------------------------------------------------------------------------
# Durable persistence (reuse the stage-2 sidecar-first commit discipline)
# ---------------------------------------------------------------------------
# Count tables are stored sparsely — only the non-zero `(position, symbol, count)`
# triples — because a cluster's n×257 table is overwhelmingly zero (a peaked
# magic byte touches one of 257 symbols per position). Sparse keeps the catalog
# file small and its load O(non-zeros), not O(n·257·K).
function _sparse_counts(counts::Matrix{Int})
n, A = size(counts)
triples = Vector{Vector{Int}}()
@inbounds for i in 1:n, v in 1:A
c = counts[i, v]
c != 0 && push!(triples, [i, v, c])
end
return triples
end
function _dense_counts(triples, n::Integer)
counts = zeros(Int, n, ALPHABET)
for t in triples
counts[Int(t[1]), Int(t[2])] = Int(t[3])
end
return counts
end
"Serialize a `Catalog` to a plain `NamedTuple` ready for `JSON3.write`."
function catalog_payload(cat::Catalog)
clusters = [(
id = id,
members = c.members,
counts = _sparse_counts(c.counts),
examples = get(cat.examples, id, String[]),
) for (id, c) in sort(collect(cat.clusters); by=first)]
return (
n = cat.n,
next_id = cat.next_id,
clusters = clusters,
processed = sort(collect(cat.processed)),
)
end
"""
save_catalog!(path, cat)
Durably write `cat` to `path` with the sidecar-first ordering (DESIGN §9): write
to a temp name, fsync the bytes, atomically rename into place, then fsync the
containing directory so the rename itself survives power loss. A crash can leave
at most a stale `.tmp`, never a torn catalog.
"""
function save_catalog!(path::AbstractString, cat::Catalog)
dir = dirname(path)
isempty(dir) || mkpath(dir)
tmp = string(path, ".tmp")
open(tmp, "w") do io
write(io, JSON3.write(catalog_payload(cat)))
flush(io)
fsync_fd(fd(io)) # persist bytes before the rename
end
mv(tmp, path; force=true) # atomic replace
fsync_dir(isempty(dir) ? "." : dir) # persist the rename itself
return path
end
"""
load_catalog(path; n) -> Catalog
Load the durable catalog from `path`, or return a fresh empty `Catalog(n)` if it
does not exist yet (first run). `n` is the configured header window used only for
the empty case; a loaded catalog keeps its own frozen `n`.
"""
function load_catalog(path::AbstractString; n::Integer=HEADER_N)
isfile(path) || return Catalog(n)
doc = JSON3.read(read(path, String))
cn = Int(doc.n)
cat = Catalog(cn)
cat.next_id = Int(doc.next_id)
for entry in doc.clusters
id = Int(entry.id)
c = ClusterStats(_dense_counts(entry.counts, cn), Int(entry.members))
cat.clusters[id] = c
cat.examples[id] = String[String(e) for e in entry.examples]
end
for name in doc.processed
push!(cat.processed, String(name))
end
return cat
end
# ---------------------------------------------------------------------------
# Listing the input pile
# ---------------------------------------------------------------------------
"""
binary_files(dir) -> Vector{String}
Sorted absolute paths of the regular files in `dir` to be swept, skipping
`.meta.json` sidecars and any `.tmp` scratch. Sorted so a sweep's sequential
CRP-predictive assignment (which is order-dependent) is deterministic run to run.
"""
function binary_files(dir::AbstractString)
isdir(dir) || return String[]
paths = String[]
for name in readdir(dir; join=true)
isfile(name) || continue
(endswith(name, ".meta.json") || endswith(name, ".tmp")) && continue
push!(paths, name)
end
sort!(paths)
return paths
end
# ---------------------------------------------------------------------------
# Phase B: the incremental sweep (the deliverable)
# ---------------------------------------------------------------------------
"""
catalog_sweep!(cat, cfg) -> NamedTuple
Fold every *new* file in `cfg.cluster_dir` into `cat` using the deterministic
CRP-predictive rule (`assign_file`, DESIGN §5B), updating the chosen cluster's
sufficient statistics in place. Files already in `cat.processed` are skipped, so
repeated sweeps are incremental and idempotent over the pile.
Per file, `assign_file` returns the argmax component:
* an existing cluster id → the file joins it (`add!`);
* `0` (background) → counted, not clustered — a novel-but-unmatched file parks
here by design; genuinely new formats are discovered by the offline
`compact!` re-clustering the residue, not by single-file minting;
* `-1` (mint) → a fresh cluster is seeded with a frozen `next_id`. Under the
calibrated `bg_mass > α` this never fires on the live path (fresh and
background share the one-file likelihood, so background always wins) — the
branch exists for correctness, not as a routine outcome (DESIGN §5B).
Mutates `cat` but does NOT persist it — the caller commits once, after the sweep.
Returns a summary of what happened this sweep.
"""
function catalog_sweep!(cat::Catalog, cfg::Config)
n_seen = 0; n_bg = 0; n_joined = 0; n_minted = 0
for path in binary_files(cfg.cluster_dir)
base = basename(path)
base in cat.processed && continue
x = header_symbols(path; n=cat.n)
ids = sort!(collect(keys(cat.clusters)))
k = assign_file(x, cat.clusters, ids;
α=cfg.cluster_alpha, β=cfg.cluster_pseudocount,
bg_mass=cfg.cluster_bg_mass)
if k == -1
id = cat.next_id
cat.next_id += 1
c = ClusterStats(cat.n)
add!(c, x)
cat.clusters[id] = c
record_example!(cat, id, base)
n_minted += 1
elseif k == 0
n_bg += 1
else
add!(cat.clusters[k], x)
record_example!(cat, k, base)
n_joined += 1
end
push!(cat.processed, base)
n_seen += 1
end
return (; n_seen, n_joined, n_bg, n_minted,
n_clusters=length(cat.clusters), n_processed=length(cat.processed))
end
# ---------------------------------------------------------------------------
# Offline seed / compaction (wraps the phase-A Gibbs sampler)
# ---------------------------------------------------------------------------
"""
compact!(cat, cfg; sweeps, restarts, rng) -> NamedTuple
Re-cluster the *entire* `binary/` pile with the offline collapsed Gibbs sampler
and adopt the winning partition as the catalog's clusters (DESIGN §5). This is
both the **seed** on first run (an empty catalog has no clusters, so the live
sweep alone would send everything to background) and the **periodic compaction**
that merges drifted clusters / splits bloated ones later.
Ids are taken from the Gibbs partition and frozen; because compaction re-derives
the whole partition, this is a wholesale replace of `clusters`/`examples`, and
every file in the pile is marked processed. Callers run this on an explicit
schedule (e.g. `--compact`), never on the latency path.
"""
function compact!(cat::Catalog, cfg::Config;
sweeps::Integer=150, restarts::Integer=6,
rng::AbstractRNG=Random.default_rng())
paths = binary_files(cfg.cluster_dir)
if isempty(paths)
return (; n_files=0, n_clusters=length(cat.clusters), n_bg=0)
end
X = header_matrix(paths; n=cat.n)
result = gibbs_cluster(X; α=cfg.cluster_alpha, β=cfg.cluster_pseudocount,
bg_mass=cfg.cluster_bg_mass, sweeps=sweeps,
restarts=restarts, rng=rng)
empty!(cat.clusters)
empty!(cat.examples)
empty!(cat.processed)
for (id, c) in result.clusters
cat.clusters[id] = c
end
cat.next_id = (isempty(result.clusters) ? 0 : maximum(keys(result.clusters))) + 1
for (j, path) in enumerate(paths)
base = basename(path)
push!(cat.processed, base)
z = result.assignments[j]
z > 0 && record_example!(cat, z, base)
end
n_bg = count(==(0), result.assignments)
return (; n_files=length(paths), n_clusters=length(cat.clusters), n_bg)
end
# ---------------------------------------------------------------------------
# Nominations (closing the loop to the classifier — DESIGN §6)
# ---------------------------------------------------------------------------
"Render a signature (from `signature`) into a human-readable hex template:
two hex digits for a required byte, `EOF` for a required past-EOF, `??` for a
wildcard. This is what a human eyeballs at the promotion gate."
function signature_hex(sig::AbstractVector)
parts = map(sig) do s
s === nothing ? "??" :
s == PAST_EOF ? "EOF" :
string(s; base=16, pad=2)
end
return join(parts, " ")
end
"The required (non-wildcard) positions of a signature as `(position, byte)`
records; `byte` is the raw 0–255 value, or the string `\"past_eof\"`."
function signature_magic(sig::AbstractVector)
magic = Vector{NamedTuple{(:position, :byte),Tuple{Int,Any}}}()
for (i, s) in enumerate(sig)
s === nothing && continue
push!(magic, (position=i, byte=(s == PAST_EOF ? "past_eof" : s)))
end
return magic
end
"""
write_nominations!(cat, cfg) -> Vector{String}
Write one JSON nomination per promotable cluster (`is_promotable`, DESIGN §6)
into `cfg.nominated_dir`, each carrying the cluster's signature (hex template +
required magic positions), member count, and example filenames — everything a
human needs to glance and promote. The background (id 0) is never a cluster here,
so it can never be nominated, by construction.
Nominations are rewritten every sweep (membership only grows), so each file is
durably replaced via the same temp→fsync→rename→fsync-dir commit as the catalog.
Returns the paths written. Non-promotable clusters are left alone — a cluster
that *was* nominated and later fell below threshold cannot happen (members only
grow), so there is nothing to retract.
"""
function write_nominations!(cat::Catalog, cfg::Config)
mkpath(cfg.nominated_dir)
written = String[]
for (id, c) in sort(collect(cat.clusters); by=first)
sig = signature(c) # default β — signature β is
# decoupled from clustering β (DESIGN §11.3a)
is_promotable(c, sig; min_members=cfg.promote_min_members,
min_magic=cfg.promote_min_magic) || continue
payload = (
cluster_id = id,
members = c.members,
magic_length = magic_positions(sig),
signature_hex = signature_hex(sig),
magic = signature_magic(sig),
examples = get(cat.examples, id, String[]),
)
dest = joinpath(cfg.nominated_dir, "cluster-$(id).json")
tmp = string(dest, ".tmp")
open(tmp, "w") do io
write(io, JSON3.write(payload))
flush(io)
fsync_fd(fd(io))
end
mv(tmp, dest; force=true)
push!(written, dest)
end
fsync_dir(cfg.nominated_dir)
return written
end
# ---------------------------------------------------------------------------
# Orchestration + CLI (the periodic single-owner process — DESIGN §9)
# ---------------------------------------------------------------------------
"""
run_cluster_sweep(cfg; compact=false, rng) -> NamedTuple
One end-to-end pass of the single-owner stage-5 process: load the durable
catalog, either `compact!` (offline Gibbs — used to seed on first run or to
recompact) or `catalog_sweep!` (the incremental live path), then durably persist
the catalog and (re)write nominations. This is the whole job the cron/periodic
runner performs; `bin/cluster_sweep.jl` is a thin shell around it.
`compact` is forced when the catalog is empty (no clusters AND nothing processed
yet): a first live sweep against no clusters would send every file to background,
so the catalog must be seeded by an offline Gibbs pass before it can assign.
"""
function run_cluster_sweep(cfg::Config; compact::Bool=false,
rng::AbstractRNG=Random.default_rng())
cat = load_catalog(cfg.cluster_catalog_path; n=cfg.cluster_n)
if cat.n != cfg.cluster_n
@warn "configured cluster_n differs from the catalog's frozen window; using the catalog's" catalog_n=cat.n configured_n=cfg.cluster_n
end
is_empty = isempty(cat.clusters) && isempty(cat.processed)
mode = (compact || is_empty) ? :compact : :sweep
summary = mode === :compact ? compact!(cat, cfg; rng=rng) : catalog_sweep!(cat, cfg)
save_catalog!(cfg.cluster_catalog_path, cat)
nominated = write_nominations!(cat, cfg)
return (; mode, summary, n_nominated=length(nominated), nominated,
n_clusters=length(cat.clusters), n_processed=length(cat.processed))
end
"""
cluster_sweep_cli(args)
Entry point for `bin/cluster_sweep.jl`. Builds a `Config` from the environment,
runs one `run_cluster_sweep`, and logs a one-line summary. `--compact` forces the
offline Gibbs re-cluster (seed / periodic compaction) instead of the incremental
live sweep.
"""
function cluster_sweep_cli(args::AbstractVector{<:AbstractString}=String[])
compact = "--compact" in args
cfg = config_from_env()
ensure_dirs(cfg)
@info "stage-5 sweep starting" catalog=cfg.cluster_catalog_path input=cfg.cluster_dir compact=compact
r = run_cluster_sweep(cfg; compact=compact)
@info "stage-5 sweep complete" mode=r.mode clusters=r.n_clusters processed=r.n_processed nominated=r.n_nominated summary=r.summary
return r
end

26
src/config.jl
View File

@@ -31,6 +31,10 @@ Base.@kwdef struct Config
text_done_dir::String = "data/text_done" # fully enriched text files (+ .meta.json sidecars)
failed_dir::String = "data/failed" # files move here if a worker throws
model_path::String = "model/classifier.jld2" # committed classifier artifact, loaded at startup
# Intake reads each upload off the socket in chunks of this size and streams
# them straight to the spool file, so this — not the file size — is what
# bounds intake memory per in-flight upload (see src/multipart.jl).
upload_chunk_bytes::Int = UPLOAD_CHUNK_BYTES
exiftool_timeout::Int = 30 # seconds before a stuck exiftool is killed → degraded sidecar
linguist_timeout::Int = 30 # seconds before a stuck github-linguist is killed → no programming language
# Stage 5 (unknown-format discovery). A separate single-owner batch process
@@ -44,6 +48,11 @@ Base.@kwdef struct Config
cluster_bg_mass::Float64 = 5.0 # fixed mass of the uniform background 'junk drawer'
promote_min_members::Int = 20 # cluster size threshold for promotion nomination
promote_min_magic::Int = 3 # required fixed signature positions for nomination
# The stage-5 catalog is a single durable file mutated by the one sweep
# process (never a worker), and nominations are written as one file per
# promotable cluster for a human to glance at before promoting (DESIGN §9/§6).
cluster_catalog_path::String = "data/catalog.json" # durable phase-B catalog (sufficient stats + processed set)
nominated_dir::String = "data/nominated" # one JSON per self-nominated cluster, awaiting a human promote
end
"""
@@ -60,9 +69,10 @@ Recognised variables:
FS_TEXT_WORKERS, FS_TEXT_QUEUE_CAPACITY,
FS_SPOOL_DIR, FS_KNOWN_DIR, FS_UNKNOWN_DIR, FS_BINARY_DIR, FS_TEXT_DIR,
FS_DONE_DIR, FS_TEXT_DONE_DIR, FS_FAILED_DIR, FS_MODEL_PATH,
FS_EXIFTOOL_TIMEOUT, FS_LINGUIST_TIMEOUT,
FS_UPLOAD_CHUNK_BYTES, FS_EXIFTOOL_TIMEOUT, FS_LINGUIST_TIMEOUT,
FS_CLUSTER_DIR, FS_CLUSTER_N, FS_CLUSTER_ALPHA, FS_CLUSTER_PSEUDOCOUNT,
FS_CLUSTER_BG_MASS, FS_PROMOTE_MIN_MEMBERS, FS_PROMOTE_MIN_MAGIC
FS_CLUSTER_BG_MASS, FS_PROMOTE_MIN_MEMBERS, FS_PROMOTE_MIN_MAGIC,
FS_CLUSTER_CATALOG, FS_NOMINATED_DIR
"""
function config_from_env(; host=nothing, port=nothing, worker_count=nothing,
queue_capacity=nothing, known_worker_count=nothing,
@@ -71,11 +81,13 @@ function config_from_env(; host=nothing, port=nothing, worker_count=nothing,
text_queue_capacity=nothing, spool_dir=nothing,
known_dir=nothing, unknown_dir=nothing, binary_dir=nothing,
text_dir=nothing, done_dir=nothing, text_done_dir=nothing,
failed_dir=nothing, model_path=nothing, exiftool_timeout=nothing,
failed_dir=nothing, model_path=nothing,
upload_chunk_bytes=nothing, exiftool_timeout=nothing,
linguist_timeout=nothing, cluster_dir=nothing, cluster_n=nothing,
cluster_alpha=nothing, cluster_pseudocount=nothing,
cluster_bg_mass=nothing, promote_min_members=nothing,
promote_min_magic=nothing)
promote_min_magic=nothing, cluster_catalog_path=nothing,
nominated_dir=nothing)
Config(
host = something(host, get(ENV, "FS_HOST", "127.0.0.1")),
port = something(port, parse(Int, get(ENV, "FS_PORT", "8080"))),
@@ -96,6 +108,7 @@ function config_from_env(; host=nothing, port=nothing, worker_count=nothing,
text_done_dir = something(text_done_dir, get(ENV, "FS_TEXT_DONE_DIR", "data/text_done")),
failed_dir = something(failed_dir, get(ENV, "FS_FAILED_DIR", "data/failed")),
model_path = something(model_path, get(ENV, "FS_MODEL_PATH", "model/classifier.jld2")),
upload_chunk_bytes = something(upload_chunk_bytes, parse(Int, get(ENV, "FS_UPLOAD_CHUNK_BYTES", string(UPLOAD_CHUNK_BYTES)))),
exiftool_timeout = something(exiftool_timeout, parse(Int, get(ENV, "FS_EXIFTOOL_TIMEOUT", "30"))),
linguist_timeout = something(linguist_timeout, parse(Int, get(ENV, "FS_LINGUIST_TIMEOUT", "30"))),
cluster_dir = something(cluster_dir, get(ENV, "FS_CLUSTER_DIR", "data/binary")),
@@ -105,13 +118,16 @@ function config_from_env(; host=nothing, port=nothing, worker_count=nothing,
cluster_bg_mass = something(cluster_bg_mass, parse(Float64, get(ENV, "FS_CLUSTER_BG_MASS", "5.0"))),
promote_min_members = something(promote_min_members, parse(Int, get(ENV, "FS_PROMOTE_MIN_MEMBERS", "20"))),
promote_min_magic = something(promote_min_magic, parse(Int, get(ENV, "FS_PROMOTE_MIN_MAGIC", "3"))),
cluster_catalog_path = something(cluster_catalog_path, get(ENV, "FS_CLUSTER_CATALOG", "data/catalog.json")),
nominated_dir = something(nominated_dir, get(ENV, "FS_NOMINATED_DIR", "data/nominated")),
)
end
"Create all the pipeline-stage directories if they don't already exist."
function ensure_dirs(cfg::Config)
for d in (cfg.spool_dir, cfg.known_dir, cfg.unknown_dir, cfg.binary_dir,
cfg.text_dir, cfg.done_dir, cfg.text_done_dir, cfg.failed_dir)
cfg.text_dir, cfg.done_dir, cfg.text_done_dir, cfg.failed_dir,
cfg.nominated_dir)
mkpath(d)
end
return nothing

74
src/metadata.jl
View File

@@ -67,6 +67,19 @@ function coalesce_tag(bytag::Dict{String,Any}, tags)
return nothing
end
"How long a child gets to honor SIGTERM before `run_with_timeout` escalates to SIGKILL."
const KILL_GRACE_SECONDS = 2.0
"""
Send `signum` to the whole process group `pgid` (a negative pid means "the group"
to `kill(2)`). Julia's `kill(::Process, sig)` signals only the child itself,
which is not enough to enforce a timeout — see `run_with_timeout`.
"""
function signal_group(pgid::Integer, signum::Integer)
ccall(:kill, Cint, (Cint, Cint), -pgid, signum)
return nothing
end
"""
run_with_timeout(cmd, timeout) -> Union{Vector{UInt8},Nothing}
@@ -75,33 +88,56 @@ Run `cmd`, capturing stdout, and return the captured bytes on clean exit, or
SIGKILL after a grace period) once it overruns `timeout` seconds, so one
pathological input can't wedge a worker forever. Shared by the exiftool (stage 2)
and github-linguist (stage 4) shells.
The child runs in its own process group and the timeout signals the *group*, not
just the child. This is what makes the timeout enforceable: `wait` below returns
only once the captured stdout pipe closes, and any grandchild inherits that pipe,
so signalling the child alone leaves a `sh -c "...; sleep 30"`-shaped process
tree running to completion with the worker still blocked on it. The cost of the
process group is that a hard crash of the server orphans an in-flight child
rather than taking it down; these children are short-lived and timeout-bounded,
which is the cheaper side of that trade.
"""
function run_with_timeout(cmd::Cmd, timeout::Integer)
out = IOBuffer()
proc = Base.run(pipeline(cmd; stdout=out, stderr=devnull); wait=false)
# `detach` puts the child in a fresh process group (it becomes the group
# leader, so the group id is its pid); see the docstring for why the group,
# and not the child, is what the timeout has to signal.
proc = Base.run(pipeline(detach(cmd); stdout=out, stderr=devnull); wait=false)
pgid = Base.getpid(proc)
# Kill the process if it overruns the timeout. `t` polls rather than blocking
# so we can `kill` a hung child; the poll interval bounds shutdown latency.
# A one-shot timer, cancelled the moment the child exits, rather than a
# polling loop the caller has to join. The polling version charged every
# call the remainder of its in-flight `sleep(0.1)` *after* the child had
# already exited — ~50 ms on average, and a measured 101 ms on a process
# that exits instantly. That is pure latency on the hot path of two stages
# (exiftool here, github-linguist in stage 4), and it dwarfed the work on
# anything but a slow file. Waiting on the process directly costs nothing
# when the child exits normally, which is the overwhelmingly common case.
killed = Ref(false)
t = Threads.@spawn begin
waited = 0.0
while process_running(proc) && waited < timeout
sleep(0.1); waited += 0.1
end
if process_running(proc)
killed[] = true
kill(proc, Base.SIGTERM)
# Escalate: a process that ignores/defers SIGTERM would otherwise pin
# the worker forever on the wait(proc) below, defeating the timeout.
grace = 0.0
while process_running(proc) && grace < 2.0
sleep(0.1); grace += 0.1
timer = Timer(timeout) do _
process_running(proc) || return
killed[] = true
signal_group(pgid, Base.SIGTERM)
# Escalate: a process that ignores/defers SIGTERM would otherwise pin the
# worker forever on the wait(proc) below, defeating the timeout. This
# runs off the timer's task so the event loop isn't held during the
# grace period, and it is not joined — by the time it wakes, `wait(proc)`
# has long since returned and `process_running` settles it.
Threads.@spawn begin
deadline = time() + KILL_GRACE_SECONDS
while process_running(proc) && time() < deadline
sleep(0.05)
end
process_running(proc) && kill(proc, Base.SIGKILL)
process_running(proc) && signal_group(pgid, Base.SIGKILL)
end
end
wait(proc)
wait(t)
try
wait(proc)
finally
close(timer) # cancel the pending kill; a no-op if it already fired
end
(killed[] || !success(proc)) && return nothing
return take!(out)

296
src/multipart.jl Normal file
View File

@@ -0,0 +1,296 @@
# Streaming multipart/form-data reader.
#
# Why this exists: HTTP.jl's `parse_multipart_form` takes the *complete* request
# body as a byte vector, so using it means every file in the request sits in
# memory at once — and is then copied again per part. That contradicts the whole
# point of this service: file bytes belong on disk, and only a small reference
# travels through the queue. So intake needs a parser that never holds a file.
#
# This reader walks the body incrementally: it pulls fixed-size chunks off the
# socket and hands each part's bytes straight to a sink (the spool file). Peak
# memory per connection is `chunk_bytes` + the boundary length, regardless of how
# large — or how many — the uploaded files are.
#
# Interface: two calls in a loop, so the caller keeps ordinary control flow
# rather than inverting into callbacks.
#
# r = MultipartReader(io, boundary)
# while (part = next_part!(r)) !== nothing
# part.filename === nothing ? skip_part_body!(r) : write_part_body!(sink, r)
# end
#
# The grammar it implements (RFC 2046 §5.1, RFC 7578):
#
# [preamble] "--" boundary CRLF
# part-headers CRLF CRLF part-body
# CRLF "--" boundary CRLF ... another part ...
# CRLF "--" boundary "--" CRLF ... end of form, [epilogue]
#
# So the delimiter that *closes* a body is CRLF + "--" + boundary, and the two
# bytes after it say whether another part follows (CRLF) or the form is over
# ("--"). Every read is bounded, and the buffer retains only the last
# `length(delimiter)-1` bytes when no delimiter is found — that tail is what
# makes a delimiter split across two chunks parse correctly.
"Default socket read size, and therefore the memory bound per in-flight upload."
const UPLOAD_CHUNK_BYTES = 64 * 1024
"""
A part header block bigger than this is abuse, not a filename. Bounding it keeps
the one genuinely unbounded-looking read (headers, which must be buffered whole
to be parsed) from being a memory hole.
"""
const MAX_PART_HEADER_BYTES = 16 * 1024
const CRLF = UInt8[0x0d, 0x0a]
const CRLFCRLF = UInt8[0x0d, 0x0a, 0x0d, 0x0a]
const DASHDASH = UInt8[0x2d, 0x2d]
"A malformed (or truncated) multipart body. Callers turn this into a 400."
struct MultipartError <: Exception
msg::String
end
Base.showerror(io::IO, e::MultipartError) = print(io, "MultipartError: ", e.msg)
"What a part's headers said about it. `filename === nothing` means a plain form field, not a file."
struct MultipartPart
name::Union{String,Nothing}
filename::Union{String,Nothing}
content_type::Union{String,Nothing}
end
"""
MultipartReader(io, boundary; chunk_bytes = UPLOAD_CHUNK_BYTES)
An incremental reader over the multipart body arriving on `io`. `boundary` is the
value from the request's `Content-Type` header (see [`multipart_boundary`](@ref)).
"""
mutable struct MultipartReader{I<:IO}
io::I
dash_boundary::Vector{UInt8} # "--" boundary: opens the first part
delimiter::Vector{UInt8} # CRLF "--" boundary: closes every part
buf::Vector{UInt8} # rolling window; bounded by chunk_bytes + delimiter
pos::Int # next unconsumed index in buf
scratch::Vector{UInt8} # reused socket read target, so chunks don't churn the GC
chunk_bytes::Int
state::Symbol # :preamble | :at_delimiter | :body | :done
end
function MultipartReader(io::IO, boundary::AbstractString;
chunk_bytes::Int = UPLOAD_CHUNK_BYTES)
chunk_bytes > 0 || throw(ArgumentError("chunk_bytes must be positive"))
isempty(boundary) && throw(MultipartError("empty multipart boundary"))
dash_boundary = Vector{UInt8}(codeunits(string("--", boundary)))
return MultipartReader(io, dash_boundary, vcat(CRLF, dash_boundary),
UInt8[], 1, Vector{UInt8}(undef, chunk_bytes),
chunk_bytes, :preamble)
end
"""
multipart_boundary(content_type) -> String | nothing
Pull the boundary out of a `multipart/form-data` Content-Type header. Returns
`nothing` if the header is missing, is some other media type, or has no boundary
— all of which are the same 400 to a caller.
"""
function multipart_boundary(content_type::Union{AbstractString,Nothing})
content_type === nothing && return nothing
occursin(r"^\s*multipart/form-data"i, content_type) || return nothing
m = match(r"(?i:\bboundary)=(?:\"([^\"]+)\"|([^\s;]+))", content_type)
m === nothing && return nothing
return String(something(m[1], m[2]))
end
# ------------------------------------------------------------------ buffer plumbing
"Unconsumed bytes currently buffered."
navail(r::MultipartReader) = length(r.buf) - r.pos + 1
"Drop already-consumed bytes so the buffer stays bounded across a long body."
function compact!(r::MultipartReader)
r.pos == 1 && return nothing
n = navail(r)
n > 0 && copyto!(r.buf, 1, r.buf, r.pos, n)
resize!(r.buf, max(n, 0))
r.pos = 1
return nothing
end
"""
Pull one more chunk off the wire, returning `false` at end of body.
`readbytes!` on an `HTTP.Stream` returns at most what remains of the current
content-length or chunk, so this is bounded by `chunk_bytes`; `eof` is what
advances a chunked-encoded body to its next chunk, hence the guard.
"""
function fill_more!(r::MultipartReader)
eof(r.io) && return false
n = readbytes!(r.io, r.scratch, r.chunk_bytes)
n == 0 && return false
append!(r.buf, view(r.scratch, 1:n))
return true
end
"Buffer until `needle` is found, returning its range, or `nothing` at end of body."
function seek_needle!(r::MultipartReader, needle::Vector{UInt8}; limit::Int = 0)
while true
idx = findnext(needle, r.buf, r.pos)
idx === nothing || return idx
# Only the last length(needle)-1 bytes can still be part of a match, but
# the caller may need the skipped bytes (a part body), so trimming is the
# caller's job — we only enforce the optional limit.
limit > 0 && navail(r) > limit &&
throw(MultipartError("no delimiter within $limit bytes"))
compact!(r)
fill_more!(r) || return nothing
end
end
"Ensure at least `n` bytes are buffered; `false` if the body ended first."
function ensure!(r::MultipartReader, n::Int)
while navail(r) < n
compact!(r)
fill_more!(r) || return false
end
return true
end
# Write `r.buf[range]` to `sink`. Goes through `unsafe_write` because
# `write(io, ::SubArray{UInt8})` falls back to a byte-at-a-time loop in Base,
# which would dominate the cost of a large upload.
function emit!(sink::IO, r::MultipartReader, from::Int, to::Int)
n = to - from + 1
n <= 0 && return 0
buf = r.buf # GC.@preserve needs a plain symbol, not a field access
GC.@preserve buf unsafe_write(sink, pointer(buf, from), UInt(n))
return n
end
# ------------------------------------------------------------------- parts
"""
next_part!(r) -> MultipartPart | nothing
Advance to the next part and return its headers, or `nothing` at the end of the
form. The previous part's body must have been consumed first (with
[`write_part_body!`](@ref) or [`skip_part_body!`](@ref)) — the reader cannot skip
a body it hasn't been told to, because the body is only bounded by finding the
next delimiter.
"""
function next_part!(r::MultipartReader)
r.state === :done && return nothing
r.state === :body &&
throw(MultipartError("the current part's body must be consumed before the next part"))
if r.state === :preamble
# Discard the preamble (RFC says ignore it) and consume the opening
# delimiter. Bounded: real clients send no preamble at all, and an
# unbounded scan here would be a way to make us buffer a whole body.
idx = seek_needle!(r, r.dash_boundary; limit = MAX_PART_HEADER_BYTES)
idx === nothing && throw(MultipartError("no multipart boundary found in body"))
r.pos = last(idx) + 1
r.state = :at_delimiter
end
# Just after a delimiter: "--" ends the form, CRLF introduces another part.
ensure!(r, 2) || throw(MultipartError("truncated body after a boundary delimiter"))
if view(r.buf, r.pos:r.pos+1) == DASHDASH
r.pos += 2
r.state = :done
return nothing
end
skip_linear_whitespace!(r)
ensure!(r, 2) || throw(MultipartError("truncated body after a boundary delimiter"))
view(r.buf, r.pos:r.pos+1) == CRLF ||
throw(MultipartError("boundary delimiter is not followed by a line ending"))
r.pos += 2
part = read_part_headers!(r)
r.state = :body
return part
end
"RFC 2046 allows spaces/tabs between the delimiter and its line ending."
function skip_linear_whitespace!(r::MultipartReader)
while ensure!(r, 1) && (r.buf[r.pos] == 0x20 || r.buf[r.pos] == 0x09)
r.pos += 1
end
return nothing
end
function read_part_headers!(r::MultipartReader)
# A part with no headers at all is `CRLF CRLF body`: the empty line comes
# immediately, so searching for CRLFCRLF would run past it into the body.
if ensure!(r, 2) && view(r.buf, r.pos:r.pos+1) == CRLF
r.pos += 2
return MultipartPart(nothing, nothing, nothing)
end
# The `limit` here bounds *buffering* — it only fires when the headers span
# chunks. The explicit length check below is the actual policy, so the rule
# doesn't depend on how the body happened to be chunked on the wire.
idx = seek_needle!(r, CRLFCRLF; limit = MAX_PART_HEADER_BYTES)
idx === nothing && throw(MultipartError("truncated body inside a part's headers"))
first(idx) - r.pos > MAX_PART_HEADER_BYTES &&
throw(MultipartError("part headers exceed $MAX_PART_HEADER_BYTES bytes"))
# Copying is fine: the check above bounds this block.
block = String(r.buf[r.pos:first(idx)-1])
r.pos = last(idx) + 1
return parse_part_headers(block)
end
"Unescape the backslash escapes RFC 2045 allows inside a quoted-string."
unquote(s::AbstractString) = replace(s, r"\\(.)" => s"\1")
function parse_part_headers(block::AbstractString)
name = filename = content_type = nothing
for line in eachsplit(block, "\r\n")
colon = findfirst(':', line)
colon === nothing && continue
key = lowercase(strip(line[1:colon-1]))
value = strip(line[colon+1:end])
if key == "content-disposition"
# `\b` matters: it keeps the `name=` pattern from matching inside `filename=`.
m = match(r"(?i:\bname)=(?:\"((?:[^\"\\]|\\.)*)\"|([^\s;]+))", value)
m === nothing || (name = unquote(String(something(m[1], m[2]))))
m = match(r"(?i:\bfilename)=(?:\"((?:[^\"\\]|\\.)*)\"|([^\s;]+))", value)
m === nothing || (filename = unquote(String(something(m[1], m[2]))))
elseif key == "content-type"
content_type = String(value)
end
end
return MultipartPart(name, filename, content_type)
end
"""
write_part_body!(sink, r) -> Int
Stream the current part's body into `sink`, returning the number of bytes
written. Nothing larger than a chunk is ever held in memory.
"""
function write_part_body!(sink::IO, r::MultipartReader)
r.state === :body || throw(MultipartError("no part body is open"))
total = 0
keep = length(r.delimiter) - 1 # a delimiter may straddle two chunks
while true
idx = findnext(r.delimiter, r.buf, r.pos)
if idx !== nothing
total += emit!(sink, r, r.pos, first(idx) - 1)
r.pos = last(idx) + 1
r.state = :at_delimiter
return total
end
# Emit only what cannot be the start of a straddling delimiter, then
# keep that tail and read more.
emit_to = length(r.buf) - keep
if emit_to >= r.pos
total += emit!(sink, r, r.pos, emit_to)
r.pos = emit_to + 1
end
compact!(r)
fill_more!(r) || throw(MultipartError("truncated body inside a part"))
end
end
"Consume and discard the current part's body (a form field, or a file we can't take)."
skip_part_body!(r::MultipartReader) = write_part_body!(devnull, r)

10
src/queue.jl
View File

@@ -81,6 +81,16 @@ function close!(q::ChannelQueue)
return nothing
end
"""
capacity(q) -> Int
How many jobs the queue can hold before `enqueue!` starts refusing. Part of the
introspection seam alongside `length`: `/stats` reports depth against capacity,
because a depth of 900 means nothing without knowing whether the limit is 1000
or 1_000_000.
"""
capacity(q::ChannelQueue) = q.capacity
"Number of jobs currently buffered (for logging/introspection)."
function Base.length(q::ChannelQueue)
lock(q.cond)

255
src/server.jl
View File

@@ -1,13 +1,21 @@
# HTTP layer: a single multipart upload endpoint plus a health check.
#
# The handler's whole job is to get files onto the queue fast and get out of the
# way: spool each uploaded file to disk, enqueue a reference, respond 202. It
# way: stream each uploaded file to disk, enqueue a reference, respond 202. It
# never does real processing — that's the workers' job.
#
# Intake is *streamed*, not buffered (see src/multipart.jl for the reader). This
# is what makes the service's memory story hold end to end: bytes go from the
# socket to the spool file a chunk at a time, so a 4 GB upload costs the same
# resident memory as a 4 KB one. It is also why /upload is served by its own
# stream handler rather than an Oxygen route — see `root_stream_handler`.
#
# NOTE: routes are registered at runtime via `register_routes()` (called from
# `run`), NOT with top-level macros. In a precompiled package, top-level
# `@get`/`@post` would execute during precompilation and be lost before serving.
const UPLOAD_PATH = "/upload"
jsonresp(status::Int, data) =
HTTP.Response(status, ["Content-Type" => "application/json"], JSON3.write(data))
@@ -15,48 +23,215 @@ function health_handler(_::HTTP.Request)
return jsonresp(200, (; status = "ok"))
end
function upload_handler(req::HTTP.Request)
cfg = CONFIG[]
queue = QUEUE[]
"""
`GET /stats` — the pipeline's own counters (src/stats.jl), as JSON.
parts = try
HTTP.parse_multipart_form(req)
catch
nothing
end
parts === nothing &&
return jsonresp(400, (; error = "expected multipart/form-data"))
Read-only and cheap: a few atomic loads and one `length` per queue, no pipeline
state touched. Two scrapes Δt apart give per-stage throughput and utilization —
see bin/bench.jl, which is the intended consumer.
files = filter(p -> p.filename !== nothing && !isempty(p.filename), parts)
isempty(files) &&
return jsonresp(400, (; error = "no files found in request"))
accepted = NamedTuple{(:id, :name),Tuple{String,String}}[]
for p in files
bytes = read(p.data)
job = try
spool_file(cfg, p.filename, bytes)
catch e
@error "spool failed" name=p.filename exception=(e, catch_backtrace())
return jsonresp(500, (; error = "failed to store file", accepted))
end
if !enqueue!(queue, job)
rm(job.path; force = true) # never queued → don't leave it in spool
return jsonresp(503, (; error = "queue full, retry later", accepted))
end
@info "accepted" id=job.id name=job.original_name size=job.size
push!(accepted, (; id = job.id, name = job.original_name))
end
return jsonresp(202, (; accepted))
Unlike `/upload` this is an ordinary Oxygen route: it has no body to stream, and
being in Oxygen's middleware chain is a feature here.
"""
function stats_handler(_::HTTP.Request)
queues = (classify = QUEUE[], enrich = KNOWN_QUEUE[],
triage = UNKNOWN_QUEUE[], language = TEXT_QUEUE[])
return jsonresp(200, stats_snapshot(CONFIG[], queues))
end
"Register HTTP routes on the Oxygen instance. Must run at runtime, before serve."
function register_routes()
@get("/health", health_handler)
@post("/upload", upload_handler)
"Write a JSON response onto a raw stream (the streaming handler's `jsonresp`)."
function stream_jsonresp(stream::HTTP.Stream, status::Int, data)
body = JSON3.write(data)
HTTP.setstatus(stream, status)
HTTP.setheader(stream, "Content-Type" => "application/json")
HTTP.setheader(stream, "Content-Length" => string(sizeof(body)))
HTTP.startwrite(stream)
write(stream, body)
return nothing
end
"""
Read and discard whatever is left of the request body.
HTTP.jl's server calls `closeread` after the handler and *errors* if the body was
only partly consumed — a half-read body can't be followed by another request on a
keep-alive connection. So every exit path drains first. Discarding is bounded in
memory (one chunk) and costs nothing in the normal case, where the body is
already fully consumed and this returns immediately.
"""
function discard_body!(stream::HTTP.Stream, chunk_bytes::Int)
scratch = Vector{UInt8}(undef, chunk_bytes)
while !eof(stream)
readbytes!(stream, scratch, chunk_bytes) == 0 && break
end
return nothing
end
"""
Did this exception mean the client went away, rather than something being wrong
on our side?
A client that hangs up mid-upload (user cancels, network drops) is routine, and
must not be logged as a server error or reported as a failed write — but it looks
like an I/O failure from inside the parser, so the distinction has to be made
explicitly. `EOFError` is what `HTTP.Stream` raises when a connection dies with
bytes still promised by `Content-Length`.
"""
is_client_gone(e) =
e isa EOFError ||
(e isa Base.IOError && e.code in (Base.UV_EPIPE, Base.UV_ECONNRESET, Base.UV_ECONNABORTED))
"""
Stream a multipart upload to disk, one part at a time.
Each file part is spooled straight from the socket and its reference enqueued.
The response reports what was actually queued:
* `202` — every file in the request was spooled and queued
* `400` — not multipart/form-data, no files present, or a malformed body
* `503` — the intake queue filled up; `accepted` lists what got in first
* `500` — a file could not be written to disk
Unlike a buffered handler, this one cannot know up front how many files a request
holds or whether they will fit. So when the queue fills mid-request it does not
abandon the connection: it stops spooling (discarding the remaining parts rather
than writing files it can't queue), drains the body, and answers `503` with the
`accepted` list. Files already queued stay queued — a client can retry the rest.
"""
function upload_stream_handler(stream::HTTP.Stream)
try
return serve_upload!(stream)
catch e
# The client vanished — while we were reading its body, draining it, or
# answering. Nothing is wrong on our side, so log it as the routine event
# it is instead of a server error.
is_client_gone(e) || rethrow()
@info "upload aborted by client"
# HTTP.jl insists a handler write *some* response before returning. The
# client is probably already gone, so this write is best-effort: attempt
# it only if we haven't started a response, and let it fail silently.
if isopen(stream) && !iswritable(stream)
try
stream_jsonresp(stream, 400, (; error = "upload truncated"))
catch e2
is_client_gone(e2) || rethrow()
end
end
return nothing
end
end
function serve_upload!(stream::HTTP.Stream)
Threads.atomic_add!(METRICS.intake.requests, 1)
cfg = CONFIG[]
queue = QUEUE[]
chunk = cfg.upload_chunk_bytes
boundary = multipart_boundary(HTTP.header(stream.message, "Content-Type", nothing))
if boundary === nothing
discard_body!(stream, chunk)
return stream_jsonresp(stream, 400, (; error = "expected multipart/form-data"))
end
reader = MultipartReader(stream, boundary; chunk_bytes = chunk)
accepted = NamedTuple{(:id, :name),Tuple{String,String}}[]
n_files = 0
queue_full = false
failure = nothing # (status, message) from a fatal error mid-body
try
while (part = next_part!(reader)) !== nothing
# A part with no filename is an ordinary form field, not a file.
if part.filename === nothing || isempty(part.filename)
skip_part_body!(reader)
continue
end
n_files += 1
# Already backpressured: consume the part, but don't write a file we
# know we cannot enqueue.
if queue_full
Threads.atomic_add!(METRICS.intake.rejected, 1)
skip_part_body!(reader)
continue
end
job = try
spool_stream(cfg, part.filename) do io
write_part_body!(io, reader)
end
catch e
(e isa MultipartError || is_client_gone(e)) && rethrow()
# A disk error leaves the reader mid-part, so the rest of the body
# can no longer be parsed — stop and report.
@error "spool failed" name=part.filename exception=(e, catch_backtrace())
failure = (500, "failed to store file")
break
end
if enqueue!(queue, job)
@info "accepted" id=job.id name=job.original_name size=job.size
push!(accepted, (; id = job.id, name = job.original_name))
# Counted at the point the job becomes stage 1's problem, so
# intake totals and stage-1 arrivals refer to the same files.
Threads.atomic_add!(METRICS.intake.files, 1)
Threads.atomic_add!(METRICS.intake.bytes, job.size)
else
rm(job.path; force = true) # never queued → don't leave it in spool
Threads.atomic_add!(METRICS.intake.rejected, 1)
queue_full = true
end
end
catch e
e isa MultipartError || rethrow()
@warn "malformed multipart upload" reason=e.msg accepted=length(accepted)
failure = (400, "malformed multipart body")
end
discard_body!(stream, chunk)
failure !== nothing &&
return stream_jsonresp(stream, failure[1], (; error = failure[2], accepted))
n_files == 0 &&
return stream_jsonresp(stream, 400, (; error = "no files found in request"))
queue_full &&
return stream_jsonresp(stream, 503, (; error = "queue full, retry later", accepted))
return stream_jsonresp(stream, 202, (; accepted))
end
"""
root_stream_handler(middleware) -> (stream -> nothing)
Oxygen's root handler wraps `HTTP.streamhandler`, which does
`request.body = read(stream)` — the entire body into memory — *before* any route
is dispatched. That happens even for an Oxygen `@stream` route, so no route can
stream an upload. We therefore intercept `POST /upload` at the stream level and
hand everything else to Oxygen unchanged.
Trade-off: `/upload` bypasses Oxygen's middleware chain, so it is absent from
Oxygen's built-in metrics and docs. Deliberate — flat intake memory is the point
of this service, and intake is covered by our own counters (`/stats`) and `@info`
records anyway.
"""
function root_stream_handler(middleware::Function)
oxygen_handler = Oxygen.Core.stream_handler(middleware)
return function (stream::HTTP.Stream)
req = stream.message
if req.method == "POST" && HTTP.URI(req.target).path == UPLOAD_PATH
return upload_stream_handler(stream)
end
return oxygen_handler(stream)
end
end
"""
Register HTTP routes on the Oxygen instance. Must run at runtime, before serve.
`POST /upload` is deliberately absent: it is served by `upload_stream_handler`
via `root_stream_handler`, ahead of Oxygen's router.
"""
function register_routes()
@get("/health", health_handler)
@get("/stats", stats_handler)
return nothing
end

34
src/spool.jl
View File

@@ -19,15 +19,33 @@ function sanitize_filename(name::AbstractString)::String
return first(base, MAX_NAME_LEN)
end
"Write `bytes` to the spool dir under `<uuid>-<sanitized>` and return the Job."
function spool_file(cfg::Config, original_name::AbstractString, bytes::Vector{UInt8})::Job
id = string(uuid4())
safe = sanitize_filename(original_name)
path = joinpath(cfg.spool_dir, string(id, "-", safe))
open(path, "w") do io
write(io, bytes)
"Build the spool path for a client-supplied name: `<uuid>-<sanitized>`."
function spool_path(cfg::Config, original_name::AbstractString)
id = string(uuid4())
return id, joinpath(cfg.spool_dir, string(id, "-", sanitize_filename(original_name)))
end
"""
spool_stream(write_body!, cfg, original_name) -> Job
Create the spool file for `original_name`, hand the open `IO` to `write_body!`,
and build the `Job` from however many bytes it reports writing.
This is the streaming counterpart to `spool_file`: the caller pumps bytes in from
the network as they arrive, so a file never exists in memory in one piece. A
partial file left by a failed or abandoned write is removed — intake either
produces a complete spooled file or nothing at all, so recovery on restart never
picks up a truncated upload.
"""
function spool_stream(write_body!, cfg::Config, original_name::AbstractString)::Job
id, path = spool_path(cfg, original_name)
nbytes = try
open(write_body!, path, "w")
catch
rm(path; force = true)
rethrow()
end
return Job(id, String(original_name), path, length(bytes), time())
return Job(id, String(original_name), path, nbytes, time())
end
"Move a spooled file into `dir` (done/ or failed/), returning the destination."

211
src/stats.jl Normal file
View File

@@ -0,0 +1,211 @@
# Per-stage pipeline metrics.
#
# End-to-end throughput says how fast the pipeline is; it does not say which
# stage is the reason. The external harness can't answer that either: `known/`,
# `unknown/` and `text/` are *transient* — a file can pass through one between
# two directory polls — so sampling directories from outside undercounts exactly
# the stages we most want to measure. Only the pipeline itself sees every job.
#
# So each stage keeps four counters, all incremented in `worker_loop` (the one
# place every stage's work passes through) and read by `GET /stats`:
#
# completed / failed jobs finished, jobs quarantined → throughput
# bytes job bytes processed → per-stage MiB/s
# busy_ns summed handler wall time → service time
# blocked_ns of that, time parked on a full downstream queue
# in_flight handlers running right now → saturation
#
# Rates fall out of a pair of scrapes taken Δt apart:
#
# throughput = Δcompleted / Δt
# utilization = (Δbusy_ns - Δblocked_ns) / (Δt * workers) ~1.0 ⇒ bottleneck
#
# Utilization is the useful one. Throughput alone can't distinguish a stage that
# is saturated from one that is merely starved by the stage ahead of it — both
# show the same files/s — whereas utilization separates them: the saturated stage
# sits near 1.0 with its queue backing up, the starved stage sits near 0.
#
# `blocked_ns` is what keeps that true downstream. Stages 1 and 3 apply blocking
# backpressure: when the next queue is full the handler parks and retries rather
# than dropping the file (see ROUTE_ENQUEUE_RETRY_SECONDS). That parked time is
# inside the handler, so counting it as busy would show stage 1 pinned at 1.0
# whenever stage 2 is the real bottleneck — every stage upstream of the jam would
# look like the jam. Subtracting it leaves utilization meaning "doing its own
# work", and the blocked share becomes its own signal: a stage blocked 90% of the
# time is naming its successor as the bottleneck.
#
# Everything here is monotonic since process start (or since `reset_metrics!`),
# in the Prometheus style: counters, never rates. Rates are the reader's job, so
# a scrape is stateless and two readers can't disturb each other.
#
# Cost is a handful of atomic adds per file, against handlers that spawn
# exiftool — unmeasurable in practice, and the counters are never read on the
# hot path.
# Stage identity lives here, in declaration order, so the report, the JSON and
# the worker wiring can't drift apart: adding stage 5 to the live path means
# adding it here and passing the new `StageStats` to its `worker_loop`.
const STAGE_KEYS = (:classify, :enrich, :triage, :language)
const STAGE_TITLES = (classify = "classify", enrich = "enrich",
triage = "triage", language = "language")
"""
Counters for one pipeline stage. All fields are atomic and monotonic: workers
only ever add, readers only ever read, so no lock is needed between them.
`in_flight` is the exception to monotonic — it goes up and down — and is the one
counter that is a *level* rather than a total.
"""
struct StageStats
completed::Threads.Atomic{Int}
failed::Threads.Atomic{Int}
bytes::Threads.Atomic{Int}
busy_ns::Threads.Atomic{Int}
blocked_ns::Threads.Atomic{Int}
in_flight::Threads.Atomic{Int}
end
StageStats() = StageStats(Threads.Atomic{Int}(0), Threads.Atomic{Int}(0),
Threads.Atomic{Int}(0), Threads.Atomic{Int}(0),
Threads.Atomic{Int}(0), Threads.Atomic{Int}(0))
"""
Counters for HTTP intake, which has no worker loop to hang them off.
`files` counts what was actually spooled *and* queued — the same thing the 202
body reports as `accepted` — so it lines up with stage 1's arrivals. Files
dropped because the queue was full are counted separately in `rejected`, since a
run where intake outruns the pipeline should be visible as backpressure rather
than as slow intake.
"""
struct IntakeStats
requests::Threads.Atomic{Int}
files::Threads.Atomic{Int}
bytes::Threads.Atomic{Int}
rejected::Threads.Atomic{Int}
end
IntakeStats() = IntakeStats(Threads.Atomic{Int}(0), Threads.Atomic{Int}(0),
Threads.Atomic{Int}(0), Threads.Atomic{Int}(0))
"""
Every counter in the process, plus the wall-clock origin the totals are measured
from.
`since` matters to a reader computing rates from a single scrape: without it,
"1000 files completed" has no denominator. Readers that scrape twice should use
their own Δt instead — it excludes the time before they started watching.
"""
struct Metrics
intake::IntakeStats
stages::NamedTuple{STAGE_KEYS,NTuple{4,StageStats}}
since::Base.RefValue{Float64}
end
Metrics() = Metrics(IntakeStats(),
NamedTuple{STAGE_KEYS}(ntuple(_ -> StageStats(), 4)),
Ref(time()))
# Process-global, like the logger: workers on every thread add to it and the
# HTTP layer reads it, with no way to thread a handle through both paths that
# wouldn't just be this by another name.
const METRICS = Metrics()
"""
reset_metrics!()
Zero every counter and restart the measurement window. For tests, and for a
benchmark that wants totals covering only its own run — though a harness that
scrapes before and after can subtract instead, which is safer against a server
that is also serving someone else.
"""
function reset_metrics!(m::Metrics = METRICS)
for a in (m.intake.requests, m.intake.files, m.intake.bytes, m.intake.rejected)
a[] = 0
end
for s in m.stages
s.completed[] = 0
s.failed[] = 0
s.bytes[] = 0
s.busy_ns[] = 0
s.blocked_ns[] = 0
s.in_flight[] = 0
end
m.since[] = time()
return nothing
end
"Record one finished job: `ok` distinguishes a completion from a quarantine."
function record_job!(s::StageStats, ok::Bool, bytes::Int, elapsed_ns::Int)
Threads.atomic_add!(ok ? s.completed : s.failed, 1)
Threads.atomic_add!(s.bytes, bytes)
Threads.atomic_add!(s.busy_ns, elapsed_ns)
return nothing
end
"""
enqueue_blocking!(queue, job, stats; retry_seconds) -> nothing
Hand `job` to a downstream queue, parking and retrying until it fits, and charge
the parked time to `stats.blocked_ns`.
This is the routing half of stages 1 and 3: a classified file is never dropped,
so a full downstream queue means waiting, not failing. Wrapping the retry loop
here — rather than repeating `while !enqueue! sleep end` at each call site — is
what makes that wait measurable at all, and keeps the three routing paths from
drifting into three different backoff behaviours.
"""
function enqueue_blocking!(queue::JobQueue, job::Job, stats::StageStats;
retry_seconds::Real)
enqueue!(queue, job) && return nothing
t0 = time_ns()
while !enqueue!(queue, job)
sleep(retry_seconds)
end
Threads.atomic_add!(stats.blocked_ns, Int(time_ns() - t0))
return nothing
end
# --- snapshot ---------------------------------------------------------------
"""
stats_snapshot(cfg, queues, m = METRICS) -> NamedTuple
Read every counter into a plain value tree for `GET /stats`.
`queues` is a NamedTuple of `JobQueue`s keyed by `STAGE_KEYS`, supplying each
stage's live depth and capacity — the counters above are about work *done*, and
a stage's depth is what says whether work is piling up in front of it.
The read is not atomic across stages: counters keep moving while we walk them,
so a snapshot can show a job counted as complete by stage 1 but not yet arrived
at stage 2. Over a benchmark window that skew is a job or two and does not move
a rate; a consistent snapshot would mean stopping the pipeline to read it.
"""
function stats_snapshot(cfg::Config, queues, m::Metrics = METRICS)
workers = (classify = cfg.worker_count, enrich = cfg.known_worker_count,
triage = cfg.unknown_worker_count, language = cfg.text_worker_count)
now = time()
stages = map(STAGE_KEYS, ntuple(identity, 4)) do key, i
s, q = m.stages[key], queues[key]
(; stage = i,
name = STAGE_TITLES[key],
workers = workers[key],
queue_depth = length(q),
queue_capacity = capacity(q),
completed = s.completed[],
failed = s.failed[],
bytes = s.bytes[],
busy_seconds = s.busy_ns[] / 1e9,
blocked_seconds = s.blocked_ns[] / 1e9,
in_flight = s.in_flight[])
end
return (; now,
since = m.since[],
uptime_seconds = now - m.since[],
intake = (; requests = m.intake.requests[],
files = m.intake.files[],
bytes = m.intake.bytes[],
rejected = m.intake.rejected[]),
stages = collect(stages))
end

68
src/worker.jl
View File

@@ -18,6 +18,21 @@
# this worker-to-worker handoff blocks.
const ROUTE_ENQUEUE_RETRY_SECONDS = 0.05
# Per-file logging in stage 1 is `@debug`, not `@info`, because it is the
# stage's dominant cost. Measured by bin/bench_stage1.jl (2000 x 64 KiB files,
# min of 5 trials): the two log lines cost ~71 µs of the ~118 µs
# `handle_classify_job` spent per file — roughly 6x the classifier (10.6 µs) and
# 6x the rename (11.6 µs). Nearly all of it is `ConsoleLogger` formatting
# (~64 µs); the FlushLogger's per-message flush is only ~8 µs on top. Demoting
# them takes stage 1 from ~8.5k files/s to ~35k files/s on one worker.
#
# `@debug` is compiled to a min-level check that doesn't evaluate its arguments,
# so a disabled line costs ~0.15 µs rather than ~36 µs. The messages are still
# there when wanted: run with `JULIA_DEBUG=FileServer` to get them back. Errors,
# quarantines and lifecycle events stay at `@error`/`@info` — they are rare and
# their cost doesn't scale with throughput. `GET /stats` (src/stats.jl) is the
# per-file observability that survives, and it is counted, not formatted.
"""
handle_classify_job(job, cfg, worker_id, known_queue, unknown_queue)
@@ -32,24 +47,24 @@ reference is visible downstream; the moved path becomes the routed job's locatio
Sub-`MIN_FILE_BYTES` files short-circuit to `:unknown` inside `classify`.
"""
function handle_classify_job(job::Job, cfg::Config, worker_id::Int,
known_queue::JobQueue, unknown_queue::JobQueue)
known_queue::JobQueue, unknown_queue::JobQueue,
stats::StageStats)
classification = classify(CLASSIFIER[], job.path)
@info "classified file" worker=worker_id id=job.id name=job.original_name size=job.size classification=classification
@debug "classified file" worker=worker_id id=job.id name=job.original_name size=job.size classification=classification
if classification === :known
dest = move_to(cfg.known_dir, job)
routed = Job(job.id, job.original_name, dest, job.size, job.received_at)
while !enqueue!(known_queue, routed)
sleep(ROUTE_ENQUEUE_RETRY_SECONDS) # known queue full → back off, don't drop
end
@info "routed to enrichment" worker=worker_id id=job.id dest=dest
# known queue full → park and retry, don't drop (time charged to blocked_ns)
enqueue_blocking!(known_queue, routed, stats;
retry_seconds = ROUTE_ENQUEUE_RETRY_SECONDS)
@debug "routed to enrichment" worker=worker_id id=job.id dest=dest
else
dest = move_to(cfg.unknown_dir, job)
routed = Job(job.id, job.original_name, dest, job.size, job.received_at)
while !enqueue!(unknown_queue, routed)
sleep(ROUTE_ENQUEUE_RETRY_SECONDS) # unknown queue full → back off, don't drop
end
@info "routed to content triage" worker=worker_id id=job.id dest=dest
enqueue_blocking!(unknown_queue, routed, stats;
retry_seconds = ROUTE_ENQUEUE_RETRY_SECONDS)
@debug "routed to content triage" worker=worker_id id=job.id dest=dest
end
return nothing
end
@@ -79,16 +94,17 @@ data, `text/` otherwise. A text file is then routed onward to the stage-4
language-enrichment queue, retrying on a full queue rather than dropping the file
(the same blocking backpressure stage 1 uses for its downstream queues).
"""
function handle_unknown_job(job::Job, cfg::Config, worker_id::Int, text_queue::JobQueue)
function handle_unknown_job(job::Job, cfg::Config, worker_id::Int,
text_queue::JobQueue, stats::StageStats)
if is_binary(job.path)
dest = move_to(cfg.binary_dir, job)
@info "sorted unknown" worker=worker_id id=job.id name=job.original_name kind=:binary dest=dest
else
dest = move_to(cfg.text_dir, job)
routed = Job(job.id, job.original_name, dest, job.size, job.received_at)
while !enqueue!(text_queue, routed)
sleep(ROUTE_ENQUEUE_RETRY_SECONDS) # text queue full → back off, don't drop
end
# text queue full → park and retry, don't drop (time charged to blocked_ns)
enqueue_blocking!(text_queue, routed, stats;
retry_seconds = ROUTE_ENQUEUE_RETRY_SECONDS)
@info "routed to language enrichment" worker=worker_id id=job.id dest=dest
end
return nothing
@@ -111,26 +127,46 @@ function handle_text_job(job::Job, cfg::Config, worker_id::Int, detector)
end
"""
worker_loop(worker_id, cfg, queue, handler)
worker_loop(worker_id, cfg, queue, handler, stats)
Consume jobs from `queue` until it is closed and drained, running `handler` on
each. A failure on one job is logged and the file quarantined in `failed/` — it
must never kill the worker, or the pool would silently shrink.
This loop is also where per-stage metrics are recorded (`stats`, see
src/stats.jl). Instrumenting here rather than in each handler means every stage
is measured the same way, by construction, and a new stage is measured the
moment it is wired up — there is no per-handler bookkeeping to forget.
The timed region is the handler alone, excluding the `dequeue!` above it: time
parked waiting for work is idleness, and counting it as service time would make
an idle stage look as busy as a saturated one. A quarantined job still counts
its time — the work was done, it just ended in `failed/`.
"""
function worker_loop(worker_id::Int, cfg::Config, queue::JobQueue, handler)
function worker_loop(worker_id::Int, cfg::Config, queue::JobQueue, handler,
stats::StageStats)
@info "worker started" worker=worker_id
while true
job = dequeue!(queue)
job === nothing && break # queue closed and drained → exit
Threads.atomic_add!(stats.in_flight, 1)
t0 = time_ns()
ok = true
try
handler(job, cfg, worker_id)
catch e
ok = false
@error "processing failed" worker=worker_id id=job.id name=job.original_name exception=(e, catch_backtrace())
try
move_to(cfg.failed_dir, job)
catch e2
@error "could not quarantine failed file" worker=worker_id id=job.id path=job.path exception=(e2, catch_backtrace())
end
finally
# In a `finally` so an InterruptException during shutdown can't leave
# in_flight permanently above zero, which would read as a stuck job.
record_job!(stats, ok, job.size, Int(time_ns() - t0))
Threads.atomic_sub!(stats.in_flight, 1)
end
end
@info "worker stopped" worker=worker_id

556
test/runtests.jl
View File

@@ -5,17 +5,25 @@ 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,
header_symbols, header_matrix, ClusterStats, add!, remove!,
log_predictive, loggamma, gibbs_cluster, assign_file,
signature, magic_positions, is_promotable,
adjusted_rand_index, v_measure, HEADER_N, ALPHABET, PAST_EOF
adjusted_rand_index, v_measure, HEADER_N, ALPHABET, PAST_EOF,
Catalog, load_catalog, save_catalog!, catalog_sweep!, compact!,
write_nominations!, run_cluster_sweep, binary_files, record_example!,
signature_hex, ensure_dirs,
MultipartReader, MultipartError, MultipartPart, next_part!,
write_part_body!, skip_part_body!, multipart_boundary,
parse_part_headers, spool_stream, UPLOAD_CHUNK_BYTES
using Random: MersenneTwister
using Languages: LanguageDetector
@@ -25,6 +33,39 @@ const PNG_1x1 = UInt8[137,80,78,71,13,10,26,10,0,0,0,13,73,72,68,82,0,0,0,1,0,
0,0,1,8,6,0,0,0,31,21,196,137,0,0,0,11,73,68,65,84,120,218,99,100,248,255,
191,30,0,5,132,2,127,194,91,30,42,0,0,0,0,73,69,78,68,174,66,96,130]
"""
Assemble a multipart/form-data body. `parts` are `(name, filename, content_type,
data)` tuples; a `nothing` filename makes a plain form field rather than a file.
"""
function multipart_body(boundary, parts; preamble = "", terminate = true)
io = IOBuffer()
write(io, preamble)
for (name, filename, content_type, data) in parts
write(io, "--$boundary\r\n")
write(io, "Content-Disposition: form-data; name=\"$name\"")
filename === nothing || write(io, "; filename=\"$filename\"")
write(io, "\r\n")
content_type === nothing || write(io, "Content-Type: $content_type\r\n")
write(io, "\r\n")
write(io, data)
write(io, "\r\n")
end
write(io, terminate ? "--$boundary--\r\n" : "--$boundary\r\n")
return take!(io)
end
"Read every part out of `bytes`, returning `(part, body, nbytes)` triples."
function read_all_parts(bytes, boundary; chunk_bytes = UPLOAD_CHUNK_BYTES)
r = MultipartReader(IOBuffer(bytes), boundary; chunk_bytes = chunk_bytes)
out = Tuple{MultipartPart,String,Int}[]
while (part = next_part!(r)) !== nothing
sink = IOBuffer()
n = write_part_body!(sink, r)
push!(out, (part, String(take!(sink)), n))
end
return out
end
"Build a Config whose data dirs all live under a fresh temp directory."
function tmp_config(root; kwargs...)
cfg = Config(;
@@ -36,6 +77,9 @@ function tmp_config(root; kwargs...)
done_dir = joinpath(root, "done"),
text_done_dir = joinpath(root, "text_done"),
failed_dir = joinpath(root, "failed"),
cluster_dir = joinpath(root, "binary"), # stage-5 sweeps the binary sink
cluster_catalog_path = joinpath(root, "catalog.json"),
nominated_dir = joinpath(root, "nominated"),
kwargs...,
)
FileServer.ensure_dirs(cfg)
@@ -59,6 +103,139 @@ end
@test Base.length(sanitize_filename("a"^500)) == FileServer.MAX_NAME_LEN
end
@testset "multipart_boundary: extraction from Content-Type" begin
@test multipart_boundary("multipart/form-data; boundary=abc") == "abc"
@test multipart_boundary("multipart/form-data; boundary=\"a b;c\"") == "a b;c"
@test multipart_boundary("MULTIPART/FORM-DATA; BOUNDARY=xyz") == "xyz"
@test multipart_boundary("multipart/form-data; charset=utf-8; boundary=q1") == "q1"
# Anything that isn't a usable multipart header is the same 400 to a caller.
@test multipart_boundary("multipart/form-data") === nothing
@test multipart_boundary("application/json") === nothing
@test multipart_boundary(nothing) === nothing
end
@testset "parse_part_headers" begin
p = parse_part_headers("Content-Disposition: form-data; name=\"f\"; filename=\"a b.txt\"\r\n" *
"Content-Type: text/plain")
@test p.name == "f"
@test p.filename == "a b.txt"
@test p.content_type == "text/plain"
# `name=` must not match inside `filename=` — that would label every
# file part with a bogus name and (worse) hide a missing real name.
p = parse_part_headers("Content-Disposition: form-data; filename=\"only.txt\"")
@test p.name === nothing
@test p.filename == "only.txt"
# No filename means a plain form field, which intake must not spool.
p = parse_part_headers("Content-Disposition: form-data; name=\"note\"")
@test p.filename === nothing
end
@testset "MultipartReader: parts, fields, and bodies" begin
B = "----testboundary"
body = multipart_body(B, [("f0", "a.txt", "text/plain", "hello world"),
("note", nothing, nothing, "just-a-field"),
("f1", "b.bin", nothing, "\x00\x01\x02")])
got = read_all_parts(body, B)
@test length(got) == 3
@test got[1][1].filename == "a.txt"
@test got[1][2] == "hello world"
@test got[1][3] == 11 # reported byte count
@test got[1][1].content_type == "text/plain"
@test got[2][1].filename === nothing # the form field
@test got[2][2] == "just-a-field"
@test codeunits(got[3][2]) == UInt8[0x00, 0x01, 0x02]
# A zero-byte file is legal and must survive as zero bytes.
empty_got = read_all_parts(multipart_body(B, [("f", "empty.bin", nothing, "")]), B)
@test empty_got[1][3] == 0
@test empty_got[1][2] == ""
end
@testset "MultipartReader: delimiter straddling every chunk offset" begin
# The one thing a chunked parser can get catastrophically wrong is a
# delimiter split across two reads. Parsing the same body at many chunk
# sizes puts the split at every offset. The payload deliberately contains
# CR, LF and '-' bytes, so a sloppy scan finds false delimiters.
B = "----testboundary"
rng = MersenneTwister(7)
payload = String(rand(rng, UInt8[0x41:0x5a; 0x0d; 0x0a; 0x2d], 5000))
body = multipart_body(B, [("f", "big.bin", nothing, payload)])
for chunk in (1, 2, 3, 5, 7, 13, 16, 17, 64, 255, 4096, 10_000)
got = read_all_parts(body, B; chunk_bytes = chunk)
@test length(got) == 1
@test got[1][2] == payload
end
# A payload containing a *prefix* of the real delimiter must not end the part.
tricky = "aaa\r\n--" * "----testboundar" * "bbb\r\n--x\r\nccc"
body2 = multipart_body(B, [("f", "t.bin", nothing, tricky)])
for chunk in (1, 4, 9, 64, 4096)
got = read_all_parts(body2, B; chunk_bytes = chunk)
@test length(got) == 1
@test got[1][2] == tricky
end
end
@testset "MultipartReader: memory stays bounded, not proportional to the part" begin
# The whole point of the streaming reader. A 16 MiB part read with a
# 64 KiB chunk must allocate on the order of the chunk, not the part.
B = "----testboundary"
payload = String(rand(MersenneTwister(11), UInt8, 16 * 1024 * 1024))
body = multipart_body(B, [("f", "huge.bin", nothing, payload)])
r = MultipartReader(IOBuffer(body), B; chunk_bytes = 64 * 1024)
next_part!(r)
GC.gc()
allocated = @allocated write_part_body!(devnull, r)
@test allocated < 4 * 1024 * 1024
end
@testset "MultipartReader: malformed bodies raise MultipartError" begin
B = "----testboundary"
valid = multipart_body(B, [("f", "a.bin", nothing, "hello")])
@test_throws MultipartError read_all_parts(Vector{UInt8}("no delimiter here"), B)
@test_throws MultipartError read_all_parts(valid[1:end-20], B) # truncated mid-part
@test_throws MultipartError read_all_parts(
multipart_body(B, [("f", "a.bin", nothing, "x")]; terminate = false), B)
# Part headers must be bounded regardless of how the body was chunked,
# since they are the one thing that has to be buffered whole to parse.
oversized = Vector{UInt8}("--$B\r\nContent-Disposition: form-data; name=\"" *
"x"^30_000 * "\"\r\n\r\ndata\r\n--$B--\r\n")
@test_throws MultipartError read_all_parts(oversized, B)
# A part's body must be consumed before advancing: the reader cannot skip
# a body on its own, because a body only ends at the next delimiter.
r = MultipartReader(IOBuffer(valid), B)
next_part!(r)
@test_throws MultipartError next_part!(r)
end
@testset "spool_stream: streams to disk, cleans up a failed write" begin
mktempdir() do root
cfg = tmp_config(root)
job = spool_stream(cfg, "report v2.pdf") do io
write(io, "abc") + write(io, "de")
end
@test isfile(job.path)
@test read(job.path, String) == "abcde"
@test job.size == 5 # from the bytes actually written
@test job.original_name == "report v2.pdf"
@test basename(job.path) == "$(job.id)-report_v2.pdf" # sanitized, uuid-prefixed
# A write that throws must leave nothing behind: recovery on restart
# re-enqueues whatever is in spool/, and a truncated upload there
# would be silently processed as if it were complete.
before = length(readdir(cfg.spool_dir))
@test_throws ErrorException spool_stream(cfg, "bad.bin") do io
write(io, "partial")
error("disk went away")
end
@test length(readdir(cfg.spool_dir)) == before
end
end
@testset "normalize_metadata" begin
job = Job("id-1", "photo.jpg", "/data/known/id-1-photo.jpg", 4242, 0.0)
# Group-prefixed tags as exiftool -G emits them are already group-stripped
@@ -112,6 +289,42 @@ end
end
end
@testset "run_with_timeout: returns as soon as the child exits" begin
# Regression guard. The original implementation polled with sleep(0.1)
# and joined the polling task, so every call paid the remainder of an
# in-flight sleep after the child had already exited — ~101 ms on a
# process that exits instantly, on the hot path of stages 2 and 4. The
# bound here is deliberately loose (a loaded CI box is slow) but far
# under the 100 ms floor the polling version could not beat.
FileServer.run_with_timeout(`true`, 30) # warm up / compile
t0 = time()
out = FileServer.run_with_timeout(`echo hi`, 30)
elapsed = time() - t0
@test out !== nothing
@test strip(String(out)) == "hi"
@test elapsed < 0.05
end
@testset "run_with_timeout: kills an overrunning child and reports failure" begin
t0 = time()
out = FileServer.run_with_timeout(`sleep 30`, 1)
elapsed = time() - t0
@test out === nothing # timed out → no output, caller degrades
@test elapsed < 5 # killed near the timeout, not after 30 s
end
@testset "run_with_timeout: escalates to SIGKILL when SIGTERM is ignored" begin
# A child that traps SIGTERM. Without the escalation the worker would
# block on wait(proc) forever and the timeout would be unenforceable.
cmd = `sh -c "trap '' TERM; sleep 30"`
t0 = time()
out = FileServer.run_with_timeout(cmd, 1)
elapsed = time() - t0
@test out === nothing
# 1 s timeout + up to KILL_GRACE_SECONDS before SIGKILL lands.
@test elapsed < 1 + FileServer.KILL_GRACE_SECONDS + 3
end
@testset "run_exiftool: real extraction on a PNG" begin
mktempdir() do root
p = joinpath(root, "pixel.png")
@@ -209,12 +422,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
@@ -224,7 +438,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)
@@ -525,4 +739,336 @@ end
end
end
# Helper: write a "file" of raw bytes into a dir with a UUID-ish unique name,
# returning its path. Mirrors what stage-3 deposits into binary/.
function drop_binary(dir, bytes; name=string(rand(UInt128)))
mkpath(dir)
p = joinpath(dir, name)
open(p, "w") do io; write(io, Vector{UInt8}(bytes)); end
return p
end
@testset "catalog: durable save/load round-trip" begin
mktempdir() do root
n = 8
cat = Catalog(n)
c = ClusterStats(n)
add!(c, [0xCA+1, 0xFE+1, 0xBA+1, 0xBE+1, 1, 2, 3, 4])
add!(c, [0xCA+1, 0xFE+1, 0xBA+1, 0xBE+1, 5, 6, 7, 8])
cat.clusters[7] = c
cat.next_id = 8
record_example!(cat, 7, "alpha.bin")
push!(cat.processed, "alpha.bin"); push!(cat.processed, "beta.bin")
path = joinpath(root, "catalog.json")
save_catalog!(path, cat)
@test isfile(path)
back = load_catalog(path; n=n)
@test back.n == n
@test back.next_id == 8
@test back.processed == cat.processed
@test haskey(back.clusters, 7)
@test back.clusters[7].members == 2
@test back.clusters[7].counts == c.counts # sparse round-trips exactly
@test back.examples[7] == ["alpha.bin"]
end
end
@testset "catalog: load of a missing file is a fresh catalog" begin
mktempdir() do root
cat = load_catalog(joinpath(root, "nope.json"); n=16)
@test cat.n == 16
@test isempty(cat.clusters)
@test isempty(cat.processed)
@test cat.next_id == 1
end
end
@testset "catalog: binary_files skips sidecars, tmp, dirs; sorts" begin
mktempdir() do root
drop_binary(root, "a"; name="002-file")
drop_binary(root, "b"; name="001-file")
write(joinpath(root, "003-file.meta.json"), "{}") # sidecar
write(joinpath(root, "004-file.tmp"), "x") # scratch
mkpath(joinpath(root, "subdir")) # not a file
fs = binary_files(root)
@test basename.(fs) == ["001-file", "002-file"]
end
end
@testset "catalog: incremental sweep grows an existing cluster" begin
mktempdir() do root
n = 8
cfg = tmp_config(root; cluster_n=n, cluster_alpha=1.0,
cluster_pseudocount=0.1, cluster_bg_mass=5.0)
# Seed a strong cluster (magic 0xCA 0xFE 0xBA 0xBE, random tail).
cat = Catalog(n)
c = ClusterStats(n)
rng = MersenneTwister(3)
for _ in 1:40
add!(c, vcat([0xCA,0xFE,0xBA,0xBE] .+ 1, rand(rng, 1:256, 4)))
end
cat.clusters[1] = c
cat.next_id = 2
# A brand-new file that matches the magic must JOIN cluster 1.
drop_binary(cfg.cluster_dir, vcat(UInt8[0xCA,0xFE,0xBA,0xBE], rand(rng, UInt8, 4)); name="match-01")
# A structureless random blob must park in the background.
drop_binary(cfg.cluster_dir, rand(rng, UInt8, 64); name="blob-01")
s = catalog_sweep!(cat, cfg)
@test s.n_seen == 2
@test s.n_joined == 1
@test s.n_bg == 1
@test s.n_minted == 0
@test cat.clusters[1].members == 41 # grew by the matching file
@test "match-01" in cat.processed
@test "blob-01" in cat.processed
# Re-sweeping the same pile is idempotent — nothing new is seen.
s2 = catalog_sweep!(cat, cfg)
@test s2.n_seen == 0
@test cat.clusters[1].members == 41
end
end
@testset "catalog: §10.1 nothing from noise (end-to-end, no promotion)" begin
mktempdir() do root
n = 32
cfg = tmp_config(root; cluster_n=n, cluster_alpha=1.0,
cluster_pseudocount=0.1, cluster_bg_mass=5.0,
promote_min_members=20, promote_min_magic=3)
rng = MersenneTwister(10)
# The §10.1 pile: 20 small random blobs + 1 lone structured "PDF".
for i in 1:20
drop_binary(cfg.cluster_dir, rand(rng, UInt8, 40); name="blob-$(lpad(i,2,'0'))")
end
drop_binary(cfg.cluster_dir, vcat(UInt8[0x25,0x50,0x44,0x46], rand(rng, UInt8, 60)); name="lone-pdf")
# First run auto-compacts (empty catalog) to seed, then persists + nominates.
r = run_cluster_sweep(cfg; rng=MersenneTwister(10))
@test r.mode == :compact
@test isfile(cfg.cluster_catalog_path)
# The mission-critical assertion: ZERO promoted clusters from pure noise.
@test r.n_nominated == 0
@test isempty(readdir(cfg.nominated_dir))
# Every file was accounted for (clustered-as-singleton or background).
@test r.n_processed == 21
end
end
@testset "catalog: a real recurring format self-nominates" begin
mktempdir() do root
n = 32
# β=0.1 over-splits a format into pure sub-clusters (DESIGN §11 known
# limitation) — each still carries the full magic and nominates
# independently, so a modest min_members catches those sub-clusters.
cfg = tmp_config(root; cluster_n=n, cluster_alpha=1.0,
cluster_pseudocount=0.1, cluster_bg_mass=5.0,
promote_min_members=10, promote_min_magic=3)
rng = MersenneTwister(21)
# 30 files sharing a fixed 6-byte magic then random payload — a format.
magic = UInt8[0x89, 0x46, 0x4d, 0x54, 0x21, 0x0a]
for i in 1:30
drop_binary(cfg.cluster_dir, vcat(magic, rand(rng, UInt8, 40)); name="fmt-$(lpad(i,2,'0'))")
end
r = run_cluster_sweep(cfg; rng=MersenneTwister(21))
@test r.n_nominated >= 1
files = readdir(cfg.nominated_dir; join=true)
@test !isempty(files)
payload = JSON3.read(read(first(files), String))
@test payload.members >= 10
@test payload.magic_length >= 3
# The hex template exposes the shared magic bytes for the human gate.
@test occursin("89 46 4d 54", payload.signature_hex)
end
end
@testset "catalog: seeded catalog then live-assigns a matching arrival" begin
mktempdir() do root
n = 32
cfg = tmp_config(root; cluster_n=n, cluster_alpha=1.0,
cluster_pseudocount=0.1, cluster_bg_mass=5.0,
promote_min_members=20, promote_min_magic=3)
rng = MersenneTwister(31)
magic = UInt8[0x7a, 0x7a, 0x01, 0x02, 0x03]
for i in 1:25
drop_binary(cfg.cluster_dir, vcat(magic, rand(rng, UInt8, 40)); name="seed-$(lpad(i,2,'0'))")
end
# Seed pass.
run_cluster_sweep(cfg; rng=MersenneTwister(31))
cat = load_catalog(cfg.cluster_catalog_path; n=n)
@test !isempty(cat.clusters)
members_before = sum(c.members for c in values(cat.clusters))
# A new matching file arrives; an incremental sweep must fold it in
# (mode :sweep, not compact) without re-clustering the world.
drop_binary(cfg.cluster_dir, vcat(magic, rand(rng, UInt8, 40)); name="arrival-01")
r2 = run_cluster_sweep(cfg; rng=MersenneTwister(99))
@test r2.mode == :sweep
cat2 = load_catalog(cfg.cluster_catalog_path; n=n)
members_after = sum(c.members for c in values(cat2.clusters))
@test members_after == members_before + 1 # the arrival joined a cluster
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