Startup performance logging (#2145)

mantidimaging/__main__.py

@@ -2,6 +2,9 @@
 # Copyright (C) 2024 ISIS Rutherford Appleton Laboratory UKRI
 # SPDX - License - Identifier: GPL-3.0-or-later
 from __future__ import annotations
+import time
+
+process_start_time = time.monotonic()
 
 if __name__ == '__main__':
     from multiprocessing import freeze_support

mantidimaging/core/parallel/manager.py

@@ -1,6 +1,8 @@
 # Copyright (C) 2024 ISIS Rutherford Appleton Laboratory UKRI
 # SPDX - License - Identifier: GPL-3.0-or-later
 from __future__ import annotations
+
+import time
 from multiprocessing import get_context
 import os
 import uuid
@@ -20,19 +22,24 @@
 CURRENT_PID = psutil.Process().pid
 
 LOG = getLogger(__name__)
+perf_logger = getLogger("perf." + __name__)
 
 cores: int = 1
 pool: Pool | None = None
 
 
 def create_and_start_pool():
     LOG.info('Creating process pool')
+    t0 = time.monotonic()
     context = get_context('spawn')
     global cores
     cores = context.cpu_count()
     global pool
     pool = context.Pool(cores, initializer=worker_setup)
 
+    if perf_logger.isEnabledFor(1):
+        perf_logger.info(f"Process pool started in {time.monotonic() - t0}")
+
 
 def worker_setup():
     # Required to import modules for running operations

mantidimaging/gui/windows/main/view.py

@@ -6,6 +6,7 @@
 import uuid
 from logging import getLogger
 from pathlib import Path
+import time
 from typing import TYPE_CHECKING
 from uuid import UUID
 
@@ -42,6 +43,7 @@
 from mantidimaging.gui.windows.stack_visualiser import StackVisualiserView
 from mantidimaging.gui.windows.welcome_screen.presenter import WelcomeScreenPresenter
 from mantidimaging.gui.windows.wizard.presenter import WizardPresenter
+from mantidimaging.__main__ import process_start_time
 
 if TYPE_CHECKING:
     from mantidimaging.core.data.dataset import MixedDataset
@@ -50,6 +52,7 @@
 SINO_TEXT = "Sinograms"
 
 LOG = getLogger(__name__)
+perf_logger = getLogger("perf." + __name__)
 
 
 class QTreeDatasetWidgetItem(QTreeWidgetItem):
@@ -164,6 +167,11 @@ def __init__(self, open_dialogs: bool = True):
 
         self.tabifiedDockWidgetActivated.connect(self._on_tab_bar_clicked)
 
+    def _window_ready(self) -> None:
+        if perf_logger.isEnabledFor(1):
+            perf_logger.info(f"Mantid Imaging ready in {time.monotonic() - process_start_time}")
+        super()._window_ready()
+
     def setup_shortcuts(self):
         self.actionLoadDataset.triggered.connect(self.show_image_load_dialog)
         self.actionLoadImages.triggered.connect(self.load_image_stack)

mantidimaging/helper.py

@@ -54,7 +54,7 @@ def initialise_logging(arg_level: str) -> None:
     perf_logger = logging.getLogger('perf')
     perf_logger.setLevel(100)
     perf_logger.propagate = False
-    if settings.value("logging/performance_log", defaultValue=False):
+    if settings.value("logging/performance_log", defaultValue=False, type=bool):
         perf_logger.setLevel(1)
         perf_logger.addHandler(console_handler)
         if log_directory != Path(""):