The package installed its own handler, Formatter and level on a module-level logger, then logged through that logger. ComfyUI core already installs app.logger.ColoredFormatter on the ROOT logger, so a bare logging.<level>() call whose message starts with "[ComfyUI-VibeVoice] " is tagged and coloured for free. This removes the duplicate machinery rather than extending it -- no vv_logging module, Logger subclass, LoggerAdapter, vendored ANSI table, new handler, setLevel or propagate. Three hazards that motivated deleting the setup block rather than moving it: - propagate=False severed pytest's caplog; the tests only passed because __init__.py's `if "pytest" in sys.modules` guard skipped the block. Bare root calls propagate by default. - logger.setLevel(INFO) on the package logger pinned every descendant, so ComfyUI's --verbose never applied to this node. Deleting the block fixes it. - The level must stay a literal at the call site; no env-var switch was added. modules/diagnostics.py gates diagnostic CONTENT and is untouched. Every call site (235 across 34 files) is now a bare root call with the prefix. The vendored src/vibevoice tree used transformers.utils.logging, which has no module-level info/warning/debug; those files now import stdlib logging, so a new call site there would fail loudly instead of silently. Level audit against ERROR=failure / WARNING=degradation / INFO=user-facing progress / DEBUG=internals. Deleted as noise: the resample notice (44.1 kHz reference audio is the normal case) and the two "Successfully loaded external VibeVoice" confirmations, which duplicated the patcher's load line. Promoted to WARNING: a mixed-naming GGUF, which is resolved by heuristic majority vote and silently aliases the rest. Demoted to DEBUG: the four SageAttention kernel-selection lines, model discovery, shard counts, per-retry download attempts, attention-mode confirmation and the save_pretrained notice. Kept at INFO: generation complete, transcription results, model downloads and load starts. Judgement calls recorded in docs/2026-10-01-vv-logging-cleanup-design.md. The two I am least sure of: the ungated memory-census profile line was demoted rather than gated (adding a gate would not be presentation-only), and patcher.py's "Loading VibeVoice models for..." was kept at INFO against the ask's example list because it is the only load-start line the package has. 48 new tests in tests/test_logging_idiom.py plus tests/test_audio_utils.py: byte-exact ColoredFormatter rendering, no-leftover-machinery, AST prefix and two-direction level policy, and the 44.1 kHz resample regression (the call still fires with (44100, 24000); nothing is logged). 37 caplog.at_level pins that named a module logger were stripped -- they only lowered a named logger and left root at WARNING, so the record was discarded before capture. Gate: 1924 passed, 30 skipped, 0 failed (1876 before this change). Twelve deliberate mutations -- re-deleting a message, re-leveling, re-adding setLevel and propagate=False, stripping a prefix, moving the resample out of its branch -- were each caught by at least one test. Not run: ComfyUI was never launched and no checkpoint was loaded.
172 lines
6.8 KiB
Python
172 lines
6.8 KiB
Python
"""Tests for the sampled-PEAK half of the RAM census (task fp8-peak).
|
|
|
|
``census`` inventories the storages a model HOLDS; it cannot see a transient
|
|
— and the 7B fp8 report is a transient (+17GB, gone before the post-H2D
|
|
census). These tests cover the instrument that does see it: a background
|
|
sampler over the process working set, private resident set and commit.
|
|
|
|
Scale note: the real event is 8.82GiB, so nothing here loads a model. The
|
|
sampler is exercised with a few MiB of Python buffers held across a
|
|
synchronous ``sample()``, which is the same mechanism at 1/1000 the size —
|
|
the assertions are about WHAT is tracked, never about the magnitudes.
|
|
"""
|
|
|
|
import time
|
|
|
|
import pytest
|
|
|
|
from ComfyUI_VibeVoice.modules.memory_census import (
|
|
RssSampler,
|
|
memory_snapshot,
|
|
peak_delta,
|
|
rss_bytes,
|
|
)
|
|
|
|
|
|
def _touch_mib(mib: int) -> list:
|
|
"""Touch ``mib`` MiB of real, touched memory and keep it alive."""
|
|
blocks = [bytearray(1024 * 1024) for _ in range(mib)]
|
|
for block in blocks:
|
|
block[0] = 1
|
|
block[-1] = 1
|
|
return blocks
|
|
|
|
|
|
#: How far two consecutive live process readings may drift before the test
|
|
#: treats it as a real disagreement. A full-suite pytest process has other
|
|
#: threads (torch's autotuner, ComfyUI's samplers) touching pages, and the
|
|
#: observed drift is a few hundred KB; 64 MiB is far above that noise and far
|
|
#: below the 96 MiB blocks these tests hold, so it cannot mask a genuine
|
|
#: divergence between the two readers.
|
|
_READING_DRIFT_TOLERANCE = 64 * 1024 * 1024
|
|
|
|
|
|
class TestMemorySnapshot:
|
|
def test_reports_all_three_quantities(self):
|
|
snapshot = memory_snapshot()
|
|
# The three PROCESS counters are the contract. ``sys_used``
|
|
# (machine-wide RAM) rides along so a [vvrss] line can attribute a
|
|
# jump to this process or to the box, so assert the required keys are
|
|
# present rather than pinning the whole key set.
|
|
assert {"ws", "uss", "private"} <= set(snapshot)
|
|
assert snapshot["ws"] > 0, "this platform must be able to read a working set"
|
|
assert snapshot["uss"] > 0
|
|
assert snapshot["private"] > 0
|
|
|
|
def test_rss_bytes_is_the_two_tuple_shorthand(self):
|
|
# These are TWO SEPARATE live readings of a MOVING process: a
|
|
# background thread in a full-suite run can add or drop pages between
|
|
# the calls. The contract under test is that ``rss_bytes`` is the
|
|
# two-tuple shorthand over the SAME reader, not that the OS returns an
|
|
# identical number twice — asserting equality made this test fail
|
|
# ~1 run in 2 on process-wide drift of a few hundred KB.
|
|
ws, private = rss_bytes()
|
|
snapshot = memory_snapshot()
|
|
for name, before, after in (
|
|
("ws", ws, snapshot["ws"]),
|
|
("private", private, snapshot["private"]),
|
|
):
|
|
drift = abs(after - before)
|
|
assert drift <= _READING_DRIFT_TOLERANCE, (
|
|
f"{name} drifted {drift} B between two consecutive readings; "
|
|
"if this is a real disagreement rather than process noise, "
|
|
"rss_bytes and memory_snapshot have diverged"
|
|
)
|
|
|
|
|
|
class TestRssSampler:
|
|
def test_catches_a_transient_a_post_hoc_reading_cannot(self):
|
|
"""The whole reason the sampler exists, in miniature.
|
|
|
|
Hold memory across a synchronous sample, then release it BEFORE the
|
|
final reading. A post-hoc delta sees nothing; the peak must still
|
|
report it.
|
|
"""
|
|
before = rss_bytes()[0]
|
|
with RssSampler(interval=0.01) as sampler:
|
|
held = _touch_mib(96)
|
|
sampler.mark("held")
|
|
del held
|
|
assert sampler.peak["ws"] > before, "peak must include the freed block"
|
|
# ...and the END reading is back near the start, which is exactly the
|
|
# shape of the reported defect: a spike that resolves.
|
|
assert sampler.end["ws"] < sampler.peak["ws"]
|
|
|
|
def test_stops_its_thread_and_keeps_sampling(self):
|
|
with RssSampler(interval=0.01) as sampler:
|
|
held = _touch_mib(32)
|
|
time.sleep(0.05)
|
|
del held
|
|
first = sampler.samples
|
|
time.sleep(0.05)
|
|
assert sampler.samples == first, "__exit__ must stop the sampling thread"
|
|
assert first > 1
|
|
|
|
def test_marks_record_reading_and_running_peak(self):
|
|
with RssSampler() as sampler:
|
|
sampler.mark("start")
|
|
held = _touch_mib(48)
|
|
sampler.mark("held")
|
|
del held
|
|
labels = [label for label, _snapshot, _peak in sampler.marks]
|
|
assert labels == ["start", "held"]
|
|
held_reading = dict(sampler.marks[1][1])
|
|
held_peak = dict(sampler.marks[1][2])
|
|
assert held_peak["ws"] >= held_reading["ws"]
|
|
assert held_peak["ws"] == sampler.peak["ws"]
|
|
|
|
def test_line_names_every_quantity_it_tracks(self):
|
|
with RssSampler() as sampler:
|
|
pass
|
|
line = sampler.line("phase-test")
|
|
assert line.startswith("[vvrss] phase-test")
|
|
for token in ("peak_ws=", "peak_uss=", "peak_private=",
|
|
"start_ws=", "end_ws=", "samples="):
|
|
assert token in line
|
|
|
|
def test_report_respects_the_env_gate(self, monkeypatch, caplog):
|
|
import logging
|
|
|
|
with RssSampler() as sampler:
|
|
pass
|
|
monkeypatch.setenv("VIBEVOICE_RAM_CENSUS", "0")
|
|
with caplog.at_level(logging.INFO):
|
|
line = sampler.report("silenced")
|
|
assert "[vvrss] silenced" in line
|
|
assert "[vvrss]" not in caplog.text
|
|
|
|
def test_profile_is_off_without_a_series(self):
|
|
assert "profile=off" in RssSampler().profile()
|
|
|
|
def test_profile_renders_one_bucket_per_column(self):
|
|
with RssSampler(interval=0.01, series=True) as sampler:
|
|
held = _touch_mib(64)
|
|
time.sleep(0.05)
|
|
del held
|
|
line = sampler.profile(buckets=8)
|
|
assert "timeline" in line
|
|
# One block character per bucket, between the ")" and the peak.
|
|
blocks = line.split(") ", 1)[1].split(" peak=", 1)[0]
|
|
assert len(blocks) == 8
|
|
assert all(char in " ▁▂▃▄▅▆▇█" for char in blocks)
|
|
|
|
|
|
class TestPeakDelta:
|
|
def test_reports_ws_and_private_deltas_against_a_baseline(self):
|
|
with RssSampler() as sampler:
|
|
held = _touch_mib(64)
|
|
sampler.mark("held")
|
|
del held
|
|
delta = peak_delta(sampler, baseline=sampler.peak["ws"] - (16 << 20))
|
|
assert delta["baseline"] > 0
|
|
assert delta["peak_ws_delta"] == pytest.approx(16 << 20, rel=0.01)
|
|
assert delta["peak_uss_delta"] >= 0
|
|
assert delta["samples"] == sampler.samples
|
|
|
|
def test_never_reports_a_negative_delta(self):
|
|
with RssSampler() as sampler:
|
|
pass
|
|
delta = peak_delta(sampler, baseline=sampler.peak["ws"] + (1 << 30))
|
|
assert delta["peak_ws_delta"] == 0
|
|
assert delta["peak_uss_delta"] == 0
|