diff --git a/BaseClasses.py b/BaseClasses.py index cd8749e11d..289440b4bb 100644 --- a/BaseClasses.py +++ b/BaseClasses.py @@ -7,6 +7,8 @@ import logging import random import secrets import typing # this can go away when Python 3.8 support is dropped +import threading +import time from argparse import Namespace from collections import Counter, deque from collections.abc import Collection, MutableSequence @@ -95,6 +97,37 @@ class MultiWorld(): def __getitem__(self, player) -> bool: return self.rule(player) + class Observer(threading.Thread): + current_function: str + entered: float + + def __init__(self): + self.current_function = "" + self.entered = 0.0 + super().__init__(name="Observer", daemon=True) + + def __call__(self, function: typing.Callable, entered: float): + # use str of function to avoid having a reference to a bound method + self.current_function = str(function) + self.entered = entered + return self + + def __enter__(self): + assert self.current_function, "Entered Observer Context without current method." + + def __exit__(self, exc_type, exc_val, exc_tb): + self.current_function = "" + + def run(self): + while 1: + time.sleep(60) + if self.current_function: + now = time.perf_counter() + if now - self.entered > 60: + logging.info(f"Generation stalling in {self.current_function}, " + f"running since {time.perf_counter()-self.entered:.0f} seconds ago.") + self.current_function = "" + class RegionManager: region_cache: Dict[int, Dict[str, Region]] entrance_cache: Dict[int, Dict[str, Entrance]] @@ -160,6 +193,8 @@ class MultiWorld(): self.local_early_items = {player: {} for player in self.player_ids} self.indirect_connections = {} self.start_inventory_from_pool: Dict[int, Options.StartInventoryPool] = {} + self.observer = self.Observer() + self.observer.start() for player in range(1, players + 1): def set_player_attr(attr, val): diff --git a/worlds/AutoWorld.py b/worlds/AutoWorld.py index faf14bed18..adc8ddab08 100644 --- a/worlds/AutoWorld.py +++ b/worlds/AutoWorld.py @@ -121,7 +121,11 @@ class AutoLogicRegister(type): def _timed_call(method: Callable[..., Any], *args: Any, multiworld: Optional["MultiWorld"] = None, player: Optional[int] = None) -> Any: start = time.perf_counter() - ret = method(*args) + if multiworld: + with multiworld.observer(method, start): + ret = method(*args) + else: + ret = method(*args) taken = time.perf_counter() - start if taken > 1.0: if player and multiworld: @@ -169,7 +173,7 @@ def call_stage(multiworld: "MultiWorld", method_name: str, *args: Any) -> None: for world_type in sorted(world_types, key=lambda world: world.__name__): stage_callable = getattr(world_type, f"stage_{method_name}", None) if stage_callable: - _timed_call(stage_callable, multiworld, *args) + _timed_call(stage_callable, multiworld, *args, multiworld=multiworld) class WebWorld: