Add comprehensive timing logs across all critical paths

Logs with perf_counter timing on: file load/save, DB sync, all
render functions, save & snap (with deepcopy/save/sync breakdown),
graphviz cache hit/miss, node restore, and API endpoints.

Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>

api_routes.py

@@ -4,6 +4,7 @@ All endpoints are read-only. Mounted on the NiceGUI/FastAPI server.
 """
 
 import logging
+import time
 from typing import Any
 
 from fastapi import HTTPException, Query
@@ -54,6 +55,7 @@ def _list_sequences(name: str, file_name: str) -> dict[str, Any]:
 
 
 def _get_data(name: str, file_name: str, seq: int = Query(default=1)) -> dict[str, Any]:
+    t0 = time.perf_counter()
     db = _get_db()
     proj = db.get_project(name)
     if not proj:
@@ -64,10 +66,13 @@ def _get_data(name: str, file_name: str, seq: int = Query(default=1)) -> dict[st
     data = db.get_sequence(df["id"], seq)
     if data is None:
         raise HTTPException(status_code=404, detail=f"Sequence {seq} not found")
+    logger.info("API _get_data %s/%s seq=%d (%d keys): %.3fs",
+                 name, file_name, seq, len(data), time.perf_counter() - t0)
     return data
 
 
 def _get_keys(name: str, file_name: str, seq: int = Query(default=1)) -> dict[str, Any]:
+    t0 = time.perf_counter()
     db = _get_db()
     proj = db.get_project(name)
     if not proj:
@@ -77,4 +82,6 @@ def _get_keys(name: str, file_name: str, seq: int = Query(default=1)) -> dict[st
         raise HTTPException(status_code=404, detail=f"File '{file_name}' not found in project '{name}'")
     keys, types = db.get_sequence_keys(df["id"], seq)
     total = db.count_sequences(df["id"])
+    logger.info("API _get_keys %s/%s seq=%d (%d keys): %.3fs",
+                 name, file_name, seq, len(keys), time.perf_counter() - t0)
     return {"keys": keys, "types": types, "total_sequences": total}

main.py

@@ -200,6 +200,9 @@ def index():
 
     @ui.refreshable
     def render_main_content():
+        import time as _time
+        _t0 = _time.perf_counter()
+        logger.info("render_main_content START")
         max_w = '2400px' if dual_pane['active'] else '1200px'
         with ui.column().classes('w-full q-pa-md').style(f'max-width: {max_w}; margin: 0 auto'):
             if not state.file_path or not state.file_path.exists():
@@ -230,6 +233,8 @@ def index():
                 with ui.expansion('ComfyUI Monitor', icon='dns').classes('w-full'):
                     render_comfy_monitor(state)
 
+        logger.info("render_main_content END (%.3fs)", _time.perf_counter() - _t0)
+
     @ui.refreshable
     def _render_batch_tab_content():
         def on_toggle(e):
@@ -274,6 +279,9 @@ def index():
         async def on_select(e):
             if not e.value:
                 return
+            import time as _time
+            _t0 = _time.perf_counter()
+            logger.info("on_select START: %s", e.value)
             fp = pane_state.current_dir / e.value
             data, mtime = await asyncio.to_thread(load_json, fp)
             pane_state.data_cache = data
@@ -282,6 +290,7 @@ def index():
             pane_state.file_path = fp
             pane_state.restored_indicator = None
             _render_batch_tab_content.refresh()
+            logger.info("on_select END (%.3fs)", _time.perf_counter() - _t0)
 
         ui.select(
             file_names,
@@ -292,6 +301,9 @@ def index():
 
     async def load_file(file_name: str):
         """Load a JSON file and refresh the main content."""
+        import time as _time
+        _t0 = _time.perf_counter()
+        logger.info("load_file START: %s", file_name)
         fp = state.current_dir / file_name
         if state.loaded_file == str(fp):
             return
@@ -303,6 +315,7 @@ def index():
         state.restored_indicator = None
         if state._main_rendered:
             render_main_content.refresh()
+        logger.info("load_file END (%.3fs)", _time.perf_counter() - _t0)
 
     # Attach helpers to state so sidebar can call them
     state._load_file = load_file

tab_batch_ng.py

@@ -1,12 +1,16 @@
 import asyncio
 import copy
 import json
+import logging
 import math
 import random
+import time
 from pathlib import Path
 
 from nicegui import ui
 
+logger = logging.getLogger(__name__)
+
 from state import AppState
 from utils import (
     DEFAULTS, save_json, load_json, sync_to_db,
@@ -188,6 +192,8 @@ def dict_textarea(label, seq, key, **kwargs):
 # ======================================================================
 
 def render_batch_processor(state: AppState):
+    t0 = time.perf_counter()
+    logger.info("render_batch_processor START")
     data = state.data_cache
     file_path = state.file_path
     if isinstance(data, list):
@@ -314,6 +320,8 @@ def render_batch_processor(state: AppState):
     # --- Sequence list + mass update (inside refreshable so they stay in sync) ---
     @ui.refreshable
     def render_sequence_list():
+        t1 = time.perf_counter()
+        logger.info("render_sequence_list START (%d sequences)", len(batch_list))
         # Mass update (rebuilt on refresh so checkboxes match current sequences)
         _render_mass_update(batch_list, data, file_path, state, render_sequence_list)
 
@@ -328,8 +336,10 @@ def render_batch_processor(state: AppState):
                     _src_cache, src_seq_select,
                     standard_keys, render_sequence_list,
                 )
+        logger.info("render_sequence_list END (%.3fs)", time.perf_counter() - t1)
 
     render_sequence_list()
+    logger.info("render_batch_processor END (%.3fs)", time.perf_counter() - t0)
 
     # --- Save & Snap ---
     with ui.card().classes('w-full q-pa-md q-mt-lg'):
@@ -338,12 +348,15 @@ def render_batch_processor(state: AppState):
                                     placeholder='e.g. Added sequence 3').classes('col')
 
             async def save_and_snap():
+                t_ss = time.perf_counter()
+                logger.info("save_and_snap START")
                 data[KEY_BATCH_DATA] = batch_list
                 tree_data = data.get(KEY_HISTORY_TREE, {})
                 htree = HistoryTree(tree_data)
-                # Only deepcopy the data we need (skip history tree — it's huge and gets discarded)
+                t1 = time.perf_counter()
                 snapshot_payload = {k: copy.deepcopy(v) for k, v in data.items()
                                     if k != KEY_HISTORY_TREE}
+                logger.info("save_and_snap deepcopy %.3fs", time.perf_counter() - t1)
                 note = commit_input.value if commit_input.value else _auto_change_note(htree, batch_list)
                 try:
                     htree.commit(snapshot_payload, note=note)
@@ -351,12 +364,16 @@ def render_batch_processor(state: AppState):
                     ui.notify(f'Save failed: {e}', type='negative')
                     return
                 data[KEY_HISTORY_TREE] = htree.to_dict()
-                # Run heavy I/O off the event loop to prevent websocket timeout
+                t1 = time.perf_counter()
                 await asyncio.to_thread(save_json, file_path, data)
+                logger.info("save_and_snap save_json %.3fs", time.perf_counter() - t1)
                 if state.db_enabled and state.current_project and state.db:
+                    t1 = time.perf_counter()
                     await asyncio.to_thread(sync_to_db, state.db, state.current_project, file_path, data)
+                    logger.info("save_and_snap sync_to_db %.3fs", time.perf_counter() - t1)
                 state.restored_indicator = None
                 commit_input.set_value('')
+                logger.info("save_and_snap END (%.3fs)", time.perf_counter() - t_ss)
                 ui.notify('Batch Saved & Snapshot Created!', type='positive')
 
             ui.button('Save & Snap', icon='save', on_click=save_and_snap).props('color=primary')

tab_timeline_ng.py

@@ -1,6 +1,7 @@
 import asyncio
 import hashlib
 import json
+import logging
 import time
 
 from nicegui import ui
@@ -9,6 +10,8 @@ from state import AppState
 from history_tree import HistoryTree
 from utils import save_json, sync_to_db, KEY_BATCH_DATA, KEY_HISTORY_TREE
 
+logger = logging.getLogger(__name__)
+
 
 def _delete_nodes(htree, data, file_path, node_ids):
     """Delete nodes with backup, branch cleanup, re-parenting, and head fallback."""
@@ -361,6 +364,8 @@ def _render_node_manager(all_nodes, htree, data, file_path, restore_fn, refresh_
 
 
 def render_timeline_tab(state: AppState):
+    t0 = time.perf_counter()
+    logger.info("render_timeline_tab START")
     data = state.data_cache
     file_path = state.file_path
 
@@ -402,6 +407,8 @@ def render_timeline_tab(state: AppState):
 
     @ui.refreshable
     def render_timeline():
+        t_rt = time.perf_counter()
+        logger.info("render_timeline START (%d nodes)", len(htree.nodes))
         all_nodes = sorted(htree.nodes.values(), key=lambda x: x['timestamp'], reverse=True)
         selected_nodes = state.timeline_selected_nodes if selection_mode.value else set()
 
@@ -421,6 +428,7 @@ def render_timeline_tab(state: AppState):
                 all_nodes, htree, data, file_path,
                 _restore_and_refresh, render_timeline.refresh,
                 selected, state=state)
+        logger.info("render_timeline END (%.3fs)", time.perf_counter() - t_rt)
 
     def _toggle_select(nid, checked):
         if checked:
@@ -437,6 +445,7 @@ def render_timeline_tab(state: AppState):
     view_mode.on_value_change(lambda _: render_timeline.refresh())
     selection_mode.on_value_change(lambda _: render_timeline.refresh())
     render_timeline()
+    logger.info("render_timeline_tab END (%.3fs)", time.perf_counter() - t0)
 
     # --- Poll for graph node clicks (JS → Python bridge) ---
     graph_timer = None
@@ -481,6 +490,7 @@ def _render_graphviz(dot_source: str, selected_node_id: str | None = None):
     """Render graphviz DOT source as interactive SVG with click-to-select."""
     try:
         import graphviz
+        t_gv = time.perf_counter()
         cache_key = hashlib.md5(dot_source.encode()).hexdigest()
         svg = _graphviz_svg_cache.get(cache_key)
         if svg is None:
@@ -489,6 +499,9 @@ def _render_graphviz(dot_source: str, selected_node_id: str | None = None):
             if len(_graphviz_svg_cache) >= _GRAPHVIZ_CACHE_MAX:
                 _graphviz_svg_cache.pop(next(iter(_graphviz_svg_cache)))
             _graphviz_svg_cache[cache_key] = svg
+            logger.info("_render_graphviz MISS (generated): %.3fs", time.perf_counter() - t_gv)
+        else:
+            logger.info("_render_graphviz HIT (cached): %.3fs", time.perf_counter() - t_gv)
 
         sel_escaped = json.dumps(selected_node_id or '')[1:-1]  # strip quotes, get JS-safe content
 
@@ -548,6 +561,8 @@ def _render_graphviz(dot_source: str, selected_node_id: str | None = None):
 
 async def _restore_node(data, node, htree, file_path, state: AppState):
     """Restore a history node as the current version (full replace, not merge)."""
+    t0 = time.perf_counter()
+    logger.info("_restore_node START: %s", node.get('note', 'Step'))
     node_data = json.loads(json.dumps(node.get('data', {})))
     # Preserve the history tree before clearing
     preserved_tree = data.get(KEY_HISTORY_TREE)
@@ -566,6 +581,7 @@ async def _restore_node(data, node, htree, file_path, state: AppState):
         await asyncio.to_thread(sync_to_db, state.db, state.current_project, file_path, data)
     label = f"{node.get('note', 'Step')} ({node['id'][:4]})"
     state.restored_indicator = label
+    logger.info("_restore_node END (%.3fs)", time.perf_counter() - t0)
     ui.notify('Restored!', type='positive')
 
 

utils.py

@@ -174,24 +174,32 @@ def _migrate_lora_keys(data: dict) -> None:
 
 
 def load_json(path: str | Path) -> tuple[dict[str, Any], float]:
+    t0 = time.time()
     path = Path(path)
     if not path.exists():
         return DEFAULTS.copy(), 0
     try:
         with open(path, 'r') as f:
             data = json.load(f)
+        t1 = time.time()
         _migrate_lora_keys(data)
-        return data, path.stat().st_mtime
+        t2 = time.time()
+        mtime = path.stat().st_mtime
+        logger.info("load_json %s: read=%.3fs migrate=%.3fs total=%.3fs",
+                     path.name, t1 - t0, t2 - t1, t2 - t0)
+        return data, mtime
     except Exception as e:
         logger.error(f"Error loading JSON: {e}")
         return DEFAULTS.copy(), 0
 
 def save_json(path: str | Path, data: dict[str, Any]) -> None:
+    t0 = time.time()
     path = Path(path)
     tmp = path.with_suffix('.json.tmp')
     with open(tmp, 'w') as f:
         json.dump(data, f, indent=4)
     os.replace(tmp, path)
+    logger.info("save_json %s: %.3fs", path.name, time.time() - t0)
 
 def get_file_mtime(path: str | Path) -> float:
     """Returns the modification time of a file, or 0 if it doesn't exist."""
@@ -206,6 +214,7 @@ def sync_to_db(db, project_name: str, file_path: Path, data: dict) -> None:
     Resolves (or creates) the data_file, upserts all sequences from batch_data,
     and saves the history_tree. All writes happen in a single transaction.
     """
+    t0 = time.time()
     if not db or not project_name:
         return
     try:
@@ -280,6 +289,10 @@ def sync_to_db(db, project_name: str, file_path: Path, data: dict) -> None:
             raise
     except Exception as e:
         logger.warning(f"sync_to_db failed: {e}")
+        return
+    batch_count = len(data.get(KEY_BATCH_DATA, []))
+    logger.info("sync_to_db %s (%d seqs): %.3fs",
+                 Path(file_path).name, batch_count, time.time() - t0)
 
 
 def generate_templates(current_dir: Path) -> None: