Core: observe and report currently long-running function

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

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: