time measurement

.env.example

@@ -14,6 +14,7 @@ DELETE_SOURCE=true
 UPDATER_ENABLED=true
 UPDATER_SCHEDULE=0 19 * * 1,4
 COVER_CACHE_PATH=/config/covers
+PERF_PATH=/config/perf_stats.json
 
 # Light-novel container (kavita-lightnovel-metadata-fetcher)
 HOST_LN_CONFIG_PATH=/path/to/ln-config

docker-compose.prod.yml

@@ -21,6 +21,8 @@ services:
       UPDATER_LOG:      "/config/volume_updater.log"
       # Persistent cover cache (empty = temp dir, deleted on container stop)
       COVER_CACHE_PATH: "${COVER_CACHE_PATH:-/config/covers}"
+      # Per-step move timing stats (viewable at /perf); empty disables it
+      PERF_PATH:        "${PERF_PATH:-/config/perf_stats.json}"
       # Timezone for the cron schedule — without this 19:00 means 19:00 UTC
       TZ:               "${TZ:-Europe/Berlin}"
     ports:

main_manga.py

@@ -35,6 +35,8 @@ Environment variables
     UPDATER_LOG         default /config/volume_updater.log
     COVER_CACHE_PATH    directory for the persistent cover cache;
                         empty (default) = temporary cache, deleted on exit
+    PERF_PATH           JSON file for per-step move timing stats;
+                        empty disables profiling. Default /config/perf_stats.json
 """
 
 from __future__ import annotations
@@ -61,6 +63,7 @@ from SuwayomiFolderWatcher import SuwayomiFolderWatcher        # noqa: E402,F401
 from MatchesCache import MatchesCache                          # noqa: E402
 from MatchesWebApp import MatchesWebApp                        # noqa: E402
 from KavitaVolumeCoverUpdater import KavitaVolumeCoverUpdater  # noqa: E402
+from PerfStats import PerfStats                                # noqa: E402
 
 
 def _env_str(name: str, default: "str | None" = None,
@@ -107,6 +110,7 @@ def main() -> int:
     updater_schedule = _env_str("UPDATER_SCHEDULE", "0 19 * * 1,4")
     updater_log      = _env_str("UPDATER_LOG", "/config/volume_updater.log")
     cover_cache_path = _env_str("COVER_CACHE_PATH", "") or None
+    perf_path        = _env_str("PERF_PATH", "/config/perf_stats.json") or None
 
     print(f"[main] suwayomi  = {suwayomi_path}",  flush=True)
     print(f"[main] kavita    = {kavita_path}",    flush=True)
@@ -118,6 +122,7 @@ def main() -> int:
     print(f"[main] web       = {web_host}:{web_port}", flush=True)
 
     matches_cache = MatchesCache(match_path)
+    perf_stats = PerfStats(perf_path)
 
     mover = SuwayomiMover(
         suwayomi_path, kavita_path,
@@ -128,11 +133,13 @@ def main() -> int:
         delete_source=delete_source,
         matches_cache=matches_cache,
         cover_cache_dir=cover_cache_path,
+        perf_stats=perf_stats,
     )
 
     # watcher = SuwayomiFolderWatcher(suwayomi_path, mover, settle_seconds=settle_seconds)
 
-    web_app = MatchesWebApp(matches_cache, mover=mover, host=web_host, port=web_port)
+    web_app = MatchesWebApp(matches_cache, mover=mover, perf_stats=perf_stats,
+                            host=web_host, port=web_port)
     web_app.start()
 
     if updater_enabled:

src/manga/ComicInfoBuilder.py

@@ -40,6 +40,7 @@ from __future__ import annotations
 import re
 import sys
 import xml.etree.ElementTree as ET
+from contextlib import contextmanager
 from pathlib import Path
 
 import requests
@@ -65,6 +66,12 @@ except ImportError:
     _HAS_PIL = False
 
 
+@contextmanager
+def _no_measure():
+    """No-op stand-in for a perf recorder's measure() context manager."""
+    yield
+
+
 # --------------------------------------------------------------------------
 # Constants
 # --------------------------------------------------------------------------
@@ -218,6 +225,12 @@ class ComicInfoBuilder:
         self._matches_cache = matches_cache
         self._cover_cache = cover_cache or _default_cover_cache()
 
+        # Optional performance recorder (duck-typed: any object with a
+        # .measure(name) context manager).  The mover sets this per chapter;
+        # when None, _measure() is a no-op so the builder stays decoupled
+        # from PerfStats and works standalone (e.g. the cover updater).
+        self.perf = None
+
         self._metadata: "dict | None" = None
         self._pages: list[dict] = []
         self._cover_path: "Path | None" = None
@@ -262,6 +275,12 @@ class ComicInfoBuilder:
         self._cover_path = None
         self._suwayomi_data = {}
 
+    def _measure(self, name: str):
+        """Times a named step on the attached recorder; no-op when unset."""
+        if self.perf is not None:
+            return self.perf.measure(name)
+        return _no_measure()
+
     # ======================================================================
     # Public XML functions
     # ======================================================================
@@ -305,11 +324,13 @@ class ComicInfoBuilder:
         if not folder.is_dir():
             raise NotADirectoryError(f"Folder not found: {folder}")
 
-        self._suwayomi_data = self._read_existing_comicinfo(folder)
+        with self._measure("read_comicinfo"):
+            self._suwayomi_data = self._read_existing_comicinfo(folder)
 
         self._cover_path = None
         if download_cover:
-            self._cover_path = self._download_cover(folder, cover_filename)
+            with self._measure("cover"):
+                self._cover_path = self._download_cover(folder, cover_filename)
 
         cover_resolved = self._cover_path.resolve() if self._cover_path else None
         story_images: list[Path] = []
@@ -329,20 +350,23 @@ class ComicInfoBuilder:
         ordered.extend((img, "Story") for img in story_images)
 
         self._pages = []
