unsloth/studio/backend/hub/services/snapshot_progress.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

285 lines
9.9 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
"""Shared snapshot download-progress computation for models and datasets.
Both scan the cache's ``blobs/`` dir, split finalized vs ``.incomplete`` bytes,
filter to the target revision's expected hashes, and divide by its total size;
only the ``metadata_resolver`` differs. One copy keeps the two from drifting (a
prior hash-filter fix once landed only on the model copy, leaving datasets
summing stale blobs against the wrong total)."""
from __future__ import annotations
import asyncio
import threading
from pathlib import Path
from typing import Callable, Optional
from loggers import get_logger
from hub.utils import download_manifest
from hub.utils import download_registry
from hub.utils import inventory_scan as hf_cache_scan
from hub.utils.state_dir import RepoType
from hub.utils.hf_cache_state import (
INCOMPLETE_SUFFIX,
blob_bytes_present,
latest_snapshot_dir,
preferred_repo_cache_dirs,
)
from hub.utils.paths import is_valid_repo_id as _is_valid_repo_id
logger = get_logger(__name__)
# (repo_id, hf_token) -> (expected_total_bytes, expected_blob_hashes)
SnapshotMetadataResolver = Callable[[str, Optional[str]], "tuple[int, frozenset[str]]"]
# One progress log per 10% step per job, so an active download reports progress
# without emitting a line on every poll.
_progress_step_lock = threading.Lock()
_last_progress_step: dict[str, int] = {}
def _log_progress_step(job_key: str, repo_id: str, variant: Optional[str], progress: float) -> None:
step = int(progress * 10)
with _progress_step_lock:
last = _last_progress_step.get(job_key, -1)
if step == last:
return
_last_progress_step[job_key] = step
if step < last:
return # download restarted; resync without logging
logger.info(
"hub_download_progress",
repo_id = repo_id,
variant = variant or "",
percent = step * 10,
)
def _empty_progress(expected_bytes: int) -> dict:
return {
"downloaded_bytes": 0,
"completed_bytes": 0,
"complete_on_disk": False,
"expected_bytes": max(expected_bytes, 0),
"progress": 0,
"cache_path": None,
}
def _snapshot_complete_on_disk(
*,
repo_type: RepoType,
repo_id: str,
variant: Optional[str],
entry: Path,
expected_total: int,
completed_bytes: int,
in_progress_bytes: int,
) -> bool:
if expected_total <= 0 or completed_bytes < expected_total or in_progress_bytes > 0:
return False
snapshot_dir = latest_snapshot_dir(entry)
if snapshot_dir is None:
return False
if variant is None and hf_cache_scan.repo_cache_dir_has_incomplete_blobs(entry):
return False
if download_manifest.has_cancel_marker(repo_type, repo_id, variant):
return False
manifest = download_manifest.read_manifest(repo_type, repo_id, variant)
if manifest is None:
return False
return download_manifest.verify_against_disk(manifest, snapshot_dir).ok
def compute_snapshot_progress(
*,
repo_type: RepoType,
repo_id: str,
job_key: str,
expected_bytes: int,
hf_token: Optional[str],
registry,
metadata_resolver: SnapshotMetadataResolver,
variant: Optional[str] = None,
) -> dict:
"""Synchronous progress reading. Safe to run under ``asyncio.to_thread``."""
empty = _empty_progress(expected_bytes)
if not _is_valid_repo_id(repo_id):
return empty
job_state = registry.get_job(job_key).state
force_active = job_state in {"running", "cancelling"}
get_job_metadata = getattr(registry, "get_job_metadata", None)
metadata = get_job_metadata(job_key) if callable(get_job_metadata) else None
completed_baseline_bytes = max(
0,
int(getattr(metadata, "completed_baseline_bytes", 0) or 0),
)
expected_total = max(expected_bytes, 0)
# Always resolve the revision's blob hashes so stale blobs from a superseded
# revision can't inflate the count; hashes degrade to empty (count-all) only
# when metadata is unavailable (e.g. offline). Take the larger total so a low
# caller hint can't cap the bar below the revision's real size.
meta_total, expected_hashes = metadata_resolver(repo_id, hf_token)
expected_total = max(expected_total, meta_total)
# Without resolved hashes, a variant must not count unscoped blobs: sibling
# quants share one blobs/ dir, so a sibling's bytes (or .incomplete) would be
# misattributed and make the bar jump backward. A no-variant snapshot owns
# the whole dir, so it counts unscoped.
count_finalized_unscoped = variant is None
readings: list[tuple[int, int, Optional[str], bool]] = []
for entry in preferred_repo_cache_dirs(
repo_type,
repo_id,
force_active = force_active,
):
completed_bytes = 0
in_progress_bytes = 0
cache_path = hf_cache_scan.resolve_hf_cache_realpath(entry)
blobs_dir = entry / "blobs"
if blobs_dir.is_dir():
try:
blob_entries = list(blobs_dir.iterdir())
except OSError:
blob_entries = []
for f in blob_entries:
# Skip a blob that vanished mid-poll rather than zeroing the reading.
try:
if not f.is_file():
continue
if f.name.endswith(INCOMPLETE_SUFFIX):
blob_hash = f.name[: -len(INCOMPLETE_SUFFIX)]
if expected_hashes:
if blob_hash not in expected_hashes:
continue
elif not count_finalized_unscoped:
continue
in_progress_bytes += blob_bytes_present(f)
else:
if expected_hashes:
if f.name not in expected_hashes:
continue
elif not count_finalized_unscoped:
continue
completed_bytes += f.stat().st_size
except OSError:
continue
readings.append(
(
completed_bytes,
in_progress_bytes,
cache_path,
_snapshot_complete_on_disk(
repo_type = repo_type,
repo_id = repo_id,
variant = variant,
entry = entry,
expected_total = expected_total,
completed_bytes = completed_bytes,
in_progress_bytes = in_progress_bytes,
),
)
)
selected = max(
readings,
key = lambda item: (item[0] + item[1], item[0]),
default = None,
)
if selected is None:
return empty
completed_bytes, in_progress_bytes, cache_path, complete_on_disk = selected
downloaded_bytes = completed_bytes + in_progress_bytes
# Subtract the companion baseline only while still counted in completed_bytes
# and the variant is not yet verified complete, else genuine progress reads as
# 0-byte.
effective_baseline_bytes = (
completed_baseline_bytes
if not complete_on_disk and completed_baseline_bytes <= completed_bytes
else 0
)
display_completed_bytes = max(0, completed_bytes - effective_baseline_bytes)
display_downloaded_bytes = max(0, downloaded_bytes - effective_baseline_bytes)
if expected_total <= 0:
# Cannot determine total; report bytes only, no percentage.
return {
"downloaded_bytes": display_downloaded_bytes,
"completed_bytes": display_completed_bytes,
"complete_on_disk": False,
"expected_bytes": 0,
"progress": 0,
"cache_path": cache_path,
}
display_expected_total = max(0, expected_total - effective_baseline_bytes)
if downloaded_bytes == 0:
return {
**empty,
"expected_bytes": display_expected_total,
"cache_path": cache_path,
}
# Cap at 0.99 until the manifest-backed disk check verifies completion: on
# resume, completed bytes can sit above the threshold while files still download.
progress = (
1.0
if complete_on_disk
else (
min(display_downloaded_bytes / display_expected_total, 0.99)
if display_expected_total > 0
else 0
)
)
if force_active:
_log_progress_step(job_key, repo_id, variant, progress)
return {
"downloaded_bytes": display_downloaded_bytes,
"completed_bytes": display_completed_bytes,
"complete_on_disk": complete_on_disk,
"expected_bytes": display_expected_total,
"progress": round(progress, 3),
"cache_path": cache_path,
}
async def snapshot_progress_response(
*,
repo_type: RepoType,
repo_id: str,
job_key: str,
expected_bytes: int,
hf_token: Optional[str],
registry,
metadata_resolver: SnapshotMetadataResolver,
variant: Optional[str] = None,
) -> dict:
"""Async wrapper: offloads the blocking cache walk and never raises."""
try:
return await asyncio.to_thread(
compute_snapshot_progress,
repo_type = repo_type,
repo_id = repo_id,
job_key = job_key,
expected_bytes = expected_bytes,
hf_token = hf_token,
registry = registry,
metadata_resolver = metadata_resolver,
variant = variant,
)
except Exception as e:
logger.warning(
"Error checking %s download progress for %s: %s: %s",
repo_type,
repo_id,
type(e).__name__,
download_registry.scrub_secrets(str(e), hf_token = hf_token),
)
return _empty_progress(expected_bytes)