Add logging (#58)

* add logging

* delete old docs

Author: kevinyamauchi

docs/cellier_controller_phase1_plan.md

@@ -0,0 +1,180 @@
+# Debug Logging
+
+Cellier v2 includes structured debug logging for the rendering pipeline. By
+default all loggers are silent (level `WARNING`). You opt in to the output you
+need — by category and by level — so there is zero noise until you ask for it
+and zero runtime cost in production.
+
+## Categories
+
+There are four independent loggers, each covering a different part of the
+pipeline:
+
+| Category | Logger name | What it covers |
+|----------|-------------------------|------------------------------------------------|
+| `perf` | `cellier.render.perf` | Planning timing, fetch latency statistics |
+| `gpu` | `cellier.render.gpu` | Brick/tile writes, LUT rebuilds |
+| `cache` | `cellier.render.cache` | Cache hit/miss summaries, eviction, clear |
+| `slicer` | `cellier.render.slicer` | Async task lifecycle, batch progress |
+
+All four live under the `cellier.render` parent logger, so standard Python
+logging hierarchy applies.
+
+## Log levels
+
+Each category uses three levels:
+
+| Level | What you see |
+|-----------|--------------------------------------------------------------|
+| `WARNING` | Anomalies only (e.g. cache budget exceeded). **Default.** |
+| `INFO` | Per-frame / per-batch summaries — the useful overview. |
+| `DEBUG` | Per-brick / per-tile detail — full firehose for deep debugging. |
+
+### What each level looks like in practice
+
+**`WARNING`** — only fires when something is wrong:
+
+```
+PERF  budget_exceeded  required=500  budget=256  dropped=244
+```
+
+**`INFO`** — one or two lines per frame / per batch:
+
+```
+PERF   [frame 7]  lod_select=1.2ms  dist_sort=0.3ms  frustum_cull=0.8ms  stage=0.1ms  |  required=142  culled=40  hits=130  misses=12
+PERF   fetch_summary  status=complete  bricks=12  batches=2  total=58ms  per_batch=28.3±5.1ms  min=23.2ms  max=33.4ms
+CACHE  cache_state  frame=7  occupied=130/512  free=382  hits=130  misses=12  evictions=0
+SLICER batch_done  1/2  bricks=8  scales={0: 5, 1: 3}
+GPU    gpu_flush  bricks_in_batch=8  resident=138
+```
+
+**`DEBUG`** — per-brick detail inside each batch:
+
+```
+PERF     fetch_batch  1/2  bricks=8  elapsed=23.2ms
+SLICER     brick_received  id=abc123  scale=0  shape=(34, 34, 34)
+CACHE    evict  victim=BlockKey3D(level=1, gz=0, gy=2, gx=3)  slot=42
+GPU      brick_written  key=BlockKey3D(level=1, gz=0, gy=1, gx=2)  slot=7  grid_pos=(0, 0, 7)
+```
+
+## Quick start
+
+### Enable all categories at DEBUG (full output)
+
+```python
+from cellier.v2.logging import enable_debug_logging
+
+enable_debug_logging()
+```
+
+### Enable specific categories
+
+```python
+enable_debug_logging(categories=("perf", "cache"))
+```
+
+### Summaries only (INFO level)
+
+```python
+import logging
+from cellier.v2.logging import enable_debug_logging, _CATEGORY_MAP
+
+# Enable the handler infrastructure (sets everything to DEBUG).
+enable_debug_logging()
+
+# Override: set all categories to INFO so per-brick detail is suppressed.
+for logger in _CATEGORY_MAP.values():
+    logger.setLevel(logging.INFO)
+```
+
+### Mixed levels
+
+```python
+import logging
+from cellier.v2.logging import enable_debug_logging, _CATEGORY_MAP
+
+enable_debug_logging(categories=("perf", "cache"))
+
+# Summaries for perf, full detail for cache.
+_CATEGORY_MAP["perf"].setLevel(logging.INFO)
+_CATEGORY_MAP["cache"].setLevel(logging.DEBUG)
+```
+
+### Disable logging
+
+```python
+from cellier.v2.logging import disable_debug_logging
+
+disable_debug_logging()
+```
+
+This resets all category loggers to `WARNING` and removes the handler.
+
+### Plain output (no Rich)
+
+```python
+enable_debug_logging(use_rich=False)
+```
+
+Falls back to a plain `StreamHandler` with timestamps. Useful in CI or when
+Rich is not installed.
+
+## Rich colored output
+
+If the `rich` package is installed (`pip install cellier[logging]`), the
+default handler colors each category:
+
+| Category | Color |
+|----------|---------|
+| PERF | cyan |
+| GPU | green |
+| CACHE | yellow |
+| SLICER | magenta |
+
+If Rich is not available, output falls back to a plain `StreamHandler`
+automatically.
+
+## How it works under the hood
+
+All cellier loggers start at Python's default level (`WARNING`).
+`enable_debug_logging()` does two things:
+
+1. Sets the requested category loggers to `DEBUG`.
+2. Attaches a handler to the `cellier.render` parent logger (once only).
+
+Every log call in the instrumented code is either:
+
+- Emitted unconditionally (for `INFO` / `WARNING` calls, which are
+  infrequent).
+- Guarded by `if logger.isEnabledFor(logging.DEBUG)` (for hot loops over
+  bricks/tiles), so there is zero string formatting cost when DEBUG is off.
+
+Because the loggers are standard `logging.Logger` instances, you can
+integrate them into any existing logging configuration (file handlers,
+JSON formatters, external aggregation) using the logger names listed above.
+
+## Fetch latency timing
+
+The `perf` category includes fetch latency instrumentation for async data
+loading. This is especially useful when working with remote data stores
+where network I/O dominates.
+
+At **INFO**, a single summary line is emitted when a fetch task completes
+(or is cancelled):
+
+```
+PERF  fetch_summary  status=complete  bricks=96  batches=12  total=340ms  per_batch=28.3±5.1ms  min=19.0ms  max=42.0ms
+```
+
+- `total` — wall-clock time from first batch to last, including callback
+  overhead (GPU commit, LUT rebuild, Qt yield) between batches.
+- `per_batch` — mean ± std of the I/O-only time for each `asyncio.gather()`
+  call. This isolates the storage backend latency from the rendering overhead.
+- `min` / `max` — fastest and slowest batch, useful for spotting tail
+  latency spikes.
+
+At **DEBUG**, each batch gets its own timing line as it completes:
+
+```
+PERF  fetch_batch  3/12  bricks=8  elapsed=31.2ms
+```

docs/cellier_v2_eventbus_implementation_plan.md

@@ -68,11 +68,14 @@ dev = [
     "ruff",
 ]
 
+# optional rich-powered debug logging
+logging = ["rich>=13.0"]
+
 # dependencies for the example scripts
 examples = ["scikit-image"]
 
 # get all dependencies for development
-dev-all = ["cellier[dev,test,pyqt,examples]"]
+dev-all = ["cellier[dev,test,pyqt,examples,logging]"]
 
 [project.urls]
 homepage = "https://github.com/kevinyamauchi/cellier"

docs/cellier_v2_render_architecture_plan.md

@@ -64,6 +64,72 @@
 from cellier.v2.scene.dims import CoordinateSystem
 from cellier.v2.visuals._image import ImageAppearance
 
+# ---------------------------------------------------------------------------
+# Debug-logging CLI helper (power-user per-category:level syntax)
+# ---------------------------------------------------------------------------
+
+
+def _setup_debug_logging(spec: str) -> None:
+    """Parse ``--debug-log`` spec and configure cellier loggers.
+
+    Supports several forms::
+
+        "all"                           -> all categories at DEBUG
+        "all:info"                      -> all categories at INFO
+        "perf,cache"                    -> perf+cache at DEBUG
+        "perf:info,cache:debug"         -> per-category levels
+
+    A bare category name (no colon) defaults to DEBUG.
+    """
+    import logging as _logging
+
+    from cellier.v2.logging import _CATEGORY_MAP, enable_debug_logging
+
+    _LEVEL_NAMES = {
+        "debug": _logging.DEBUG,
+        "info": _logging.INFO,
+        "warning": _logging.WARNING,
+    }
+
+    # Parse spec into {category: level_int} pairs.
+    overrides: dict[str, int] = {}
+    all_cats = tuple(_CATEGORY_MAP.keys())
+    default_level = _logging.DEBUG
+
+    if spec in ("", "all"):
+        # All categories at DEBUG — no overrides needed.
+        pass
+    elif spec.startswith("all:"):
+        level_str = spec.split(":", 1)[1].strip().lower()
+        default_level = _LEVEL_NAMES.get(level_str, _logging.DEBUG)
+    else:
+        for token in spec.split(","):
+            token = token.strip()
+            if ":" in token:
+                cat, level_str = token.split(":", 1)
+                overrides[cat.strip()] = _LEVEL_NAMES.get(
+                    level_str.strip().lower(), _logging.DEBUG
+                )
+            else:
+                overrides[token] = _logging.DEBUG
+
+    # Determine which categories to enable.
+    if overrides:
+        cats = tuple(overrides.keys())
+    else:
+        cats = all_cats
+
+    # Step 1: enable handler + set all requested categories to DEBUG.
+    enable_debug_logging(categories=cats)
+
+    # Step 2: apply per-category level overrides (or global default).
+    for cat in cats:
+        target_level = overrides.get(cat, default_level)
+        logger = _CATEGORY_MAP.get(cat)
+        if logger is not None:
+            logger.setLevel(target_level)
+
+
 # ---------------------------------------------------------------------------
 # Constants
 # ---------------------------------------------------------------------------
@@ -563,6 +629,24 @@ def main() -> None:
         default=ZARR_PATH,
         help="Path to the multiscale zarr store.",
     )
+    parser.add_argument(
+        "--debug-log",
+        metavar="SPEC",
+        default=None,
+        const="all",
+        nargs="?",
+        help=(
+            "Enable debug logging. Comma-separated list of categories "
+            "(perf, gpu, cache, slicer). "
+            "Omit value or use 'all' for all categories at DEBUG level. "
+            "Power-user: append :LEVEL to set per-category levels. "
+            "Examples:\n"
+            "  --debug-log                    (all at DEBUG)\n"
+            "  --debug-log perf,cache         (perf+cache at DEBUG)\n"
+            "  --debug-log all:info           (all at INFO — summaries only)\n"
+            "  --debug-log perf:info,cache:debug,slicer:info"
+        ),
+    )
     args = parser.parse_args()
 
     if not args.zarr_path.exists():
@@ -571,6 +655,9 @@ def main() -> None:
         print("    uv run example.py --make-files")
         sys.exit(1)
 
+    if args.debug_log is not None:
+        _setup_debug_logging(args.debug_log)
+
     print("Opening tensorstore stores via MultiscaleZarrDataStore ...")
     data_store = MultiscaleZarrDataStore(
         zarr_path=str(args.zarr_path),
@@ -580,6 +667,9 @@ def main() -> None:
     for i, shape in enumerate(data_store.level_shapes):
         print(f"  s{i}: shape={shape}")
     print()
+    print(
+        "Debug logging: --debug-log [SPEC]  " "(e.g. all:info, perf:info,cache:debug)"
+    )
     print("Press 'Update' to render.  " "Toggle between 2D and 3D with the button.\n")
 
     _app = QApplication([sys.argv[0]])