-        for index, (img_path, page_type) in enumerate(ordered):
-            width, height = self._image_dimensions(img_path)
-            try:
-                size = img_path.stat().st_size
-            except OSError:
-                size = None
-            self._pages.append({
-                "image": index,
-                "type": page_type,
-                "width": width,
-                "height": height,
-                "size": size,
-                "double": bool(width and height and width > height),
-            })
+        # Probing every page for its pixel dimensions reads each file — on a
+        # network share this is often the dominant per-chapter cost.
+        with self._measure("image_dimensions"):
+            for index, (img_path, page_type) in enumerate(ordered):
+                width, height = self._image_dimensions(img_path)
+                try:
+                    size = img_path.stat().st_size
+                except OSError:
+                    size = None
+                self._pages.append({
+                    "image": index,
+                    "type": page_type,
+                    "width": width,
+                    "height": height,
+                    "size": size,
+                    "double": bool(width and height and width > height),
+                })
 
         return {
             "page_count": len(self._pages),

src/manga/MatchesWebApp.py

@@ -71,6 +71,7 @@ _INDEX_HTML = """<!doctype html>
   <button id="batchSave" class="primary">Save dirty (0)</button>
   <button id="build">Build all (rescan)</button>
   <button id="move">Start move</button>
+  <a href="/perf" style="margin-left:.5rem;color:#60a5fa;">Performance ▸</a>
   <span class="status" id="status"></span>
 </div>
 
@@ -357,6 +358,135 @@ load();
 """
 
 
+_PERF_HTML = """<!doctype html>
+<html lang="en">
+<head>
+  <meta charset="utf-8">
+  <title>Move performance</title>
+  <style>
+    body  { font-family: system-ui, sans-serif; margin: 1.5rem; background: #111; color: #eee; }
+    h1    { margin: 0 0 1rem; font-size: 1.4rem; }
+    h2    { font-size: 1.05rem; margin: 1.4rem 0 .5rem; color:#cbd5e1; }
+    a     { color:#60a5fa; text-decoration:none; }
+    a:hover { text-decoration:underline; }
+    .bar  { display:flex; gap:.6rem; align-items:center; margin-bottom:1rem; flex-wrap:wrap; }
+    select, button { padding:.35rem .6rem; background:#222; color:#eee; border:1px solid #555; }
+    .summary { color:#9ca3af; margin:.3rem 0 1rem; }
+    table { border-collapse: collapse; width: 100%; margin-bottom:.5rem; }
+    th, td { border: 1px solid #333; padding: .35rem .6rem; text-align: left; }
+    th { background:#1d1d1d; }
+    td.num { text-align:right; font-variant-numeric: tabular-nums; white-space:nowrap; }
+    .barcell { position:relative; }
+    .barfill { position:absolute; left:0; top:0; bottom:0; background:#2563eb33; z-index:0; }
+    .barcell span { position:relative; z-index:1; }
+    details { margin:.3rem 0; }
+    summary { cursor:pointer; padding:.25rem 0; }
+    .chip { color:#9ca3af; font-size:.85rem; }
+    .err  { color:#f87171; }
+  </style>
+</head>
+<body>
+<h1>Move performance <a href="/" style="font-size:.9rem;">◂ back to matches</a></h1>
+<div class="bar">
+  <label>Run: <select id="runSelect"></select></label>
+  <button id="reload">Reload</button>
+  <span class="summary" id="summary"></span>
+</div>
+
+<div id="content"></div>
+
+<script>
+let runs = [];
+
+function fmtSecs(s) { return (s || 0).toFixed(2) + "s"; }
+function fmtTime(unix) { return unix ? new Date(unix * 1000).toLocaleString() : ""; }
+
+function stepTable(totals, grandTotal) {
+  const entries = Object.entries(totals || {}).sort((a, b) => b[1] - a[1]);
+  if (!entries.length) return "<p class=chip>(no steps recorded)</p>";
+  const max = entries[0][1] || 1;
+  let rows = "";
+  for (const [name, secs] of entries) {
+    const pct = grandTotal ? (secs / grandTotal * 100) : 0;
+    const w = (secs / max * 100);
+    rows += "<tr><td>" + name + "</td>"
+         + "<td class='num'>" + fmtSecs(secs) + "</td>"
+         + "<td class='num'>" + pct.toFixed(1) + "%</td>"
+         + "<td class='barcell'><div class='barfill' style='width:" + w + "%'></div>"
+         + "<span>&nbsp;</span></td></tr>";
+  }
+  return "<table><thead><tr><th>Step</th><th class=num>Total</th>"
+       + "<th class=num>% of run</th><th>&nbsp;</th></tr></thead><tbody>"
+       + rows + "</tbody></table>";
+}
+
+function seriesBlock(s) {
+  let chapters = "";
+  // Chapters sorted slowest first to surface outliers.
+  const chs = (s.chapters || []).slice().sort((a, b) => b.totalSeconds - a.totalSeconds);
+  for (const c of chs) {
+    const steps = Object.entries(c.steps || {}).sort((a, b) => b[1] - a[1])
+      .map(([n, v]) => n + " " + fmtSecs(v)).join(", ");
+    chapters += "<tr><td>" + c.chapter + (c.ok ? "" : " <span class=err>(failed)</span>") + "</td>"
+             + "<td class='num'>" + fmtSecs(c.totalSeconds) + "</td>"
+             + "<td>" + steps + "</td></tr>";
+  }
+  const seriesSteps = Object.entries(s.steps || {})
+    .map(([n, v]) => n + " " + fmtSecs(v)).join(", ") || "—";
+  return "<details><summary><b>" + s.title + "</b> "
+       + "<span class=chip>" + fmtSecs(s.totalSeconds) + " · "
+       + (s.chapterCount || 0) + " chapters · " + seriesSteps + "</span></summary>"
+       + "<table><thead><tr><th>Chapter</th><th class=num>Total</th>"
+       + "<th>Steps</th></tr></thead><tbody>" + chapters + "</tbody></table></details>";
+}
+
+function renderRun(run) {
+  const c = document.getElementById("content");
+  if (!run) { c.innerHTML = "<p class=chip>No runs recorded yet.</p>"; return; }
+  document.getElementById("summary").textContent =
+    fmtTime(run.startedAt) + " · " + fmtSecs(run.totalSeconds) + " · "
+    + run.seriesCount + " series · " + run.chapterCount + " chapters";
+
+  let html = "<h2>Chapter steps (summed over all chapters)</h2>"
+           + stepTable(run.stepTotals, run.totalSeconds)
+           + "<h2>Series steps (metadata / person sync)</h2>"
+           + stepTable(run.seriesStepTotals, run.totalSeconds)
+           + "<h2>Series detail</h2>";
+  const series = (run.series || []).slice().sort((a, b) => b.totalSeconds - a.totalSeconds);
+  html += series.map(seriesBlock).join("");
+  c.innerHTML = html;
+}
+
+function renderSelect() {
+  const sel = document.getElementById("runSelect");
+  sel.innerHTML = "";
+  runs.forEach((r, i) => {
+    const o = document.createElement("option");
+    o.value = i;
+    o.textContent = fmtTime(r.startedAt) + "  (" + fmtSecs(r.totalSeconds) + ")";
+    sel.appendChild(o);
+  });
+}
+
+async function load() {
+  const r = await fetch("/api/perf");
+  const data = await r.json();
+  runs = data.runs || [];
+  renderSelect();
+  renderRun(runs[0]);
+}
+
+document.getElementById("runSelect").addEventListener("change", e => {
+  renderRun(runs[e.target.value]);
+});
+document.getElementById("reload").addEventListener("click", load);
+load();
+</script>
+</body>
+</html>
+"""
+
+
 class MatchesWebApp:
     """
     Flask app exposing the MatchesCache. `mover` is required when you want
@@ -367,10 +497,12 @@ class MatchesWebApp:
 
     def __init__(self, cache: MatchesCache, *,
                  mover=None,
+                 perf_stats=None,
                  host: str = "0.0.0.0",
                  port: int = 8080):
         self._cache = cache
         self._mover = mover
+        self._perf = perf_stats
         self._host = host
         self._port = port
         self._build_lock = threading.Lock()
@@ -498,3 +630,13 @@ class MatchesWebApp:
             finally:
                 self._move_lock.release()
             return jsonify({"results": results})
+
+        @app.get("/perf")
+        def perf_page() -> Response:
+            return Response(_PERF_HTML, mimetype="text/html; charset=utf-8")
+
+        @app.get("/api/perf")
+        def api_perf():
+            if self._perf is None:
+                return jsonify({"runs": []})
+            return jsonify(self._perf.all())

src/manga/SuwayomiMover.py

@@ -69,6 +69,7 @@ from KavitaPersonUpdater import KavitaPersonUpdater
 from MatchesCache import MatchesCache
 from MangaBakaRateLimit import apply_to_session as _apply_mangabaka_rate_limit
 from CoverCache import CoverCache, _IMAGE_EXTS
+from PerfStats import PerfStats
 
 
 _CHAPTER_RE = re.compile(r'[Cc]hapter\s+(\d+(?:\.\d+)?)')
@@ -313,6 +314,8 @@ class SuwayomiMover:
     delete_source   : Remove the source chapter folder after successful pack.
     cover_cache_dir : Directory for the persistent cover cache.  None ->
                       temporary cache, deleted at process exit.
+    perf_stats      : Optional PerfStats instance for per-step timing.  None
+                      (default) disables profiling.
     """
 
     def __init__(self,
@@ -326,7 +329,8 @@ class SuwayomiMover:
                  delete_source: bool = True,
                  matches_cache: "MatchesCache | None" = None,
                  api_base_url: str = "https://api.mangabaka.dev/v1",
-                 cover_cache_dir=None):
+                 cover_cache_dir=None,
+                 perf_stats: "PerfStats | None" = None):
         self._src = Path(suwayomi_path)
         self._dst = Path(kavita_path)
         self._language = language
