wip startup profiler

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())
 

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)