Stop paying for the [TILEDBG] diagnostics when debug logging is off

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:

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