diff --git a/bec_widgets/applications/main_app.py b/bec_widgets/applications/main_app.py index 10dfcc7b..ee176a8e 100644 --- a/bec_widgets/applications/main_app.py +++ b/bec_widgets/applications/main_app.py @@ -1,3 +1,5 @@ +from bec_widgets.applications.startup_profiler import startup_profiler # isort: skip + from bec_qthemes import material_icon from qtpy.QtGui import QAction # type: ignore from qtpy.QtWidgets import QApplication, QHBoxLayout, QStackedWidget, QWidget @@ -20,6 +22,8 @@ from bec_widgets.utils.screen_utils import ( ) from bec_widgets.widgets.containers.main_window.main_window import BECMainWindow +startup_profiler.mark("module imports") + class BECMainApp(BECMainWindow): RPC = False @@ -34,6 +38,7 @@ class BECMainApp(BECMainWindow): **kwargs, ): super().__init__(parent=parent, *args, **kwargs) + startup_profiler.mark("BEC connection + base window") self._show_examples = bool(show_examples) # --- Compose central UI (sidebar + stack) @@ -54,17 +59,22 @@ class BECMainApp(BECMainWindow): self.sidebar.view_selected.connect(self._on_view_selected) self._add_views() + startup_profiler.mark("views added") # Initialize guided tour self.guided_tour = GuidedTour(self) self._setup_guided_tour() + startup_profiler.mark("guided tour") def _add_views(self): self.add_section("BEC Applications", "bec_apps") self.dock_area = DockAreaView(self) + startup_profiler.mark("DockAreaView") self.device_manager = DeviceManagerView(self) + startup_profiler.mark("DeviceManagerView") # self.developer_view = DeveloperView(self) #TODO temporary disable until the bugs with BECShell are resolved self.admin_view = AdminView(self) + startup_profiler.mark("AdminView") self.add_view(icon="widgets", title="Dock Area", widget=self.dock_area, mini_text="Docks") self.add_view( @@ -395,8 +405,11 @@ def main(): # pragma: no cover app = QApplication([sys.argv[0], *qt_args]) app.setApplicationName("BEC") + startup_profiler.mark("QApplication") apply_theme("dark") + startup_profiler.mark("theme applied") w = BECMainApp(show_examples=args.examples) + startup_profiler.mark("main window built") screen_geometry = available_screen_geometry() if screen_geometry is not None: @@ -406,6 +419,12 @@ def main(): # pragma: no cover w.resize(w.minimumSizeHint()) w.show() + startup_profiler.mark("window shown") + + # First event-loop iteration -> the window is actually painted/interactive. + from qtpy.QtCore import QTimer + + QTimer.singleShot(0, lambda: startup_profiler.mark("interactive", final=True)) sys.exit(app.exec()) diff --git a/bec_widgets/applications/startup_profiler.py b/bec_widgets/applications/startup_profiler.py new file mode 100644 index 00000000..d2ebedde --- /dev/null +++ b/bec_widgets/applications/startup_profiler.py @@ -0,0 +1,82 @@ +"""Lightweight startup stage profiler for ``bec-app``. + +Logs, for each startup stage, the time since the previous mark and the +cumulative time since process start. A slow/cold start can then be localised +straight from the logs to one of the three cost centres: + +* ``module imports`` -> Python import + bytecode + NFS read cost +* ``BEC connection`` -> BEC client / Redis round-trips (dominates when Redis is remote) +* per-view marks -> widget construction (and any Redis/config the view loads) + +Example log:: + + [startup] module imports +6.21s (total 6.21s) + [startup] QApplication +0.34s (total 6.55s) + [startup] BEC connection +18.40s (total 25.07s) <- remote Redis + [startup] DeviceManagerView +2.10s (total 27.47s) + [startup] interactive +0.06s (total 27.71s) + +The origin is captured at *first import* of this module. ``main_app`` imports it +before its heavy imports, so ``module imports`` covers the real import cost. + +Set ``BEC_STARTUP_PROFILE=0`` to silence the output. +""" + +from __future__ import annotations + +import os +import time + +# Captured the moment this module is first imported (before main_app's heavy +# imports run), so it approximates the start of the bec-app import phase. +_ORIGIN = time.perf_counter() + +try: + from bec_lib import bec_logger + + _logger = bec_logger.logger +except Exception: # pragma: no cover - logging must never break startup + _logger = None + + +def _emit(msg: str) -> None: + if _logger is not None: + _logger.info(msg) + else: # pragma: no cover + print(msg, flush=True) + + +class StartupProfiler: + """Records named stage timings relative to a fixed origin.""" + + def __init__(self, origin: float) -> None: + self._origin = origin + self._last = origin + self._enabled = os.environ.get("BEC_STARTUP_PROFILE", "1").lower() not in ( + "0", + "false", + "no", + ) + + def reset(self, origin: float | None = None) -> None: + """Re-anchor the origin (e.g. to a perf_counter captured even earlier).""" + self._origin = time.perf_counter() if origin is None else origin + self._last = self._origin + + def mark(self, stage: str, *, final: bool = False) -> float: + """Log elapsed-since-last and total-since-origin for ``stage``. + + Returns the cumulative time so callers may use it programmatically. + """ + now = time.perf_counter() + delta = now - self._last + total = now - self._origin + self._last = now + if self._enabled: + _emit(f"[startup] {stage:<26} +{delta:6.2f}s (total {total:6.2f}s)") + if final: + _emit(f"[startup] ---- bec-app interactive after {total:.2f}s ----") + return total + + +startup_profiler = StartupProfiler(_ORIGIN)