diff --git a/pkgs/clan-vm-manager/README.md b/pkgs/clan-vm-manager/README.md index fc966750..df504a6a 100644 --- a/pkgs/clan-vm-manager/README.md +++ b/pkgs/clan-vm-manager/README.md @@ -37,3 +37,9 @@ gsettings set org.gtk.Settings.Debug enable-inspector-keybinding true # Start the application with the debugger attached GTK_DEBUG=interactive ./bin/clan-vm-manager --debug ``` + +## Profiling +To activate profiling execute: +``` +PERF=1 ./bin/clan-vm-manager +``` \ No newline at end of file diff --git a/pkgs/clan-vm-manager/clan_vm_manager/__init__.py b/pkgs/clan-vm-manager/clan_vm_manager/__init__.py index 2fce92cc..17fcd5d4 100644 --- a/pkgs/clan-vm-manager/clan_vm_manager/__init__.py +++ b/pkgs/clan-vm-manager/clan_vm_manager/__init__.py @@ -2,12 +2,10 @@ import logging import sys from clan_vm_manager.app import MainApplication -from clan_vm_manager.components.profiler import profile log = logging.getLogger(__name__) -@profile def main() -> int: app = MainApplication() return app.run(sys.argv) diff --git a/pkgs/clan-vm-manager/clan_vm_manager/components/gkvstore.py b/pkgs/clan-vm-manager/clan_vm_manager/components/gkvstore.py index 2a7004dc..0efa282a 100644 --- a/pkgs/clan-vm-manager/clan_vm_manager/components/gkvstore.py +++ b/pkgs/clan-vm-manager/clan_vm_manager/components/gkvstore.py @@ -1,5 +1,4 @@ import logging -from collections import OrderedDict from collections.abc import Callable from typing import Any, Generic, TypeVar @@ -29,7 +28,8 @@ class GKVStore(GObject.GObject, Gio.ListModel, Generic[K, V]): super().__init__() self.gtype = gtype self.key_gen = key_gen - self._items: "OrderedDict[K, V]" = OrderedDict() + # From Python 3.7 onwards dictionaries are ordered by default + self._items: "dict[K, V]" = dict() ################################## # # @@ -175,7 +175,6 @@ class GKVStore(GObject.GObject, Gio.ListModel, Generic[K, V]): else: # Add the new key-value pair self._items[key] = value - self._items.move_to_end(key) position = max(len(self._items) - 1, 0) self.items_changed(position, 0, 1) diff --git a/pkgs/clan-vm-manager/clan_vm_manager/components/profiler.py b/pkgs/clan-vm-manager/clan_vm_manager/components/profiler.py index c0b86d97..05c022d5 100644 --- a/pkgs/clan-vm-manager/clan_vm_manager/components/profiler.py +++ b/pkgs/clan-vm-manager/clan_vm_manager/components/profiler.py @@ -4,11 +4,80 @@ import logging import os import pstats import re +import weakref from collections.abc import Callable from typing import Any # Ensure you have a logger set up for logging exceptions log = logging.getLogger(__name__) +explanation = """ +cProfile Output Columns Explanation: + +- ncalls: The number of calls to the function. This includes both direct and indirect (recursive) calls. + +- tottime: The total time spent in the given function alone, excluding time spent in calls to sub-functions. + This measures the function's own overhead and execution time. + +- percall (first instance): Represents the average time spent in the function per call, calculated as tottime divided by ncalls. + This value excludes time spent in sub-function calls, focusing on the function's own processing time. + +- cumtime: The cumulative time spent in this function and all the sub-functions it calls (both directly and indirectly). + This includes all execution time within the function, from the start of its invocation to its return, + including all calls to other functions and the time those calls take. + +- percall (second instance): Represents the average time per call, including time spent in this function and in all sub-function calls. + It is calculated as cumtime divided by ncalls, providing an average over all calls that includes all nested function calls. +""" + + +def print_profile(profiler: cProfile.Profile) -> None: + s = io.StringIO() + ps = pstats.Stats(profiler, stream=s) + ps.sort_stats(pstats.SortKey.CUMULATIVE) + ps.print_stats(12) + + # Process the output to trim file paths + output_lines = s.getvalue().split("\n") + for line in output_lines: + try: + parts = re.split(r"\s+", line)[ + 1: + ] # Split on the first space to separate the time from the path + fqpath = parts[-1] + fpath, line_num = fqpath.split(":") + if os.path.sep in fpath: # Check if this looks like it includes a path + fpath = trim_path_to_three_levels(fpath) + prefix = f"{parts[0]:>7}" + prefix += f"{parts[1]:>9}" + prefix += f"{parts[2]:>9}" + prefix += f"{parts[3]:>9}" + prefix += f"{parts[4]:>9}" + new_line = f"{prefix:} {fpath}:{line_num}" + else: + new_line = line + except (ValueError, IndexError): + new_line = line # If there's no path, leave the line as is + print(new_line) + + +class ProfilerStore: + profilers: dict[str, cProfile.Profile] + + def __init__(self) -> None: + self.profilers = {} + self._exit_callback = weakref.finalize(self, self.on_exit) + + def __getitem__(self, func: Callable) -> cProfile.Profile: + key = f"{func.__module__}:{func.__name__}" + if key not in self.profilers: + self.profilers[key] = cProfile.Profile() + return self.profilers[key] + + def on_exit(self) -> None: + for key, profiler in self.profilers.items(): + print("=" * 7 + key + "=" * 7) + print_profile(profiler) + print(explanation) def trim_path_to_three_levels(path: str) -> str: @@ -19,6 +88,9 @@ def trim_path_to_three_levels(path: str) -> str: return path +PROFS = ProfilerStore() + + def profile(func: Callable) -> Callable: """ A decorator that profiles the decorated function, printing out the profiling @@ -26,44 +98,20 @@ def profile(func: Callable) -> Callable: """ def wrapper(*args: Any, **kwargs: Any) -> Any: - pr = cProfile.Profile() - res: Any = None + global PROFS + profiler = PROFS[func] + try: - pr.enable() + profiler.enable() res = func(*args, **kwargs) - pr.disable() + profiler.disable() except Exception as ex: log.exception(ex) - pr.disable() + profiler.disable() return None - - s = io.StringIO() - ps = pstats.Stats(pr, stream=s) - ps.sort_stats(pstats.SortKey.CUMULATIVE) - ps.print_stats(12) - - # Process the output to trim file paths - output_lines = s.getvalue().split("\n") - for line in output_lines: - try: - parts = re.split(r"\s+", line)[ - 1: - ] # Split on the first space to separate the time from the path - fqpath = parts[-1] - fpath, line_num = fqpath.split(":") - if os.path.sep in fpath: # Check if this looks like it includes a path - fpath = trim_path_to_three_levels(fpath) - prefix = f"{parts[0]:>7}" - prefix += f"{parts[1]:>9}" - prefix += f"{parts[2]:>9}" - prefix += f"{parts[3]:>9}" - prefix += f"{parts[4]:>9}" - new_line = f"{prefix:} {fpath}:{line_num}" - else: - new_line = line - except (ValueError, IndexError): - new_line = line # If there's no path, leave the line as is - print(new_line) return res - return wrapper + if os.getenv("PERF", "0") == "1": + return wrapper + else: + return func diff --git a/pkgs/clan-vm-manager/clan_vm_manager/singletons/use_vms.py b/pkgs/clan-vm-manager/clan_vm_manager/singletons/use_vms.py index c76ebdf7..1ffcd73c 100644 --- a/pkgs/clan-vm-manager/clan_vm_manager/singletons/use_vms.py +++ b/pkgs/clan-vm-manager/clan_vm_manager/singletons/use_vms.py @@ -7,6 +7,7 @@ from clan_cli.history.add import HistoryEntry from clan_vm_manager import assets from clan_vm_manager.components.gkvstore import GKVStore +from clan_vm_manager.components.profiler import profile from clan_vm_manager.components.vmobj import VMObject gi.require_version("GObject", "2.0") @@ -47,6 +48,7 @@ class ClanStore: self.push_history_entry(vm) return GLib.SOURCE_REMOVE + @profile def push_history_entry(self, entry: HistoryEntry) -> None: # TODO: We shouldn't do this here but in the list view if entry.flake.icon is None: