perf: replace logger.debug with cached no-op to eliminate logging overhead

logger.debug() consumed 65-75% of event processing time even with DEBUG
disabled, due to frame inspection, string formatting, and lock acquisition
on every call.

- Store `self._debug` on BaseEngine at init: real logger.debug when DEBUG
  is enabled, no-op lambda otherwise
- Add BaseEngine.stop() to encapsulate external engine shutdown (replaces
  _stop_child_machine's inline engine manipulation)
- InvokeManager delegates _debug/_log_id to engine for consistent prefixes
- Module-level _debug in io/scxml/actions.py for parse-time callables
- Remove unused logging imports from sync/async engines and invoke module

Author: fgmacedo

pyproject.toml

@@ -131,7 +131,14 @@ disable_error_code = "annotation-unchecked"
 mypy_path = "$MYPY_CONFIG_FILE_DIR/tests/django_project"
 
 [[tool.mypy.overrides]]
-module = ['django.*', 'pytest.*', 'pydot.*', 'sphinx_gallery.*', 'docutils.*', 'sphinx.*']
+module = [
+    'django.*',
+    'pytest.*',
+    'pydot.*',
+    'sphinx_gallery.*',
+    'docutils.*',
+    'sphinx.*',
+]
 ignore_missing_imports = true
 
 [tool.ruff]

statemachine/engines/async_.py

@@ -1,6 +1,5 @@
 import asyncio
 import contextvars
-import logging
 from itertools import chain
 from time import time
 from typing import TYPE_CHECKING
@@ -20,9 +19,6 @@
     from ..event import Event
     from ..transition import Transition
 
-logger = logging.getLogger(__name__)
-
-
 # ContextVar to distinguish reentrant calls (from within callbacks) from
 # concurrent external calls. asyncio propagates context to child tasks
 # (e.g., those created by asyncio.gather in the callback system), so a
@@ -179,7 +175,7 @@ async def _exit_states(  # type: ignore[override]
             args, kwargs = await self._get_args_kwargs(info.transition, trigger_data)
 
             if info.state is not None:  # pragma: no branch
-                logger.debug("%s Exiting state: %s", self._log_id, info.state)
+                self._debug("%s Exiting state: %s", self._log_id, info.state)
                 await self.sm._callbacks.async_call(
                     info.state.exit.key, *args, on_error=on_error, **kwargs
                 )
@@ -234,7 +230,7 @@ async def _enter_states(  # noqa: C901
                 target=target,
             )
 
-            logger.debug("%s Entering state: %s", self._log_id, target)
+            self._debug("%s Entering state: %s", self._log_id, target)
             self._add_state_to_configuration(target)
 
             on_entry_result = await self.sm._callbacks.async_call(
@@ -274,7 +270,7 @@ async def _enter_states(  # noqa: C901
 
     async def microstep(self, transitions: "List[Transition]", trigger_data: TriggerData):
         self._microstep_count += 1
-        logger.debug(
+        self._debug(
             "%s macro:%d micro:%d transitions: %s",
             self._log_id,
             self._macrostep_count,
@@ -366,7 +362,7 @@ async def processing_loop(  # noqa: C901
             return None
 
         _ctx_token = _in_processing_loop.set(True)
-        logger.debug("%s Processing loop started: %s", self._log_id, self.sm.current_state_value)
+        self._debug("%s Processing loop started: %s", self._log_id, self.sm.current_state_value)
         first_result = self._sentinel
         try:
             took_events = True
@@ -378,7 +374,7 @@ async def processing_loop(  # noqa: C901
                 # Phase 1: eventless transitions and internal events
                 while not macrostep_done:
                     self._microstep_count = 0
-                    logger.debug(
+                    self._debug(
                         "%s Macrostep %d: eventless/internal queue",
                         self._log_id,
                         self._macrostep_count,
@@ -394,7 +390,7 @@ async def processing_loop(  # noqa: C901
                             internal_event = self.internal_queue.pop()
                             enabled_transitions = await self.select_transitions(internal_event)
                     if enabled_transitions:
-                        logger.debug(
+                        self._debug(
                             "%s Enabled transitions: %s", self._log_id, enabled_transitions
                         )
                         took_events = True
@@ -412,9 +408,7 @@ async def processing_loop(  # noqa: C901
                         await self._run_microstep(enabled_transitions, internal_event)
 
                 # Phase 3: external events
-                logger.debug(
-                    "%s Macrostep %d: external queue", self._log_id, self._macrostep_count
-                )
+                self._debug("%s Macrostep %d: external queue", self._log_id, self._macrostep_count)
                 while not self.external_queue.is_empty():
                     self.clear_cache()
                     took_events = True
@@ -429,7 +423,7 @@ async def processing_loop(  # noqa: C901
 
                     self._macrostep_count += 1
                     self._microstep_count = 0
-                    logger.debug(
+                    self._debug(
                         "%s macrostep %d: event=%s",
                         self._log_id,
                         self._macrostep_count,
@@ -453,7 +447,7 @@ async def processing_loop(  # noqa: C901
                     event_future = external_event.future
                     try:
                         enabled_transitions = await self.select_transitions(external_event)
-                        logger.debug(
+                        self._debug(
                             "%s Enabled transitions: %s", self._log_id, enabled_transitions
                         )
                         if enabled_transitions:
@@ -494,7 +488,7 @@ async def processing_loop(  # noqa: C901
             _in_processing_loop.reset(_ctx_token)
             self._processing.release()
 
-        logger.debug("%s Processing loop ended", self._log_id)
+        self._debug("%s Processing loop ended", self._log_id)
         result = first_result if first_result is not self._sentinel else None
         # If the caller has a future, await it (already resolved by now).
         if caller_future is not None:

statemachine/engines/base.py

@@ -99,6 +99,7 @@ def __init__(self, sm: "StateChart"):
         self._macrostep_count: int = 0
         self._microstep_count: int = 0
         self._log_id = f"[{type(sm).__name__}]"
+        self._debug = logger.debug if logger.isEnabledFor(logging.DEBUG) else lambda *a, **k: None
         self._root_parallel_final_pending: "State | None" = None
 
     def empty(self):  # pragma: no cover
@@ -125,7 +126,7 @@ def put(self, trigger_data: TriggerData, internal: bool = False, _delayed: bool
             self.external_queue.put(trigger_data)
 
         if not _delayed:
-            logger.debug(
+            self._debug(
                 "%s New event '%s' put on the '%s' queue",
                 self._log_id,
                 trigger_data.event,
@@ -180,7 +181,7 @@ def _send_error_execution(self, error: Exception, trigger_data: TriggerData):
 
         If already processing an error.execution event, ignore to avoid infinite loops.
         """
-        logger.debug(
+        self._debug(
             "%s Error %s captured while executing event=%s",
             self._log_id,
             error,
@@ -382,7 +383,7 @@ def microstep(self, transitions: List[Transition], trigger_data: TriggerData):
         This includes exiting states, executing transition content, and entering states.
         """
         self._microstep_count += 1
-        logger.debug(
+        self._debug(
             "%s macro:%d micro:%d transitions: %s",
             self._log_id,
             self._macrostep_count,
@@ -469,7 +470,7 @@ def _prepare_exit_states(
             states_to_exit, key=lambda x: x.state and x.state.document_order or 0, reverse=True
         )
         result = OrderedSet([info.state for info in ordered_states if info.state])
-        logger.debug("%s States to exit: %s", self._log_id, result)
+        self._debug("%s States to exit: %s", self._log_id, result)
 
         # Update history
         for info in ordered_states:
@@ -480,7 +481,7 @@ def _prepare_exit_states(
                 else:  # shallow history
                     history_value = [s for s in self.sm.configuration if s.parent == state]
 
-                logger.debug(
+                self._debug(
                     "%s Saving '%s.%s' history state: '%s'",
                     self._log_id,
                     state,
@@ -512,7 +513,7 @@ def _exit_states(
 
             # Execute `onexit` handlers — same per-block error isolation as onentry.
             if info.state is not None:  # pragma: no branch
-                logger.debug("%s Exiting state: %s", self._log_id, info.state)
+                self._debug("%s Exiting state: %s", self._log_id, info.state)
                 self.sm._callbacks.call(info.state.exit.key, *args, on_error=on_error, **kwargs)
 
             self._remove_state_from_configuration(info.state)
@@ -569,7 +570,7 @@ def _prepare_entry_states(
         new_configuration = cast(
             OrderedSet[State], (previous_configuration - states_to_exit) | states_targets_to_enter
         )
-        logger.debug("%s States to enter: %s", self._log_id, states_targets_to_enter)
+        self._debug("%s States to enter: %s", self._log_id, states_targets_to_enter)
 
         return ordered_states, states_for_default_entry, default_history_content, new_configuration
 
@@ -578,6 +579,15 @@ def _add_state_to_configuration(self, target: State):
         if not self.sm.atomic_configuration_update:
             self.sm._config.add(target)
 
+    def stop(self):
+        """Stop this engine externally (e.g. when a parent cancels a child invocation)."""
+        self._debug("%s Stopping engine", self._log_id)
+        self.running = False
+        try:
+            self._invoke_manager.cancel_all()
+        except Exception:  # pragma: no cover
+            self._debug("%s Error stopping engine", self._log_id, exc_info=True)
+
     def __del__(self):
         try:
             self._invoke_manager.cancel_all()
@@ -586,7 +596,7 @@ def __del__(self):
 
     def _handle_final_state(self, target: State, on_entry_result: list):
         """Handle final state entry: queue done events. No direct callback dispatch."""
-        logger.debug("%s Reached final state: %s", self._log_id, target)
+        self._debug("%s Reached final state: %s", self._log_id, target)
         if target.parent is None:
             self._invoke_manager.cancel_all()
             self.running = False
@@ -665,7 +675,7 @@ def _enter_states(  # noqa: C901
                 target=target,
             )
 
-            logger.debug("%s Entering state: %s", self._log_id, target)
+            self._debug("%s Entering state: %s", self._log_id, target)
             self._add_state_to_configuration(target)
 
             # Execute `onentry` handlers — each handler is a separate block per
@@ -765,7 +775,7 @@ def add_descendant_states_to_enter(  # noqa: C901
             parent_id = state.parent and state.parent.id
             default_history_content[parent_id] = [info]
             if state.id in self.sm.history_values:
-                logger.debug(
+                self._debug(
                     "%s History state '%s.%s' %s restoring: '%s'",
                     self._log_id,
                     state.parent,
@@ -795,7 +805,7 @@ def add_descendant_states_to_enter(  # noqa: C901
                     )
             else:
                 # Handle default history content
-                logger.debug(
+                self._debug(
                     "%s History state '%s.%s' default content: %s",
                     self._log_id,
                     state.parent,

statemachine/engines/sync.py

@@ -1,4 +1,3 @@
-import logging
 from time import sleep
 from time import time
 from typing import TYPE_CHECKING
@@ -14,8 +13,6 @@
 if TYPE_CHECKING:
     from ..transition import Transition
 
-logger = logging.getLogger(__name__)
-
 
 class SyncEngine(BaseEngine):
     def _run_microstep(self, enabled_transitions, trigger_data):
@@ -77,7 +74,7 @@ def processing_loop(self, caller_future=None):  # noqa: C901
         # We will collect the first result as the processing result to keep backwards compatibility
         # so we need to use a sentinel object instead of `None` because the first result may
         # be also `None`, and on this case the `first_result` may be overridden by another result.
-        logger.debug("%s Processing loop started: %s", self._log_id, self.sm.current_state_value)
+        self._debug("%s Processing loop started: %s", self._log_id, self.sm.current_state_value)
         first_result = self._sentinel
         try:
             took_events = True
@@ -92,7 +89,7 @@ def processing_loop(self, caller_future=None):  # noqa: C901
                 # handles eventless transitions and internal events
                 while not macrostep_done:
                     self._microstep_count = 0
-                    logger.debug(
+                    self._debug(
                         "%s Macrostep %d: eventless/internal queue",
                         self._log_id,
                         self._macrostep_count,
@@ -110,7 +107,7 @@ def processing_loop(self, caller_future=None):  # noqa: C901
                             internal_event = self.internal_queue.pop()
                             enabled_transitions = self.select_transitions(internal_event)
                     if enabled_transitions:
-                        logger.debug(
+                        self._debug(
                             "%s Enabled transitions: %s", self._log_id, enabled_transitions
                         )
                         took_events = True
@@ -130,9 +127,7 @@ def processing_loop(self, caller_future=None):  # noqa: C901
                         self._run_microstep(enabled_transitions, internal_event)
 
                 # Process external events
-                logger.debug(
-                    "%s Macrostep %d: external queue", self._log_id, self._macrostep_count
-                )
+                self._debug("%s Macrostep %d: external queue", self._log_id, self._macrostep_count)
                 while not self.external_queue.is_empty():
                     self.clear_cache()
                     took_events = True
@@ -147,7 +142,7 @@ def processing_loop(self, caller_future=None):  # noqa: C901
 
                     self._macrostep_count += 1
                     self._microstep_count = 0
-                    logger.debug(
+                    self._debug(
                         "%s macrostep %d: event=%s",
                         self._log_id,
                         self._macrostep_count,
@@ -158,7 +153,7 @@ def processing_loop(self, caller_future=None):  # noqa: C901
                     self._invoke_manager.handle_external_event(external_event)
 
                     enabled_transitions = self.select_transitions(external_event)
-                    logger.debug("%s Enabled transitions: %s", self._log_id, enabled_transitions)
+                    self._debug("%s Enabled transitions: %s", self._log_id, enabled_transitions)
                     if enabled_transitions:
                         try:
                             result = self.microstep(list(enabled_transitions), external_event)
@@ -177,7 +172,7 @@ def processing_loop(self, caller_future=None):  # noqa: C901
 
         finally:
             self._processing.release()
-        logger.debug("%s Processing loop ended", self._log_id)
+        self._debug("%s Processing loop ended", self._log_id)
         return first_result if first_result is not self._sentinel else None
 
     def enabled_events(self, *args, **kwargs):