Python overhead with function in argument
I am using python registration module (python 3.4.3). Let's say my logging level is set to INFO and I would like to use a function as an argument to my log message.
Now I would expect when the log level is lowered (like WARNING) that the argument functions are not executed.
It's true?
Example (console):
>>> import math
>>> import logging
>>> logging.basicConfig(level=logging.INFO)
>>> logging.debug('Factorial of 100000=',math.factorial(100000))
>>> */empty output but slightly delayed, small CPU peak/*
>>> logging.debug('Factorial of 10=',math.factorial(10))
>>> */empty output but instant, no noticeable CPU usage/*
The function probably failed, but there is still a noticeable delay. Can someone please explain to me a possible reason?
source to share
Evaluating Function Arguments Before Calling
Well you see that the arguments you pass to logging.debug('Factorial of 100000=', math.factorial(100000))
must be evaluated before being logging.debug()
called, and the evaluation math.factorial(100000)
will take time
It doesn't matter, ultimately the function does nothing in its call, the arguments will still be evaluated
Conceptually, you can think of it as work
value = math.factorial(100000) # This gets evaluated
logging.debug('Factorial is %d', value) # Even if this is a "no op" call,
# the arg evaluation still takes place
Bypass
import math
import logging
logging.basicConfig(level=logging.INFO)
logger = logging.getLogger()
if logger.getEffectiveLevel() <= logging.DEBUG: # Or use == if you want DEBUG only
logger.debug('Factorial is %d', math.factorial(100000))
Using Python 3 logger.getEffectiveLevel ()
Considering the levels are ordered like
CRITICAL 50
ERROR 40
WARNING 30
INFO 20
DEBUG 10
NOTSET 0
You can see that our if-block (c <= logging.DEBUG
) will only work on DEBUG
and below (so DEBUG
and NOTSET
)
source to share
The problem is that you are evaluating the function before calling. One way to combat this is to use logger.getEffectiveLevel()
as described bakkal. This can be a little verbose. Another way to get around this is to create an intermediate object to navigate to the registrar that does the work in it __str__
. This delays the function call until the logger is sure the message will be sent.
For example:
import logging
import math
class CallableMsg:
def __init__(self, func, *args, **kwargs):
self.func = func
self.args = args
self.kwargs = kwargs
def __str__(self):
return str(self.func(*self.args, **self.kwargs))
logging.basicConfig(level=logging.INFO)
# single arg log
logging.info(CallableMsg(math.factorial, 10))
# using the CallableMsg in a format string
logging.info("10! = %s", CallableMsg(math.factorial, 10))
# factorial function never gets evaluated for the debug call
logging.debug(CallableMsg(math.factorial, 1000000))
The log module is also large enough to store the line on which the log call was actually made, in case there is any error.
logging.info(CallableMsg(math.factorial, -1))
Outputs:
--- Logging error ---
Traceback (most recent call last):
File "C:\Python34\lib\logging\__init__.py", line 971, in emit
msg = self.format(record)
File "C:\Python34\lib\logging\__init__.py", line 821, in format
return fmt.format(record)
File "C:\Python34\lib\logging\__init__.py", line 558, in format
record.message = record.getMessage()
File "C:\Python34\lib\logging\__init__.py", line 319, in getMessage
msg = str(self.msg)
File "C:python\run.py", line 12, in __str__
return str(self.func(*self.args, **self.kwargs))
ValueError: factorial() not defined for negative values
Call stack:
File "<string>", line 1, in <module>
File "C:\Python34\lib\idlelib\run.py", line 126, in main
ret = method(*args, **kwargs)
File "C:\Python34\lib\idlelib\run.py", line 353, in runcode
exec(code, self.locals)
File "C:\python\run.py", line 18, in <module>
logging.info(CallableMsg(math.factorial, -1))
Message: <__main__.CallableMsg object at 0x02ECF970>
Arguments: ()
source to share