From ecb5cdc13fc46112ccdc04f19d9ecbfbc897632d Mon Sep 17 00:00:00 2001 From: Ethanfel Date: Wed, 18 Mar 2026 23:53:30 +0100 Subject: [PATCH] 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 --- api_routes.py | 7 +++++++ main.py | 13 +++++++++++++ tab_batch_ng.py | 21 +++++++++++++++++++-- tab_timeline_ng.py | 16 ++++++++++++++++ utils.py | 15 ++++++++++++++- 5 files changed, 69 insertions(+), 3 deletions(-) diff --git a/api_routes.py b/api_routes.py index 62f8512..34f61ff 100644 --- a/api_routes.py +++ b/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} diff --git a/main.py b/main.py index ad29c37..a67a2a8 100644 --- a/main.py +++ b/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 diff --git a/tab_batch_ng.py b/tab_batch_ng.py index 0da999c..0652926 100644 --- a/tab_batch_ng.py +++ b/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') diff --git a/tab_timeline_ng.py b/tab_timeline_ng.py index 5e2802d..cf3b88a 100644 --- a/tab_timeline_ng.py +++ b/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') diff --git a/utils.py b/utils.py index d200b80..f6185b4 100644 --- a/utils.py +++ b/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: