diff --git a/pype/modules/base.py b/pype/modules/base.py index 97e5f891af..ad0fecb8f7 100644 --- a/pype/modules/base.py +++ b/pype/modules/base.py @@ -1,7 +1,9 @@ # -*- coding: utf-8 -*- """Base class for Pype Modules.""" +import time import inspect import logging +import collections from uuid import uuid4 from abc import ABCMeta, abstractmethod import six @@ -268,12 +270,17 @@ class ITrayService(ITrayModule): class ModulesManager: + # Helper attributes for report + _report_total_key = "Total" + def __init__(self): self.log = logging.getLogger(self.__class__.__name__) self.modules = [] self.modules_by_id = {} self.modules_by_name = {} + # For report of time consumption + self._report = {} self.initialize_modules() self.connect_modules() @@ -283,6 +290,11 @@ class ModulesManager: self.log.debug("*** Pype modules initialization.") # Prepare settings for modules modules_settings = get_system_settings()["modules"] + + report = {} + time_start = time.time() + prev_start_time = time_start + # Go through globals in `pype.modules` for name in dir(pype.modules): modules_item = getattr(pype.modules, name, None) @@ -321,17 +333,28 @@ class ModulesManager: enabled_str = " " self.log.debug("[{}] {}".format(enabled_str, name)) + now = time.time() + report[module.__class__.__name__] = now - prev_start_time + prev_start_time = now + except Exception: self.log.warning( "Initialization of module {} failed.".format(name), exc_info=True ) + if self._report is not None: + report[self._report_total_key] = time.time() - time_start + self._report["Initialization"] = report + def connect_modules(self): """Trigger connection with other enabled modules. Modules should handle their interfaces in `connect_with_modules`. """ + report = {} + time_start = time.time() + prev_start_time = time_start enabled_modules = self.get_enabled_modules() self.log.debug("Has {} enabled modules.".format(len(enabled_modules))) for module in enabled_modules: @@ -343,6 +366,14 @@ class ModulesManager: exc_info=True ) + now = time.time() + report[module.__class__.__name__] = now - prev_start_time + prev_start_time = now + + if self._report is not None: + report[self._report_total_key] = time.time() - time_start + self._report["Connect modules"] = report + def get_enabled_modules(self): """Enabled modules initialized by the manager. @@ -468,6 +499,122 @@ class ModulesManager: output.extend(hook_paths) return output + def print_report(self): + """Print out report of time spent on modules initialization parts. + + Reporting is not automated must be implemented for each initialization + part separatelly. Reports must be stored to `_report` attribute. + Print is skipped if `_report` is empty. + + Attribute `_report` is dictionary where key is "label" describing + the processed part and value is dictionary where key is module's + class name and value is time delta of it's processing. + + It is good idea to add total time delta on processed part under key + which is defined in attribute `_report_total_key`. By default has value + `"Total"` but use the attribute please. + + ```javascript + { + "Initialization": { + "FtrackModule": 0.003, + ... + "Total": 1.003, + }, + ... + } + ``` + """ + if not self._report: + return + + available_col_names = set() + for module_names in self._report.values(): + available_col_names |= set(module_names.keys()) + + # Prepare ordered dictionary for columns + cols = collections.OrderedDict() + # Add module names to first columnt + cols["Module name"] = list(sorted( + module.__class__.__name__ + for module in self.modules + if module.__class__.__name__ in available_col_names + )) + # Add total key (as last module) + cols["Module name"].append(self._report_total_key) + + # Add columns from report + for label in self._report.keys(): + cols[label] = [] + + total_module_times = {} + for module_name in cols["Module name"]: + total_module_times[module_name] = 0 + + for label, reported in self._report.items(): + for module_name in cols["Module name"]: + col_time = reported.get(module_name) + if col_time is None: + cols[label].append("N/A") + continue + cols[label].append("{:.3f}".format(col_time)) + total_module_times[module_name] += col_time + + # Add to also total column that should sum the row + cols[self._report_total_key] = [] + for module_name in cols["Module name"]: + cols[self._report_total_key].append( + "{:.3f}".format(total_module_times[module_name]) + ) + + # Prepare column widths and total row count + # - column width is by + col_widths = {} + total_rows = None + for key, values in cols.items(): + if total_rows is None: + total_rows = 1 + len(values) + max_width = len(key) + for value in values: + value_length = len(value) + if value_length > max_width: + max_width = value_length + col_widths[key] = max_width + + rows = [] + for _idx in range(total_rows): + rows.append([]) + + for key, values in cols.items(): + width = col_widths[key] + idx = 0 + rows[idx].append(key.ljust(width)) + for value in values: + idx += 1 + rows[idx].append(value.ljust(width)) + + filler_parts = [] + for width in col_widths.values(): + filler_parts.append(width * "-") + filler = "+".join(filler_parts) + + formatted_rows = [filler] + last_row_idx = len(rows) - 1 + for idx, row in enumerate(rows): + # Add filler before last row + if idx == last_row_idx: + formatted_rows.append(filler) + + formatted_rows.append("|".join(row)) + + # Add filler after first row + if idx == 0: + formatted_rows.append(filler) + + # Join rows with newline char and add new line at the end + output = "\n".join(formatted_rows) + "\n" + print(output) + class TrayModulesManager(ModulesManager): # Define order of modules in menu @@ -489,6 +636,7 @@ class TrayModulesManager(ModulesManager): self.modules = [] self.modules_by_id = {} self.modules_by_name = {} + self._report = {} def initialize(self, tray_menu): self.initialize_modules() @@ -504,6 +652,9 @@ class TrayModulesManager(ModulesManager): return output def tray_init(self): + report = {} + time_start = time.time() + prev_start_time = time_start for module in self.get_enabled_tray_modules(): try: module.tray_init() @@ -516,6 +667,14 @@ class TrayModulesManager(ModulesManager): exc_info=True ) + now = time.time() + report[module.__class__.__name__] = now - prev_start_time + prev_start_time = now + + if self._report is not None: + report[self._report_total_key] = time.time() - time_start + self._report["Tray init"] = report + def tray_menu(self, tray_menu): ordered_modules = [] enabled_by_name = { @@ -529,6 +688,9 @@ class TrayModulesManager(ModulesManager): ordered_modules.append(module_by_name) ordered_modules.extend(enabled_by_name.values()) + report = {} + time_start = time.time() + prev_start_time = time_start for module in ordered_modules: if not module.tray_initialized: continue @@ -544,8 +706,18 @@ class TrayModulesManager(ModulesManager): ), exc_info=True ) + now = time.time() + report[module.__class__.__name__] = now - prev_start_time + prev_start_time = now + + if self._report is not None: + report[self._report_total_key] = time.time() - time_start + self._report["Tray menu"] = report def start_modules(self): + report = {} + time_start = time.time() + prev_start_time = time_start for module in self.get_enabled_tray_modules(): if not module.tray_initialized: if isinstance(module, ITrayService): @@ -561,6 +733,13 @@ class TrayModulesManager(ModulesManager): ), exc_info=True ) + now = time.time() + report[module.__class__.__name__] = now - prev_start_time + prev_start_time = now + + if self._report is not None: + report[self._report_total_key] = time.time() - time_start + self._report["Modules start"] = report def on_exit(self): for module in self.get_enabled_tray_modules(): diff --git a/pype/tools/tray/pype_tray.py b/pype/tools/tray/pype_tray.py index 1fec95906d..c27df16276 100644 --- a/pype/tools/tray/pype_tray.py +++ b/pype/tools/tray/pype_tray.py @@ -55,6 +55,9 @@ class TrayManager: # Tell each module which modules were imported self.modules_manager.start_modules() + # Print time report + self.modules_manager.print_report() + def _add_version_item(self): subversion = os.environ.get("PYPE_SUBVERSION") client_name = os.environ.get("PYPE_CLIENT")