@@ -334,6 +338,7 @@ class SuwayomiMover:
         self._delete_source = delete_source
         self._matches_cache = matches_cache
         self._api_base_url = api_base_url.rstrip("/")
+        self._perf = perf_stats or PerfStats(None)
 
         # Shared HTTP session and resolvers — reused across all series/chapters
         # to maximise cache hits and minimise API round-trips.
@@ -376,15 +381,19 @@ class SuwayomiMover:
         dict from _process_series_dir.
         """
         results: dict = {}
-        for source_dir in sorted(self._src.iterdir()):
-            if not source_dir.is_dir():
-                continue
-            for manga_dir in sorted(source_dir.iterdir()):
-                if not manga_dir.is_dir():
+        run = self._perf.begin_run()
+        try:
+            for source_dir in sorted(self._src.iterdir()):
+                if not source_dir.is_dir():
                     continue
-                title = manga_dir.name
-                print(f"[SuwayomiMover] {title}")
-                results[title] = self._process_series_dir(manga_dir)
+                for manga_dir in sorted(source_dir.iterdir()):
+                    if not manga_dir.is_dir():
+                        continue
+                    title = manga_dir.name
+                    print(f"[SuwayomiMover] {title}")
+                    results[title] = self._process_series_dir(manga_dir, run)
+        finally:
+            run.finish()
         return results
 
     def process_series(self, manga_title: str) -> dict:
@@ -400,7 +409,11 @@ class SuwayomiMover:
                 continue
             candidate = source_dir / manga_title
             if candidate.is_dir():
-                return self._process_series_dir(candidate)
+                run = self._perf.begin_run()
+                try:
+                    return self._process_series_dir(candidate, run)
+                finally:
+                    run.finish()
         raise FileNotFoundError(
             f"No Suwayomi directory found for '{manga_title}' under {self._src}")
 
@@ -487,8 +500,9 @@ class SuwayomiMover:
     # ------------------------------------------------------------------
     # Internal: series
     # ------------------------------------------------------------------
-    def _process_series_dir(self, manga_dir: Path) -> dict:
+    def _process_series_dir(self, manga_dir: Path, run=None) -> dict:
         manga_title = manga_dir.name
+        series_rec = (run or self._perf.begin_run()).begin_series(manga_title)
 
         chapter_dirs = sorted(
             (d for d in manga_dir.iterdir() if d.is_dir()),
@@ -539,7 +553,8 @@ class SuwayomiMover:
         md: "dict | None" = None
         mangabaka_title = manga_title
         try:
-            md = builder.fetch_metadata()
+            with series_rec.measure("fetch_metadata"):
+                md = builder.fetch_metadata()
             mangabaka_title = md.get("title") or manga_title
         except Exception as exc:
             print(f"  [warn] metadata fetch failed: {exc}")
@@ -571,7 +586,7 @@ class SuwayomiMover:
         chapter_results: list[dict] = []
         for chapter_dir, _fields, chapter_num in pending:
             result = self._process_chapter(
-                builder, chapter_num, chapter_dir, dest_series)
+                builder, chapter_num, chapter_dir, dest_series, series_rec)
             chapter_results.append(result)
             status = "ok" if result["ok"] else f"ERROR: {result.get('error')}"
             print(f"  Chapter {chapter_num}: {status}")
@@ -592,14 +607,16 @@ class SuwayomiMover:
             al_id  = ComicInfoBuilder._al_id_from_source(md) if md else None
             if mal_id or al_id:
                 try:
-                    person_result = self._person_updater.update_for_manga(
-                        mal_id, al_manga_id=al_id)
+                    with series_rec.measure("person_sync"):
+                        person_result = self._person_updater.update_for_manga(
+                            mal_id, al_manga_id=al_id)
                     print(f"  Persons: chars={person_result['characters'].get('updated')} "
                           f"staff={person_result['staff'].get('updated')}")
                 except Exception as exc:
                     person_result = {"error": str(exc)}
                     print(f"  Persons: ERROR {exc}")
 
+        series_rec.finish()
         return {"chapters": chapter_results, "persons": person_result}
 
     # ------------------------------------------------------------------
@@ -609,7 +626,8 @@ class SuwayomiMover:
                          builder: ComicInfoBuilder,
                          chapter_num: str,
                          chapter_dir: Path,
-                         dest_series: Path) -> dict:
+                         dest_series: Path,
+                         series_rec=None) -> dict:
         """
         Generates ComicInfo.xml for one chapter, packs it to CBZ, and
         optionally removes the source folder.
