From 148a098ca6dac5033a774428873b06f9dbc26d15 Mon Sep 17 00:00:00 2001 From: mahmoud Date: Tue, 5 May 2026 18:37:19 +0000 Subject: [PATCH 1/5] avoid format on the hot send path --- tractor/ipc/_chan.py | 4 ++-- tractor/msg/_ops.py | 12 ++++++------ 2 files changed, 8 insertions(+), 8 deletions(-) diff --git a/tractor/ipc/_chan.py b/tractor/ipc/_chan.py index 10a800e4..0bf254d7 100644 --- a/tractor/ipc/_chan.py +++ b/tractor/ipc/_chan.py @@ -326,8 +326,8 @@ class Channel: __tracebackhide__: bool = hide_tb try: log.transport( - '=> send IPC msg:\n\n' - f'{pformat(payload)}\n' + '=> send IPC msg\n\n' + # f'{pformat(payload)}\n' ) # assert self._transport # but why typing? await self._transport.send( diff --git a/tractor/msg/_ops.py b/tractor/msg/_ops.py index a134306f..fe5929f6 100644 --- a/tractor/msg/_ops.py +++ b/tractor/msg/_ops.py @@ -308,12 +308,12 @@ class PldRx(Struct): pld: PayloadT = self._pld_dec.decode(pld) log.runtime( f'Decoded payload for\n' - # f'\n' - f'{msg}\n' - # ^TODO?, ideally just render with `, - # pld={decode}` in the `msg.pformat()`?? - f'where, ' - f'{type(msg).__name__}.pld={pld!r}\n' + # # f'\n' + # f'{msg}\n' + # # ^TODO?, ideally just render with `, + # # pld={decode}` in the `msg.pformat()`?? + # f'where, ' + # f'{type(msg).__name__}.pld={pld!r}\n' ) return pld except TypeError as typerr: From 0e11ff7e9d808a5afa1101c6a2b8fe0825cf0eea Mon Sep 17 00:00:00 2001 From: root Date: Thu, 7 May 2026 22:01:55 -0700 Subject: [PATCH 2/5] Guard hot-path log calls to avoid payload rendering when disabled Wrap `log.transport()` in `Channel.send()` and `log.runtime()` in `PldRx.decode_pld()` with `log.at_least_level()` checks so that expensive `pformat(payload)` / `repr(msg)` / `repr(pld)` calls are skipped entirely when the respective log level is not active. Previously the f-string arguments were eagerly evaluated before being passed to the log method, even though `StackLevelAdapter.log()` would then discard the message internally via its own `isEnabledFor()` check. On high-frequency IPC paths this caused `pformat` to dominate CPU usage (~60-70 %) as reported in #455. This also restores the full diagnostic output (msg type, decoded payload) that was temporarily commented out in 0373164 as a stopgap. Resolves #455 --- tractor/ipc/_chan.py | 10 ++++++---- tractor/msg/_ops.py | 18 +++++++++--------- 2 files changed, 15 insertions(+), 13 deletions(-) diff --git a/tractor/ipc/_chan.py b/tractor/ipc/_chan.py index 0bf254d7..0bae7e26 100644 --- a/tractor/ipc/_chan.py +++ b/tractor/ipc/_chan.py @@ -325,10 +325,12 @@ class Channel: ''' __tracebackhide__: bool = hide_tb try: - log.transport( - '=> send IPC msg\n\n' - # f'{pformat(payload)}\n' - ) + if log.at_least_level('transport'): + # don't materialize the payload repr if not necessary + log.transport( + '=> send IPC msg:\n\n' + f'{pformat(payload)}\n' + ) # assert self._transport # but why typing? await self._transport.send( payload, diff --git a/tractor/msg/_ops.py b/tractor/msg/_ops.py index fe5929f6..1b342ca6 100644 --- a/tractor/msg/_ops.py +++ b/tractor/msg/_ops.py @@ -306,15 +306,15 @@ class PldRx(Struct): ): try: pld: PayloadT = self._pld_dec.decode(pld) - log.runtime( - f'Decoded payload for\n' - # # f'\n' - # f'{msg}\n' - # # ^TODO?, ideally just render with `, - # # pld={decode}` in the `msg.pformat()`?? - # f'where, ' - # f'{type(msg).__name__}.pld={pld!r}\n' - ) + if log.at_least_level('runtime'): + # don't materialize the payload repr if not necessary + log.runtime( + f'Decoded payload for\n' + f'\n' + f'{msg}\n' + f'where, ' + f'{type(msg).__name__}.pld={pld!r}\n' + ) return pld except TypeError as typerr: __tracebackhide__: bool = False From 67280c28987f217ee9af8f80c17b68e9adfaeddd Mon Sep 17 00:00:00 2001 From: goodboy Date: Tue, 11 Aug 2026 20:35:58 -0400 Subject: [PATCH 3/5] Honor log disable controls in hot-path guards Use `Logger.isEnabledFor()` in `at_least_level()` so logger-local and global disable controls short-circuit payload rendering. Add `Channel.send()` coverage for effective-level, per-logger, and global suppression while ensuring transport remains unchanged. Caught-during: review remediation Found-via: `/run-tests` test_log_guard_skips_payload_formatting Review: PR #458 (goodboy) https://github.com/goodboy/tractor/pull/458#issuecomment-5258207470 (this patch was generated in some part by `opencode` using `gpt-5.6-sol` (`openai`)) --- tests/test_log_sys.py | 85 +++++++++++++++++++++++++++++++++++++++++++ tractor/log.py | 4 +- 2 files changed, 86 insertions(+), 3 deletions(-) diff --git a/tests/test_log_sys.py b/tests/test_log_sys.py index 3870e825..1894bd1f 100644 --- a/tests/test_log_sys.py +++ b/tests/test_log_sys.py @@ -2,16 +2,19 @@ `tractor.log`-wrapping unit tests. ''' +import logging from pathlib import Path import shutil from types import ModuleType import pytest import tractor +import trio from tractor import ( _code_load, log, ) +from tractor.ipc import _chan def test_root_pkg_not_duplicated_in_logger_name(): @@ -222,6 +225,88 @@ def test_add_log_level_pluggable(): delattr(log.StackLevelAdapter, name.lower()) +@pytest.mark.parametrize( + 'suppression', + [ + 'level', + 'logger', + 'global', + ], +) +def test_log_guard_skips_payload_formatting( + monkeypatch: pytest.MonkeyPatch, + suppression: str, +): + ''' + Suppressed transport logs must not render payloads. + + The original hot-path guard compared only the effective logger + level. A logger disabled through its `Logger.disabled` flag or + the global `logging.disable()` threshold could therefore still + call `pformat()` before `Logger.isEnabledFor()` discarded the + record. + + Exercise effective-level, per-logger, and global suppression + independently. A poisoned `_chan.pformat()` proves rendering is + skipped, while the fake transport proves `Channel.send()` still + transmits the original payload and traceback-hiding flag. + + ''' + sent: list[tuple[object, bool]] = [] + + class FakeTransport: + async def send( + self, + payload: object, + hide_tb: bool = False, + ) -> None: + sent.append((payload, hide_tb)) + + def fail_pformat(payload: object) -> str: + raise AssertionError( + f'suppressed log rendered payload: {payload!r}' + ) + + chan_log = log.get_logger( + name=f'guard_test.{suppression}', + ) + std_log = chan_log.logger + orig_level: int = std_log.level + orig_disable: int = logging.root.manager.disable + transport_level: int = log.CUSTOM_LEVELS['TRANSPORT'] + + monkeypatch.setattr(_chan, 'log', chan_log) + monkeypatch.setattr(_chan, 'pformat', fail_pformat) + try: + logging.disable(logging.NOTSET) + std_log.setLevel(transport_level) + + if suppression == 'level': + std_log.setLevel(logging.INFO) + elif suppression == 'logger': + monkeypatch.setattr(std_log, 'disabled', True) + else: + logging.disable(logging.CRITICAL) + + assert not chan_log.isEnabledFor(transport_level) + + transport = FakeTransport() + chan = _chan.Channel(transport=transport) + payload = object() + + async def send_payload() -> None: + await chan.send( + payload, + hide_tb=True, + ) + + trio.run(send_payload) + assert sent == [(payload, True)] + finally: + std_log.setLevel(orig_level) + logging.disable(orig_disable) + + # TODO, moar tests against existing feats: # ------ - ------ # - [ ] color settings? diff --git a/tractor/log.py b/tractor/log.py index 6c8c9bc8..a87dd7c1 100644 --- a/tractor/log.py +++ b/tractor/log.py @@ -111,9 +111,7 @@ def at_least_level( if isinstance(level, str): level: int = CUSTOM_LEVELS[level.upper()] - if log.getEffectiveLevel() <= level: - return True - return False + return log.isEnabledFor(level) # TODO, compare with using a "filter" instead? From 84ec8951503d55b0d49c47ea2df303a243ac704e Mon Sep 17 00:00:00 2001 From: goodboy Date: Wed, 12 Aug 2026 12:51:43 -0400 Subject: [PATCH 4/5] Drop resolved channel log-guard TODO Remove the stale `Channel.from_addr()` design note now that its `at_least_level()` guard avoids inactive pretty-rendering work. (this patch was generated in some part by `opencode` using `gpt-5.6-sol` (`openai`)) --- tractor/ipc/_chan.py | 3 --- 1 file changed, 3 deletions(-) diff --git a/tractor/ipc/_chan.py b/tractor/ipc/_chan.py index 0bae7e26..a2450585 100644 --- a/tractor/ipc/_chan.py +++ b/tractor/ipc/_chan.py @@ -198,9 +198,6 @@ class Channel: # assert transport.raddr == addr chan = Channel(transport=transport) - # ?TODO, compact this into adapter level-methods? - # -[ ] would avoid extra repr-calcs if level not active? - # |_ how would the `calc_if_level` look though? func? if log.at_least_level('runtime'): from tractor.devx import ( pformat as _pformat, From 935c8cf656accc99982e18a47367e777d10566b1 Mon Sep 17 00:00:00 2001 From: goodboy Date: Wed, 12 Aug 2026 13:48:40 -0400 Subject: [PATCH 5/5] Guard receive-path transport rendering Skip raw packet, decoded message, peer, and channel formatting when transport logging is disabled. Keep message processing and wire reads outside the guards so logging controls never affect IPC flow. Also narrow the remaining pretty-struct TODO to require a non-raising formatter with native-repr fallback. (this patch was generated in some part by `opencode` using `gpt-5.6-sol` (`openai`)) --- tractor/ipc/_transport.py | 5 ++++- tractor/runtime/_rpc.py | 35 +++++++++++++++++------------------ 2 files changed, 21 insertions(+), 19 deletions(-) diff --git a/tractor/ipc/_transport.py b/tractor/ipc/_transport.py index 0a38d14d..dd3be179 100644 --- a/tractor/ipc/_transport.py +++ b/tractor/ipc/_transport.py @@ -309,7 +309,10 @@ class MsgpackTransport(MsgTransport): log.transport(f'received header {size}') # type: ignore msg_bytes: bytes = await self.recv_stream.receive_exactly(size) - log.transport(f"received {msg_bytes}") # type: ignore + if log.at_least_level('transport'): + log.transport( # type: ignore + f'received {msg_bytes}' + ) try: # NOTE: lookup the `trio.Task.context`'s var for # the current `MsgCodec`. diff --git a/tractor/runtime/_rpc.py b/tractor/runtime/_rpc.py index 6c0fb32a..d2c9ea30 100644 --- a/tractor/runtime/_rpc.py +++ b/tractor/runtime/_rpc.py @@ -1003,20 +1003,18 @@ async def process_messages( task_status.started(loop_cs) async for msg in chan: - log.transport( # type: ignore - f'IPC msg from peer\n' - f'<= {chan.aid.reprol()}\n\n' + if log.at_least_level('transport'): + log.transport( # type: ignore + f'IPC msg from peer\n' + f'<= {chan.aid.reprol()}\n\n' - # TODO: use of the pprinting of structs is - # FRAGILE and should prolly not be - # - # avoid fmting depending on loglevel for perf? - # -[ ] specifically `pretty_struct.pformat()` sub-call..? - # - how to only log-level-aware actually call this? - # -[ ] use `.msg.pretty_struct` here now instead! - # f'{pretty_struct.pformat(msg)}\n' - f'{msg}\n' - ) + # TODO: pretty-printing structs is FRAGILE; + # -[ ] add a non-raising log formatter with + # native-repr fallback before using + # `.msg.pretty_struct` here. + # f'{pretty_struct.pformat(msg)}\n' + f'{msg}\n' + ) match msg: # msg for an ongoing IPC ctx session, deliver msg to @@ -1262,11 +1260,12 @@ async def process_messages( log.exception(message) raise RuntimeError(message) - log.transport( - 'Waiting on next IPC msg from\n' - f'peer: {chan.aid.reprol()}\n' - f'|_{chan}\n' - ) + if log.at_least_level('transport'): + log.transport( + 'Waiting on next IPC msg from\n' + f'peer: {chan.aid.reprol()}\n' + f'|_{chan}\n' + ) # END-OF `async for`: # IPC disconnected via `trio.EndOfChannel`, likely