diff --git a/anyplotlib/plot2d/_plot2d.py b/anyplotlib/plot2d/_plot2d.py index d9c092df..c1aaa1dd 100644 --- a/anyplotlib/plot2d/_plot2d.py +++ b/anyplotlib/plot2d/_plot2d.py @@ -568,13 +568,17 @@ def _refresh_overview(self) -> None: self._state["base_width"] = int(ow) self._state["base_height"] = int(oh) self._overview_stale = False - _TLOG.debug( - "[TILEDBG] overview refresh: overview=%s u8[min=%d max=%d] " - "display=(%s,%s) base_wh=(%d,%d) image_wh=(%s,%s)", (oh, ow), - int(img_u8.min()), int(img_u8.max()), - self._state.get("display_min"), self._state.get("display_max"), - ow, oh, self._state.get("image_width"), - self._state.get("image_height")) + # min/max are two more full passes over the overview — same guard rule + # as the FETCH diagnostic below (they are .debug() ARGUMENTS, so lazy + # formatting does not skip them). + if _TLOG.isEnabledFor(logging.DEBUG): + _TLOG.debug( + "[TILEDBG] overview refresh: overview=%s u8[min=%d max=%d] " + "display=(%s,%s) base_wh=(%d,%d) image_wh=(%s,%s)", (oh, ow), + int(img_u8.min()), int(img_u8.max()), + self._state.get("display_min"), self._state.get("display_max"), + ow, oh, self._state.get("image_width"), + self._state.get("image_height")) except Exception as e: _TLOG.warning("[TILEDBG] overview refresh FAILED: %s", e) @@ -648,28 +652,47 @@ def _on_view_changed_internal(self, event) -> None: else: out_h, out_w = dh, max(1, int(round(dh * aspect))) b = self._tile_backend - # DIAGNOSTIC: the raw native region straight from the backend, BEFORE - # sampling — its shape + distinct-value count tells us whether the backend - # actually holds native pixels. If region is 82×82 but the raw crop has - # only ~100 distinct values, the backend source is a downsample (bug). - _raw = np.asarray(b._a[y0:y1, x0:x1]) if hasattr(b, "_a") else None tile = self._tile_backend.sample( x0, x1, y0, y1, out_w, out_h, self._integration_method) if b.origin == "lower": tile = np.flipud(tile) self.set_detail(np.ascontiguousarray(tile), x0, x1, y0, y1) - _bshape = b.full_shape if hasattr(b, "full_shape") else "?" - _rawinfo = ("raw_crop=%s distinct=%d" % ( - _raw.shape, int(np.unique(_raw).size))) if _raw is not None else "raw=?" - _tileinfo = "tile_distinct=%d" % int(np.unique(np.asarray(tile)).size) + # The FETCH diagnostic sorts the raw native crop and the tile + # (np.unique) — 259 ms on a 4096² frame at the zoom where VIEW_OVERFETCH + # makes the crop the whole image. Those were arguments to a .debug() + # call, so lazy %-formatting did NOT save them: every pan paid for them + # at any log level. Guard the whole block, never inline it again. + if _TLOG.isEnabledFor(logging.DEBUG): + self._log_fetch_diagnostic( + b, tile, zoom, x0, x1, y0, y1, rw, rh, out_w, out_h) + except Exception as e: + _TLOG.warning("[TILEDBG] view_changed tile update FAILED: %s", e) + + def _log_fetch_diagnostic(self, b, tile, zoom, x0, x1, y0, y1, rw, rh, + out_w, out_h) -> None: + """The expensive [TILEDBG] FETCH line — only ever call this behind an + ``isEnabledFor(DEBUG)`` guard. + + The distinct-value counts are the point of it: if the requested region is + 82×82 but the backend's raw crop has only ~100 distinct values, the backend + source is a downsample rather than native pixels (a real bug this caught). + Both counts are full sorts of up to 16 M pixels, hence the guard.""" + try: + raw = np.asarray(b._a[y0:y1, x0:x1]) if hasattr(b, "_a") else None + rawinfo = ("raw_crop=%s distinct=%d" + % (raw.shape, int(np.unique(raw).size)) + ) if raw is not None else "raw=?" + arr = np.asarray(tile) _TLOG.debug( "[TILEDBG] view_changed FETCH zoom=%.2f region=[x %d:%d y %d:%d] " - "(%dx%d logical) BACKEND_shape=%s %s → tile=%dx%d %s " - "u8[min=%d max=%d]", - zoom, x0, x1, y0, y1, rw, rh, _bshape, _rawinfo, out_w, out_h, - _tileinfo, int(np.asarray(tile).min()), int(np.asarray(tile).max())) + "(%dx%d logical) BACKEND_shape=%s %s → tile=%dx%d " + "tile_distinct=%d u8[min=%d max=%d]", + zoom, x0, x1, y0, y1, rw, rh, + b.full_shape if hasattr(b, "full_shape") else "?", rawinfo, + out_w, out_h, int(np.unique(arr).size), + int(arr.min()), int(arr.max())) except Exception as e: - _TLOG.warning("[TILEDBG] view_changed tile update FAILED: %s", e) + _TLOG.debug("[TILEDBG] FETCH diagnostic failed: %s", e) @staticmethod def _encode_bytes(arr: np.ndarray) -> str: diff --git a/anyplotlib/tests/test_plot2d/test_tile_diagnostics.py b/anyplotlib/tests/test_plot2d/test_tile_diagnostics.py new file mode 100644 index 00000000..ddf849b5 --- /dev/null +++ b/anyplotlib/tests/test_plot2d/test_tile_diagnostics.py @@ -0,0 +1,88 @@ +"""The [TILEDBG] diagnostics must cost NOTHING unless debug logging is on. + +``_on_view_changed_internal`` reports the distinct-value counts of the backend's +raw native crop and of the sampled tile, which is genuinely useful (it catches a +backend that hands back a downsample instead of native pixels). But both are +``np.unique`` — full sorts — and they were passed as ARGUMENTS to ``_TLOG.debug``. +Lazy %-formatting does not help there: the arguments are evaluated before the +call, so every pan/zoom paid for them at any log level. Measured on a 4096² frame +with VIEW_OVERFETCH=2.0, where the over-fetched crop is the whole image: 259 ms +per pan for the raw crop plus 12 ms for the tile. + +These tests pin the GUARD, not the message text. +""" +from __future__ import annotations + +import logging + +import numpy as np + +import anyplotlib as apl +from anyplotlib.callbacks import Event +import anyplotlib.plot2d._plot2d as _p2 + + +TILE_LOG = "anyplotlib.tile" + + +def _tiled_plot(edge=1024): + p = apl.subplots(1, 1)[1].imshow(np.zeros((10, 10), np.float32)) + p.set_data(np.random.RandomState(0).rand(edge, edge).astype(np.float32), + clim=(0, 1), tile=True) + return p + + +def _pan(p, zoom=4.0, cx=0.5, cy=0.5): + p.callbacks.fire(Event("view_changed", zoom=zoom, center_x=cx, center_y=cy, + display_width=800, display_height=800)) + + +class _CountUnique: + """Count np.unique calls without changing what it returns.""" + + def __init__(self, monkeypatch): + self.n = 0 + real = np.unique + def counting(*a, **k): + self.n += 1 + return real(*a, **k) + monkeypatch.setattr(_p2.np, "unique", counting) + + +class TestFetchDiagnosticIsGuarded: + def test_pan_does_no_sorting_at_info_level(self, monkeypatch): + logger = logging.getLogger(TILE_LOG) + monkeypatch.setattr(logger, "level", logging.INFO) + p = _tiled_plot() + counter = _CountUnique(monkeypatch) # after setup, so only the pan counts + _pan(p) + assert p._state["detail_region"], "the detail tile must still be fetched" + assert counter.n == 0, ( + f"np.unique ran {counter.n}x on a pan with debug logging off — the " + f"[TILEDBG] diagnostic is unguarded again (259 ms/pan on a 4096² frame)") + + def test_diagnostic_still_runs_at_debug_level(self, monkeypatch, caplog): + logger = logging.getLogger(TILE_LOG) + monkeypatch.setattr(logger, "level", logging.DEBUG) + p = _tiled_plot() + counter = _CountUnique(monkeypatch) + with caplog.at_level(logging.DEBUG, logger=TILE_LOG): + _pan(p) + assert counter.n >= 1, "the distinct-value diagnostic must survive at DEBUG" + assert any("view_changed FETCH" in r.message for r in caplog.records), \ + "the FETCH line itself must still be emitted at DEBUG" + + def test_tile_content_is_unchanged_by_the_guard(self, monkeypatch): + """The guard must not alter what gets displayed — same region, same tile.""" + logger = logging.getLogger(TILE_LOG) + p = _tiled_plot() + monkeypatch.setattr(logger, "level", logging.DEBUG) + _pan(p, zoom=4.0) + dbg = (list(p._state["detail_region"]), p._state["detail_width"], + p._state["detail_height"], p._state["detail_b64"]) + p2 = _tiled_plot() + monkeypatch.setattr(logger, "level", logging.INFO) + _pan(p2, zoom=4.0) + quiet = (list(p2._state["detail_region"]), p2._state["detail_width"], + p2._state["detail_height"], p2._state["detail_b64"]) + assert dbg == quiet