@@ -619,6 +637,11 @@ class SuwayomiMover:
         <Pages> element correctly points to the front cover).
         """
         cbz_path = dest_series / f"{chapter_dir.name}.cbz"
+        chap_rec = (series_rec or self._perf.begin_run().begin_series("")
+                    ).begin_chapter(chapter_num)
+        # add_pages_from_folder records its own sub-steps on this recorder.
+        builder.perf = chap_rec
+        ok = False
         try:
             builder.chapter = chapter_num
             builder.add_pages_from_folder(chapter_dir, cover_filename="000")
@@ -626,18 +649,26 @@ class SuwayomiMover:
             # by add_pages_from_folder, so it's effectively free.  Used by
             # the chapter index in the Kavita destination folder.
             try:
-                volume = builder._determine_volume()
+                with chap_rec.measure("volume"):
+                    volume = builder._determine_volume()
             except Exception:
                 volume = None
-            builder.save_xml(chapter_dir)
-            _pack_to_cbz(chapter_dir, cbz_path)
+            with chap_rec.measure("save_xml"):
+                builder.save_xml(chapter_dir)
+            with chap_rec.measure("pack_cbz"):
+                _pack_to_cbz(chapter_dir, cbz_path)
             if self._delete_source:
-                shutil.rmtree(chapter_dir)
+                with chap_rec.measure("delete_source"):
+                    shutil.rmtree(chapter_dir)
+            ok = True
             return {"chapter": chapter_num, "cbz": str(cbz_path),
                     "ok": True, "volume": volume}
         except Exception as exc:
             return {"chapter": chapter_num, "cbz": str(cbz_path),
                     "ok": False, "error": str(exc)}
+        finally:
+            builder.perf = None
+            chap_rec.finish(ok=ok)
 
 
 # --------------------------------------------------------------------------