logging: disabled log.debug() calls do not scale on the free-threaded build

Bug report

Bug description:

A log.debug(...) call that is switched off by the logger's level does not scale at all on the free-threaded build. Eight threads get through no more work than one, so for this pattern the free-threaded build performs the same as the GIL build.

This matters because a disabled debug call is one of the most executed lines in production Python. Library and application code leaves them in and relies on them costing almost nothing.

Reproducer

import logging, os, threading, time

log = logging.getLogger("bench")
log.setLevel(logging.WARNING)      # so debug() is switched off
ITERATIONS = 300_000
CPUS = [0, 2, 4, 6, 8, 10, 12, 14]   # one per physical core, adjust for your machine

def work(cpu=None):
    if cpu is not None:
        os.sched_setaffinity(0, {cpu})
    for _ in range(ITERATIONS):
        log.debug("nothing")

def run(cpus):
    threads = [threading.Thread(target=work, args=(c,)) for c in cpus]
    start = time.perf_counter()
    for t in threads: t.start()
    for t in threads: t.join()
    return time.perf_counter() - start

os.sched_setaffinity(0, {CPUS[0]})
one, many = run(CPUS[:1]), run(CPUS)
print(f"1 thread : {one:.3f}s")
print(f"{len(CPUS)} threads: {many:.3f}s")
print(f"scaling  : {one * len(CPUS) / many:.1f}x out of {len(CPUS)}.0x ideal")

On a free-threaded 3.16.0a0 (main), turbo boost disabled, workers pinned to distinct physical cores as suggested in gh-118527:

1 thread : 0.047s
8 threads: 0.362s
scaling  : 1.0x out of 8.0x ideal

Where it comes from

Logger.isEnabledFor takes no lock on its fast path:

if self.disabled:
    return False
try:
    return self._cache[level]
except KeyError:
    ...

self._cache is a dict living on a logger that every thread shares, so each call increments and decrements that dict's reference count. The logger is owned by whichever thread created it, so all the other threads take the shared refcount path, which is an atomic read-modify-write on one field.

perf c2c on this workload puts 99.77% of the HITM events on a single cache line. Within that line, offset 0x10 accounts for about 86% of them, and the top symbols are _Py_DecRefShared and _PyEval_EvalFrameDefault. Offset 0x10 in the free-threaded object header is ob_ref_shared, so the threads are contending on a reference count rather than on any data.

To check that the dict is the whole story rather than something else in the call, I compared two Logger subclasses that differ only in how the answer is cached. Both do the same self.disabled check, the same single attribute read, and the same method call:

Small ints are immortal, so the int version never touches a reference count and the contention disappears.

Possible fix, and a complication

Both conditions the cache encodes are thresholds: logging is off below manager.disable and below the logger's effective level. So max(manager.disable + 1, getEffectiveLevel()) gives an answer identical to the dict for every level, in one integer.

I tried this against Lib/logging/__init__.py. The whole test suite passes, the reproducer above goes from 1.0x to 6.9x, and single-threaded it is faster too: isEnabledFor 77.2ns to 65.0ns, and the disabled log.debug() 135ns to 122ns, measured pinned with turbo off.

The complication is invalidation. A single threshold covers every level, so it is stale the moment the level changes without _clear_cache() being called, whereas the dict is only stale for levels that were queried before. Two paths do that today: assigning to manager.disable directly rather than calling logging.disable(), and assigning to logger.level directly rather than calling setLevel(). The second is gh-82038, open since 2019.

Making Logger.level and Manager.disable properties that invalidate on write fixes both, and gh-82038 with them. But turning level into a descriptor costs real time on reads: logger.level went from 16.9ns to 35.6ns, and getEffectiveLevel() from 83.4ns to 144ns because it reads level once per ancestor while walking the parent chain. Both are public API.

So there is a genuine trade-off here and I did not want to pick the answer in a pull request. Roughly the options are to keep the dict and fix gh-82038 on its own, or take the int threshold together with the properties and accept slower level reads, or find a way to invalidate that does not put a descriptor on the hot attribute.

Happy to prepare whichever a maintainer prefers. Measurements above used turbo boost disabled and workers pinned to separate physical cores; the timings are timeit best-of-5 pinned to one core, so the sub-10% single-threaded numbers should be confirmed with pyperf before anyone relies on them.

CPython versions tested on:

3.16 (main)

Operating systems tested on:

Linux

Lib/logging/init.py の Logger.isEnabledFor から開始し、Manager.disable、Logger.level、_clear_cache に関係するキャッシュ無効化の経路を確認します。free-threaded のスケーリング結果を再現し、その後、方向性を提案する前に gh-82038 と issue で測定された代替案を検討します。無効化された呼び出しの競合に対処しつつ、公開されている level へのアクセスやキャッシュの正確性を後退させない合意済みの設計に達すれば完了です。