Skip to content

bpo-30962: Add caching to Logger.isEnabledFor() #2752

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
vsajip merged 7 commits into from
Jul 30, 2017
Merged

bpo-30962: Add caching to Logger.isEnabledFor() #2752

Changes from 1 commit
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
26a8efc
Add caching to Logger.isEnabledFor()
avylove Jul 18, 2017
aeec4d9
Fix bugs in proposed caching mechanism
avylove Jul 18, 2017
7deaaab
Save newly cached result to local variable to avoid race condition
avylove Jul 18, 2017
f3b23ad
Missing clearing of root logger cache
avylove Jul 19, 2017
d10e0e2
Add test for log caching
avylove Jul 28, 2017
d6d28ec
Update log caching tests
avylove Jul 28, 2017
11fee13
reset manager.disable on log test teardown
avylove Jul 28, 2017
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
26 changes: 23 additions & 3 deletions Lib/logging/__init__.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1244,6 +1244,17 @@ 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

@vstinner vstinner Jul 18, 2017

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

@avylove avylove Jul 18, 2017

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

@vstinner vstinner Jul 18, 2017

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():
logger._cache.clear()
_releaseLock()

#---------------------------------------------------------------------------
# Logger classes and functions
#---------------------------------------------------------------------------
Expand Down Expand Up @@ -1274,12 +1285,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 +1556,15 @@ def isEnabledFor(self, level):
"""
Is this logger enabled for level 'level'?
"""
if self.manager.disable >= level:
return False
return level >= self.getEffectiveLevel()
if level not in self._cache:
_acquireLock()
if self.manager.disable >= level:
Copy link
Member

@vsajip vsajip Jul 28, 2017

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

@avylove avylove Jul 28, 2017

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

@avylove avylove Jul 28, 2017

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

@avylove avylove Jul 28, 2017

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

@vsajip vsajip Jul 28, 2017

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

@avylove avylove Jul 28, 2017

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.

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

return self._cache[level]
Copy link
Member

@vstinner vstinner Jul 18, 2017

Choose a reason for hiding this comment

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

There is a risk of race condition if first you test if the key exists and then sets the key.

Why not using: "try: return self._cache[level] except KeyError: ..."?

Copy link
Member

@pitrou pitrou Jul 18, 2017

Choose a reason for hiding this comment

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

The real race condition is if clear_cache() is called in-between. But, yes, your proposed idiom would fix it.

Copy link
Contributor Author

@avylove avylove Jul 18, 2017

Choose a reason for hiding this comment

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

Makes sense. Fixed that to use try/except


def getChild(self, suffix):
"""
Expand Down Expand Up @@ -1910,6 +1929,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