[Ar-maan05]

Logger.setLevel() and logging.disable() call Manager._clear_cache(), which walks every logger in loggerDict to clear its isEnabledFor cache, whether or not it has cached anything. Setting levels on N loggers one at a time is O(N^2):

              before     after
1000 loggers  0.392 s    0.003 s
2000 loggers  1.562 s    0.006 s
4000 loggers  6.255 s    0.012 s
8000 loggers  24.787 s   0.025 s

(debug build of main, script from the issue)

The manager now keeps a WeakSet of loggers that have populated their cache. isEnabledFor adds itself on the cache-miss path, inside the lock it already takes, so the hot cache-hit path is untouched. _clear_cache clears those loggers and empties the set. That also covers loggers that are not in loggerDict, so logging.Logger("x").setLevel(logging.ERROR) no longer leaves a stale isEnabledFor result behind.

test_logging passes, with new tests for the stale cache and for the set being emptied.

• Issue: logging: Logger.setLevel() and logging.disable() are O(number of loggers) #160936

[eendebakpt]

As mentioned on the issue, is this a real-world problem? There are some issues with the current approach:

1. Loggers that fail the loggerDict.get(logger.name) is logger check (e.g. created directly with logging.Logger(name)) are never discarded, so every setLevel() keeps visiting them. With 4000 such loggers alive, setLevel() goes from ~1 µs on main to ~1 ms.
2. Per-item discard() leaves dummy slots in the set, and re-adding the same logger reuses them, so the table never shrinks after one bulk invalidation. After 4000 cached loggers are cleared once, every later setLevel() stays 5-10x slower than on main.

Both go away by clearing all loggers in the set unconditionally and then emptying the set:

        with _lock:
            for logger in self._cached_loggers:
                logger._cache.clear()
            self._cached_loggers.clear()
            self.root._cache.clear()

Some more details

Clearing a superset of what `main` clears is safe, and as a bonus it fixes a stale cache for loggers not in `loggerDict` (`Logger("x").setLevel(ERROR)` currently leaves `isEnabledFor(DEBUG)` True). Please add a test for that and for `_cached_loggers` being empty after `setLevel()`.

Reproducer for both:

import logging, time

lg = logging.getLogger("one")

def us_per_setlevel():
    t0 = time.perf_counter()
    for _ in range(2000):
        lg.setLevel(logging.INFO)
        lg.isEnabledFor(logging.DEBUG)
    return (time.perf_counter() - t0) / 2000 * 1e6

print(f"baseline:              {us_per_setlevel():7.1f} us")

registered = [logging.getLogger(f"app.mod{i}") for i in range(4000)]
for l in registered:
    l.isEnabledFor(logging.DEBUG)
lg.setLevel(logging.INFO)
print(f"after bulk invalidate: {us_per_setlevel():7.1f} us")   # (2)

logging.root.manager.loggerDict.clear()
standalone = [logging.Logger(f"s{i}") for i in range(4000)]
for l in standalone:
    l.isEnabledFor(logging.DEBUG)
print(f"4000 standalone alive: {us_per_setlevel():7.1f} us")   # (1)

Another approach would be to check the cache with a global counter.

_cache_version = 0                      # module global, bumped in _clear_cache

    def isEnabledFor(self, level):
        if self.disabled:
            return False
        if self._cache_version == _cache_version:
            return level >= self._threshold
        with _lock:
            threshold = max(self.getEffectiveLevel(), self.manager.disable + 1)
            self._threshold = threshold
            self._cache_version = _cache_version
        return level >= threshold

That might also help with gh-155106 (the PR now is neutral for contention)

[Ar-maan05]

Thanks for digging into this! Both slowdowns reproduce here and your version fixes them, so I've switched to it and added the two tests.

Short answer on real-world use: I found this by reading the code, not from an app of my own that was hurting. But the slow path is an idiom people really use, looping over loggerDict and calling setLevel() on each logger, for example in metavoice-src and ktrain. That's a one-time hit in most apps, small until you have thousands of loggers, so I wouldn't oversell the speedup alone.

What makes it worth it to me is that it's now a tiny change that also fixes a real bug on main: a standalone logger keeps a stale isEnabledFor result after setLevel(). The cache-hit path doesn't change at all.

The version counter looks neat, but it's a bigger change to isEnabledFor, so I'd keep it out of this PR and let it go with gh-155106 if it helps there.

[Ar-maan05]

Good idea, added before and after checks to both tests!

[picnixz]

you shoudl also have some cleanup (or if it's not the case, you can add this in setUp() and tearDown()). We don't want the cache to be possibly polluted for the next test.

[Ar-maan05]

Good catch, both new tests now clean up after themselves!