unsloth/studio/backend/tests/test_load_progress_throttle.py
Daniel Han a6aa4fff10
Studio: quiet noisy logs, log real progress, and speed up Windows/macOS dataset prep (#7087)
* Studio: exclude /api/export/status from request access logs

The frontend polls /api/export/status every 5s to detect export start, so it
fires continuously even when idle. Each poll emitted an info request_completed
access line, making up most of the server access logs. Add it to _EXCLUDED_PATHS
alongside /api/train/status. The endpoint is unchanged; export state is still
logged by the export modules and streamed over SSE, so no signal is lost.

* Studio: collapse hub download-progress polls in the access log

download-status and gguf-download-progress (plus the dataset equivalents)
are polled about twice a second for the whole download, so each emitted an
info request_completed line. Add them to _QUIET_POLL_PATHS so they collapse
to one heartbeat line per 10s instead of one per poll.

* Studio: log hub download progress at 10% steps

The access log carried no real progress, only poll pings. Emit one
hub_download_progress line per 10% step from the shared snapshot progress
reader, so an active download shows actual percentage without a line per
poll. Throttled per job and resynced if the same download restarts.

* [pre-commit.ci] auto fixes from pre-commit.com hooks

for more information, see https://pre-commit.ci

* Studio: drop successful chat thread/project CRUD from the access log

A single chat turn fans out about twenty requests under /api/chat/threads
and /api/chat/projects (list, fetch, per-message forks, and the message
writes) that only reflect the UI re-rendering. Suppress their 2xx access
line so the log keeps the signal (generation, tool calls, code execution,
engine stats) and errors. Non-2xx on these paths still log.

* Studio: silence transformers torch_dtype deprecation warning

transformers logs "`torch_dtype` is deprecated! Use `dtype` instead!" once at
model-config load via logger.warning_once (logging, not warnings), so a warnings
filter cannot catch it. Attach a small logging.Filter in setup_logging, which
runs before any model config is parsed, to drop that record on the transformers
loggers that emit it.

* Studio: quiet inference load-progress polls and log throttled load progress

The frontend polls /api/inference/load-progress about twice a second for the
whole model load, so each emitted a request_completed line. Add it to
_QUIET_POLL_PATHS (heartbeat) and emit one inference_load_progress line per 10%
step from the load-progress route, so a load shows real percentage instead of a
line per poll.

* Studio: fully suppress download/load progress poll access lines

The download-status, download-progress, gguf-download-progress, active-downloads
and transport-status polls (model and dataset), plus inference load-progress,
fire ~2x/s for the whole download or load. Their progress is now reported by the
hub_download_progress / inference_load_progress events (and the viewer's progress
line), so the per-poll access line adds nothing. Drop it on 2xx and keep it on
errors, instead of the prior 10s heartbeat. Chat CRUD suppression is folded into
the same _is_quiet_success helper.

* Studio: suppress training-tab model/dataset download-progress polls

The training tab polls /api/models/download-progress and
/api/datasets/download-progress about twice a second for the whole prep phase.
These are separate routes from the /api/hub equivalents and only scan the cache,
so their 2xx access line adds nothing (on Windows they always read 0 since the
bytes live in snapshots/, not blobs/). Suppress the 2xx line and keep errors,
alongside /api/models/gguf-download-progress.

* Studio: drop transient pre-auth 401 on chat thread/project polls

On first load the SPA fires chat thread/project GETs before the initial token
refresh, so they 401 until /api/auth/refresh runs and the retries succeed. That
pre-auth 401 is a bootstrap artifact, not an error; suppress it alongside the
already-quiet 2xx line. Genuine 4xx/5xx on these paths, the download/load poll
401s, and all /api/auth/* still log.

* Studio: quiet tab-switch list polls and per-poll scan/reconnect logs

Switching between the Train, Export, and Chat tabs refetches list endpoints on a
timer, and each hit re-logs internal detail. Heartbeat /api/train/runs,
/api/models/checkpoints, /api/models/local and /api/rag/knowledge-bases (10s
window, first hit and errors still log), and downgrade two per-poll INFO lines to
debug: the checkpoints scan summary ("Found N training runs") and the
per-reconnect SSE resume line. The meaningful "replayed N missed steps" line,
logged only when steps were actually replayed, stays at info.

* Studio: enable tokenizer parallelism for dataset prep on Windows/macOS

TOKENIZERS_PARALLELISM was forced off everywhere to stop datasets' forked map()
workers from deadlocking, but that fork only happens on Linux. On spawn platforms
(Windows/macOS) dataset.map() runs in-process (dataset_map_num_proc returns None),
so disabling tokenizer parallelism leaves the fast tokenizer single-threaded and
dataset prep runs serially on one core. Keep it off on Linux (fork safety) and on
for spawn platforms, where there is no fork to deadlock. Measured ~7x faster
tokenization (12.5s -> 1.7s for 20k rows on a 32-core Windows box).

* [pre-commit.ci] auto fixes from pre-commit.com hooks

for more information, see https://pre-commit.ci

* Studio: log throttled training status to the server log

Training step/loss/epoch only went to the UI via SSE, so the server log showed
inference engine_stats and train/runs heartbeats but nothing about the actual
run. Emit one throttled training_progress line (step/total, percent, loss, epoch,
eta) from the CUDA event pump: the first step, then at most every 30s, plus the
final step, resyncing when a new run restarts the counter. Per-step UI streaming
is unchanged.

* Studio: quiet llama.cpp update-status polls and log throttled update progress

The prebuilt llama.cpp update polls /api/llama/update-status about twice a second
for the whole download and install. Suppress its 2xx access line (errors still
log) and emit one throttled llama_update_progress line per 10% step from the
status route, so the update shows progress without a line per poll. The existing
"llama update: installing" and "llama update: success" events still bracket it.

* Studio: quiet the export log-tail poll

The Export tab polls /api/export/logs about once a second to stream the export
subprocess output into the UI panel. Suppress its 2xx access line; the real
progress is already logged as event-driven "Export subprocess status: <phase>"
lines plus the subprocess start and checkpoint-loaded events, and errors still log.

* studio: keep errors and mutations visible in access-log suppression

Make the quiet-success access-log suppression GET-only so chat thread/project
mutations (POST/PUT/DELETE) still log; only their list-poll 2xx and the
transient pre-auth 401 are dropped.

Suppress /api/export/status 2xx only (move it out of the all-status exclude
set) so a 401/403/500 on it stays visible.

Legacy /api/models and /api/datasets download-progress polls emit no
hub_download_progress events, so heartbeat them via the 10s quiet-poll window
instead of suppressing outright, keeping download visibility (notably on
Linux). The event-emitting /api/hub download polls stay fully suppressed.

Update and extend the middleware tests to cover GET-only suppression, the
export-status error path, and the legacy download heartbeat.

* [pre-commit.ci] auto fixes from pre-commit.com hooks

for more information, see https://pre-commit.ci

* studio: tighten access-log and training-progress comments

Comment-only pass: collapse the multi-line explanations in the logging
middleware and the throttled training-progress logger to fewer lines while
keeping the rationale. No behavior change.

* studio: log structured export_progress phases

Emit a structured export_progress event per phase (consolidated in the server
log like training and download progress) instead of a plain status string, and
add a phase milestone at the start of the heavy export step so the
merge/save/convert is visible in the server log, not only in the forwarded
stdout panel.

* Studio: reset training-progress log throttle on each new run

start_training rebuilds the per-run progress state but left _last_progress_log_ts/_last_progress_log_step at their prior values. A run started within 30s of a previous one whose last logged step matched the new run's first step would hit the step == prev short-circuit and drop the promised first training_progress line, then stay suppressed until the old 30s window expired. Reset both fields when a new job is accepted.

* Studio: keep post-bootstrap chat 401s visible in the access log

The chat thread/project 401 suppression dropped every GET 401 on those prefixes, so a genuine expired-session 401 vanished alongside the transient pre-auth race. Gate the 401 drop on a per-middleware bootstrap latch that flips once /api/auth/refresh first succeeds: before that the 401s are the pre-refresh race and are suppressed; after it any chat 401 is a real failure and logs. Add a test for the post-refresh case.

* [pre-commit.ci] auto fixes from pre-commit.com hooks

for more information, see https://pre-commit.ci

* Studio: limit chat access-log suppression to the exact list polls

The chat thread/project suppression matched by startswith, so it also dropped the 2xx access line for detail and message reads (/threads/{id}, /threads/{id}/messages, /threads/{id}/messages/{id}, /projects/{id}) that are not the high-frequency list polls, losing their access and latency logging. Match the two list paths exactly instead, so only the intended list polls (and their pre-auth 401 race) are suppressed while detail and message reads keep their access line. Add a regression test.

* Studio: reset inference load-progress throttle for each load

The load-progress throttle (_last_load_progress_step) is a module global that persisted across loads, so a cached or small load whose first sampled /api/inference/load-progress response already reported fraction=1.0 hit step == prev (10) from a prior completed load and emitted no inference_load_progress line, while that endpoint's access log is suppressed, leaving the new load with no progress signal. Arm the throttle at load initiation in _load_model_impl so each load's first step always logs. Add a regression test.

* Studio: tighten logging comments

Collapse a few verbose comments (tokenizer-parallelism note, torch_dtype filter, legacy download-poll heartbeat, chat list-path suppression) to fewer lines without changing intent or code.

---------

Co-authored-by: pre-commit-ci[bot] <66853113+pre-commit-ci[bot]@users.noreply.github.com>
2026-07-15 06:49:52 -07:00

48 lines
1.4 KiB
Python

# SPDX-License-Identifier: AGPL-3.0-only
# Copyright 2026-present the Unsloth AI Inc. team. All rights reserved. See /studio/LICENSE.AGPL-3.0
"""The /api/inference/load-progress throttle: one line per 10% step, reset per load."""
import pytest
import routes.inference as ri
class _Capture:
def __init__(self):
self.events = []
def info(self, event, **kw):
self.events.append((event, kw))
@pytest.fixture
def cap(monkeypatch):
capture = _Capture()
monkeypatch.setattr(ri, "logger", capture)
ri._reset_load_progress_step()
return capture
def _percents(cap):
return [kw["percent"] for _event, kw in cap.events]
def test_new_load_first_step_logs_after_reset(cap):
# Load A reaches 100%.
ri._log_load_progress_step(1.0, "ready")
assert _percents(cap) == [100]
# Same value keeps deduping (steady poll on a finished load stays quiet).
ri._log_load_progress_step(1.0, "ready")
assert _percents(cap) == [100]
# A new load arms the throttle, so a cached load B that reports 100% on its
# first poll still emits its progress line instead of hitting step == prev.
ri._reset_load_progress_step()
ri._log_load_progress_step(1.0, "ready")
assert _percents(cap) == [100, 100]
def test_steady_poll_dedups_within_a_load(cap):
for _ in range(3):
ri._log_load_progress_step(0.3, "mmap")
assert _percents(cap) == [30] # one line per 10% step, not one per poll