bpo-30962: Add caching to Logger.isEnabledFor() by avylove · Pull Request #2752 · python/cpython (original) (raw)

@vsajip I was wrong about how much slower it would be. I ran some benchmarks to compare putting the caching in isEnabledFor() vs getEffectiveLevel() and I think it would be best to leave it where it is.

Here's how I implemented caching in getEffectiveLevel(). I retained the dictionary so the check and fetch can be a single operation to avoid race conditions.

def getEffectiveLevel(self): try: return self._cache['_elevel'] except KeyError: _acquireLock() logger = self effective_level = NOTSET while logger: if logger.level: effective_level = logger.level break logger = logger.parent self._cache['_elevel'] = effective_level _releaseLock()

    return effective_level

I expanded my original benchmarking code to test at all the loggers in the hierarchy, not just the third level

import timeit

count = 10000000

set_up = """ root = logging.getLogger() logger1 = logging.getLogger('1') logger2 = logging.getLogger('1.2') logger3 = logging.getLogger('1.2.3') """

for logger in ('root', 'logger1', 'logger2', 'logger3'): statement = "%s.debug('Debug message')" % logger

orig = timeit.timeit(statement, number=count,
                     setup='import logging_orig as logging\n' + set_up)
ief = timeit.timeit(statement, number=count,
                     setup='import logging_cache_ief as logging\n' + set_up)
gel = timeit.timeit(statement, number=count,
                     setup='import logging_cache_gel as logging\n' + set_up)

print('--- %s ---' % logger)
print('Non-caching:  ', orig)
print('With Caching (isEnabledFor): ', ief)
print('With Caching (getEffectiveLevel): ', gel)
print('Time decrease (isEnabledFor): %.2f%%' % ((orig - ief) / orig * 100))
print('Time decrease (getEffectiveLevel): %.2f%%' % ((orig - gel) / orig * 100))

From the results you can see that as the logger hierarchy grows, the difference becomes less apparent, but caching at isEnabledFor() is much faster. I think this can be attributed to the significant reduction in operations (lookups and comparisons).

--- root --- Non-caching: 5.672386677993927 With Caching (isEnabledFor): 3.272040506999474 With Caching (getEffectiveLevel): 5.023688525019679 Time decrease (isEnabledFor): 42.32% Time decrease (getEffectiveLevel): 11.44% --- logger1 --- Non-caching: 6.022408013988752 With Caching (isEnabledFor): 3.288163874996826 With Caching (getEffectiveLevel): 5.099931188975461 Time decrease (isEnabledFor): 45.40% Time decrease (getEffectiveLevel): 15.32% --- logger2 --- Non-caching: 7.034587770991493 With Caching (isEnabledFor): 3.271738503011875 With Caching (getEffectiveLevel): 5.257907326973509 Time decrease (isEnabledFor): 53.49% Time decrease (getEffectiveLevel): 25.26% --- logger3 --- Non-caching: 7.899996431020554 With Caching (isEnabledFor): 3.420868766028434 With Caching (getEffectiveLevel): 5.191981957992539 Time decrease (isEnabledFor): 56.70% Time decrease (getEffectiveLevel): 34.28%