Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
30 changes: 27 additions & 3 deletions Lib/logging/__init__.py
Original file line number Diff line number Diff line change
Expand Up @@ -1244,6 +1244,19 @@ def _fixupChildren(self, ph, alogger):
alogger.parent = c.parent
c.parent = alogger

def _clear_cache(self):
"""
Clear the cache for all loggers in loggerDict
Called when level changes are made
"""

_acquireLock()
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not sure that a lock is useful here.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Isn't it needed to keep another thread from changing loggerDict or the cache dictionaries?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh ok, right, I first understood that the lock was supposed to protect the cache :-) I don't think that the cache deserves a lock.

for logger in self.loggerDict.values():
if isinstance(logger, Logger):
logger._cache.clear()
self.root._cache.clear()
_releaseLock()

#---------------------------------------------------------------------------
# Logger classes and functions
#---------------------------------------------------------------------------
Expand Down Expand Up @@ -1274,12 +1287,14 @@ def __init__(self, name, level=NOTSET):
self.propagate = True
self.handlers = []
self.disabled = False
self._cache = {}

def setLevel(self, level):
"""
Set the logging level of this logger. level must be an int or a str.
"""
self.level = _checkLevel(level)
self.manager._clear_cache()

def debug(self, msg, *args, **kwargs):
"""
Expand Down Expand Up @@ -1543,9 +1558,17 @@ def isEnabledFor(self, level):
"""
Is this logger enabled for level 'level'?
"""
if self.manager.disable >= level:
return False
return level >= self.getEffectiveLevel()
try:
return self._cache[level]
except KeyError:
_acquireLock()
if self.manager.disable >= level:
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Would it not make more sense to cache the result of getEffectiveLevel(), rather than isEnabledFor()? From what I can see, the time saving is really from cutting out the hierarchy walk in the former method.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That is where most of the time savings is, but it's still faster (Something like 5%) than checking self.manager.disable every time.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does have me thinking, in the LoggerAdapter class, there's currently no caching. LoggerAdapter.isEnabledFor() reimplements the logic from Logger.isEnabledFor(). If we point to Logger.isEnabledFor() instead of reimplementing, we get caching. I don't see a functional difference. Is there?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@vsajip The only thing I see is LoggerAdapter.getEffectiveLevel() could be overwritten and that would change the behavior of LoggerAdapter.isEnabledFor(). That would not be the case if LoggerAdapter.isEnabledFor() pointed to Logger.isEnabledFor(). So if we want caching on adapters (and we probably do), the caching logic should be duplicated on the adapter. The alternative is to give up some performance and move caching to getEffectiveLevel(). Thoughts?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't see a functional difference. Is there?

The manager.disable check is [duplicated] there because it would potentially allow skipping the hierarchy walk of getEffectiveLevel().

The alternative is to give up some performance and move caching to getEffectiveLevel()

Although it slows down isEnabledFor() because of still needing the manager.disable check, I think it would be better to cache getEffectiveLevel(). It's easier to reason about. The manager.disable level shouldn't be conflated with the effective levels of individual loggers, IMO.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I understand why the manager.disable check is in Logger.isEnabledFor(). What I was trying to say is having LoggerAdapter.isEnabledFor() reimplement Logger.isEnabledFor() only makes sense if someone is going to subclass LoggerAdapter and overwrite LoggerAdapter.getEffectiveLevel().

I wasn't associating the caching with the levels, but rather the isEnabledFor() call. I guess another benefit of moving it would be it also speeds up calls to getEffectiveLevel(). I'm not sure how often that's used outside of this module, but I'm sure it is.

is_enabled = self._cache[level] = False
else:
is_enabled = self._cache[level] = level >= self.getEffectiveLevel()
_releaseLock()

return is_enabled

def getChild(self, suffix):
"""
Expand Down Expand Up @@ -1910,6 +1933,7 @@ def disable(level=CRITICAL):
Disable all logging calls of severity 'level' and below.
"""
root.manager.disable = level
root.manager._clear_cache()

def shutdown(handlerList=_handlerList):
"""
Expand Down
60 changes: 59 additions & 1 deletion Lib/test/test_logging.py
Original file line number Diff line number Diff line change
Expand Up @@ -135,7 +135,9 @@ def tearDown(self):
logging._handlers.clear()
logging._handlers.update(self.saved_handlers)
logging._handlerList[:] = self.saved_handler_list
loggerDict = logging.getLogger().manager.loggerDict
manager = logging.getLogger().manager
manager.disable = 0
loggerDict = manager.loggerDict
loggerDict.clear()
loggerDict.update(self.saved_loggers)
logger_states = self.logger_states
Expand Down Expand Up @@ -4094,6 +4096,62 @@ def test_pickling(self):
unpickled = pickle.loads(s)
self.assertIs(unpickled, logger)

def test_caching(self):
root = self.root_logger
logger1 = logging.getLogger("abc")
logger2 = logging.getLogger("abc.def")

# Set root logger level and ensure cache is empty
root.setLevel(logging.ERROR)
self.assertEqual(logger2.getEffectiveLevel(), logging.ERROR)
self.assertEqual(logger2._cache, {})

# Ensure cache is populated and calls are consistent
self.assertTrue(logger2.isEnabledFor(logging.ERROR))
self.assertFalse(logger2.isEnabledFor(logging.DEBUG))
self.assertEqual(logger2._cache, {logging.ERROR: True, logging.DEBUG: False})
self.assertEqual(root._cache, {})
self.assertTrue(logger2.isEnabledFor(logging.ERROR))

# Ensure root cache gets populated
self.assertEqual(root._cache, {})
self.assertTrue(root.isEnabledFor(logging.ERROR))
self.assertEqual(root._cache, {logging.ERROR: True})

# Set parent logger level and ensure caches are emptied
logger1.setLevel(logging.CRITICAL)
self.assertEqual(logger2.getEffectiveLevel(), logging.CRITICAL)
self.assertEqual(logger2._cache, {})

# Ensure logger2 uses parent logger's effective level
self.assertFalse(logger2.isEnabledFor(logging.ERROR))

# Set level to NOTSET and ensure caches are empty
logger2.setLevel(logging.NOTSET)
self.assertEqual(logger2.getEffectiveLevel(), logging.CRITICAL)
self.assertEqual(logger2._cache, {})
self.assertEqual(logger1._cache, {})
self.assertEqual(root._cache, {})

# Verify logger2 follows parent and not root
self.assertFalse(logger2.isEnabledFor(logging.ERROR))
self.assertTrue(logger2.isEnabledFor(logging.CRITICAL))
self.assertFalse(logger1.isEnabledFor(logging.ERROR))
self.assertTrue(logger1.isEnabledFor(logging.CRITICAL))
self.assertTrue(root.isEnabledFor(logging.ERROR))

# Disable logging in manager and ensure caches are clear
logging.disable()
self.assertEqual(logger2.getEffectiveLevel(), logging.CRITICAL)
self.assertEqual(logger2._cache, {})
self.assertEqual(logger1._cache, {})
self.assertEqual(root._cache, {})

# Ensure no loggers are enabled
self.assertFalse(logger1.isEnabledFor(logging.CRITICAL))
self.assertFalse(logger2.isEnabledFor(logging.CRITICAL))
self.assertFalse(root.isEnabledFor(logging.CRITICAL))


class BaseFileTest(BaseTest):
"Base class for handler tests that write log files"
Expand Down