On 25/12/2012 7:23am, Andrew Grigorev wrote:

class Factorial: def __init__(self, n): self.n = n def calculate(self): return factorial(n) def __str__(self): return str(self.calculate)

logging.debug("Factorial of %d is %s", 2**15, Factorial(2**15))

A more generic alternative would be class str_partial(functools.partial): def __str__(self): return str(self()) logging.debug("Factorial of %d is %s", 2**15, str_partial(factorial, 2**15))) -- Richard

Why not pass the function/method, args, kwargs to log.debug and let log.debug decide if it should execute or not, e.g. log.debug(factorial, 2**15) On Tue, Dec 25, 2012 at 7:40 AM, Jasper St. Pierre wrote:

if __debug__: log(factorial(2**15))

Running python with -O will squash this statement. To have something inline, you could also abuse assert statements to do the job.

def debug_log(x): log(x) return True

assert debug_log(factorial(2**15))

In optimized builds, the statement will be removed entirely.

On Tue, Dec 25, 2012 at 1:28 AM, anatoly techtonik wrote:

...

For the logging module it will be extremely useful if Python included a way to disactivate processing certain blocks to avoid making sacrifices between extensive logging harness and performance. For example, instead of writing:

if log.DEBUG==True: log(factorial(2**15))

It should be possible to just write: log(factorial(2**15))

if if log() is an instance of some Nopable class, the statement in log's braces is not executed. -- anatoly t.

_______________________________________________ Python-ideas mailing list Python-ideas@python.org http://mail.python.org/mailman/listinfo/python-ideas

-- Jasper

_______________________________________________ Python-ideas mailing list Python-ideas@python.org http://mail.python.org/mailman/listinfo/python-ideas

On Tue, Dec 25, 2012 at 9:11 PM, Rene Nejsum wrote:

But if debug() was indeed NOP'able, maybe it could be done ?

If someone *really* wants to do this, they can abuse assert statements (which will be optimised out under "-O", just like code guarded by "if __debug__"). That doesn't make it a good idea - you most need log messages to investigate faults in production systems that you can't (or are still trying to) reproduce in development and integration environments. Compiling them out instead of deactivating them with runtime configuration settings means you can't switch them on without restarting the system with different options. This does mean that you have to factor in the cost of logging into your performance targets and hardware requirements, but the payoff is an increased ability to correctly diagnose system faults (as well as improving your ability to extract interesting metrics from log messages). Excessive logging calls certainly *can* cause performance problems due to the function call overhead, as can careless calculation of expensive values that aren't needed. One alternatives occasional noted is that you could design a logging API that can accept lazily evaluated callables instead of ordinary parameters. However, one danger of such expensive logging it that enabling that logging level becomes infeasible in practice, because the performance hit is too significant. The typical aim for logging is that your overhead should be such that enabling it in production means your servers run a little hotter, or your task takes a little longer, not that your application grinds to a halt. One good way to achieve this is to decouple the expensive calculations from the main application - you instead log the necessary pieces of information, which can be picked up by an external service and the calculation performed in a separate process (or even on a separate machine) where it won't affect the main application, and where you only calculate it if you actually need it for some reason. Cheers, Nick. -- Nick Coghlan | ncoghlan@gmail.com | Brisbane, Australia

On Tue, Dec 25, 2012 at 10:42 PM, Rene Nejsum wrote:

Add's 5-10% extra code lines, whereas if we could do:

log.debug( bla. bla )

at the same cost would save a lot of lines.

Right, that's where the lazy evaluation API idea comes in where there's no choice except to do the expensive calculation in process and you want to factor out the logging level check, it's possible to replace it with 7 characters embedded in the call: debug_lazy(lambda: bla. bla.) You can also do much more sophisticated things with the logging event handling system that only trigger if an event passes the initial priority level check and gets submitted to the rest of the logging machinery. There's no magic wand we can wave to say "evaluate this immediately sometimes, but lazily other times based on some unknown global state". An API has to choose one or the other. The standard logging APIs chooses do lazy evaluation of formatting calls, but eager evaluation of the interpolated values in order to speed up the typical case of readily accessible data - that's why the active level query API is exposed. Another logging API could certainly make the other choice, adapting to the standard APIs via the level query API. I don't know if such an alternative API exists - my rule of thumb for logging calls is if something is too expensive to calculate all the time, find a way to instead pass the necessary pieces for external reconstruction to a lazy formatting call rather than making a given level of logging prohibitively expensive. Cheers, Nick. -- Nick Coghlan | ncoghlan@gmail.com | Brisbane, Australia

Rene Nejsum writes:

So doing:

if log.debug.enabled(): log.debug( bla. bla. )

Add's 5-10% extra code lines, whereas if we could do:

log.debug( bla. bla )

at the same cost would save a lot of lines.

Bearing in mind that the first statement in the debug (and analogous methods) is a check for the level, the only thing you gain by having the same check outside the call is the cost of evaluating arguments. But you can also do this by passing an arbitrary class as the message object, which lazily evaluates only when needed. Contrived example: class Message(object): def __init__(self, func, x, y): # params should be cheap to evaluate self.func = func self.x = x self.y = y def __str__(self): return str(self.func(self.x**self.y)) # expense is incurred here logger.debug(Message(factorial, 2, 15)) With this setup, no if statements are needed in your code, and the expensive computations only occur when required. Regards, Vinay Sajip

I think we all agree that it cannot be done in Python right now… But i doubt there will be support for a solution just for debugging, and I am having a hard time coming up with other examples… Quick thought (very quick) and I am no expert, but maybe an acceptable/compatible solution could be: def do_debug(*args): print 'DEBUG: ', args def nop_debug(*args): pass # Empty function debug = do_debug debug( "Some evaluated text %d %d %d" % (1, 2, fact(22)) ) debug = nop_debug debug( "Will not be evaluated, since Python is clever enough to optimise out") At least some kind of -O option could optimise this out ? Then again, there are probably lot's of reasons for this not to work :-) /Rene On Dec 26, 2012, at 12:04 AM, anatoly techtonik wrote:

On Tue, Dec 25, 2012 at 5:45 PM, Vinay Sajip wrote: Rene Nejsum writes:

...

So doing:

if log.debug.enabled(): log.debug( bla. bla. )

Add's 5-10% extra code lines, whereas if we could do:

log.debug( bla. bla )

at the same cost would save a lot of lines.

Bearing in mind that the first statement in the debug (and analogous methods) is a check for the level, the only thing you gain by having the same check outside the call is the cost of evaluating arguments. But you can also do this by passing an arbitrary class as the message object, which lazily evaluates only when needed. Contrived example:

class Message(object): def __init__(self, func, x, y): # params should be cheap to evaluate self.func = func self.x = x self.y = y

def __str__(self): return str(self.func(self.x**self.y)) # expense is incurred here

logger.debug(Message(factorial, 2, 15))

With this setup, no if statements are needed in your code, and the expensive computations only occur when required.

That's still two function calls and three assignments per logging call. Too expensive and syntax unwieldy. I think everybody agrees now that for existing CPython implementation there is really no solution for the problem of expensive logging calls vs code clarity. You have to implement optimization workaround at the cost of readability.

The idea is to fix the interpreter, introducing a "feature block" - execution block that works only if it is enabled. Execution block for logging example below is defined by function name "debug" and braces ().

debug( <block contents> )

debug is an object of 'feature' type, which is only executed/evaluated, if the feature is enabled in a table of features.

It might be possible to implement this as a custom version of PyPy. Then by hardcoding logic for treating logging call as 'featured' should give an immediate performance boost to any project. Still it would be nice if logging was build with supported layout for easy optimization or for 'from __future__ import features.logging' . _______________________________________________ Python-ideas mailing list Python-ideas@python.org http://mail.python.org/mailman/listinfo/python-ideas

On Tue, Dec 25, 2012 at 11:12 PM, Ned Batchelder wrote:

On 12/25/2012 6:04 PM, anatoly techtonik wrote:

...

...

logger.debug(Message(**factorial, 2, 15))

...

With this setup, no if statements are needed in your code, and the expensive computations only occur when required.

That's still two function calls and three assignments per logging call. Too expensive and syntax unwieldy. I think everybody agrees now that for existing CPython implementation there is really no solution for the problem of expensive logging calls vs code clarity. You have to implement optimization workaround at the cost of readability.

Anatoly, do you have some measurements to justify the "too expensive" claim? Also, do you have an actual example of expensive logging? I doubt your real code is logging the factorial of 2**15. What is actually in your debug log that is expensive? It will be much easier to discuss solutions if we are talking about actual problems.

I was thinking the same thing as I read though this thread. I'm typically logging the result of a calculation and not doing a calculation only because I'm logging. On the other hand I have used a homegrown logging system (existed well before Python's logging module) that allowed the following:

...

...

logger.warn('factorial = %s', lambda: factorial(2**15))

Instead of just outputting the string representation of the lambda the logger would evaluate the function and str() the return value. Something like this would be trivial to implement on top of Python's logging module. -- David blog: http://www.traceback.org twitter: http://twitter.com/dstanek www: http://dstanek.com

My astoptimizer provides tools to really *remove* debug at compilation, so the overhead of the debug code is just null. You can for example declare your variable project.config.DEBUG as constant with the value 0, where project.config is a module. So the if statement in "from project.config import DEBUG ... if DEBUG: ..." will be removed. See: https://bitbucket.org/haypo/astoptimizer Victor Le 25 déc. 2012 13:43, "Rene Nejsum" a écrit :

I understand and agree with all your arguments on debugging.

At my company we typically make some kind of backend/server control software, with a LOT of debugging lines across many modules. We have 20+ debugging flags and in different situations we enable a few of those, if we were to enable all at once it would defently have an impact on production, but hopefully just a hotter CPU and a lot of disk space being used.

debug statements in our code is probably one per 10-20 lines of code.

I think my main issue (and what I therefore read into the original suggestion) was the extra "if" statement at every log statement

So doing:

if log.debug.enabled(): log.debug( bla. bla. )

Add's 5-10% extra code lines, whereas if we could do:

log.debug( bla. bla )

at the same cost would save a lot of lines.

And when you have 43 lines in your editor, it will give you 3-5 lines more of real code to look at :-)

/Rene

On Dec 25, 2012, at 1:28 PM, Nick Coghlan wrote:

...

On Tue, Dec 25, 2012 at 9:11 PM, Rene Nejsum wrote:

...

But if debug() was indeed NOP'able, maybe it could be done ?

If someone *really* wants to do this, they can abuse assert statements (which will be optimised out under "-O", just like code guarded by "if __debug__"). That doesn't make it a good idea - you most need log messages to investigate faults in production systems that you can't (or are still trying to) reproduce in development and integration environments. Compiling them out instead of deactivating them with runtime configuration settings means you can't switch them on without restarting the system with different options.

This does mean that you have to factor in the cost of logging into your performance targets and hardware requirements, but the payoff is an increased ability to correctly diagnose system faults (as well as improving your ability to extract interesting metrics from log messages).

Excessive logging calls certainly *can* cause performance problems due to the function call overhead, as can careless calculation of expensive values that aren't needed. One alternatives occasional noted is that you could design a logging API that can accept lazily evaluated callables instead of ordinary parameters.

However, one danger of such expensive logging it that enabling that logging level becomes infeasible in practice, because the performance hit is too significant. The typical aim for logging is that your overhead should be such that enabling it in production means your servers run a little hotter, or your task takes a little longer, not that your application grinds to a halt. One good way to achieve this is to decouple the expensive calculations from the main application - you instead log the necessary pieces of information, which can be picked up by an external service and the calculation performed in a separate process (or even on a separate machine) where it won't affect the main application, and where you only calculate it if you actually need it for some reason.

Cheers, Nick.

-- Nick Coghlan | ncoghlan@gmail.com | Brisbane, Australia

_______________________________________________ Python-ideas mailing list Python-ideas@python.org http://mail.python.org/mailman/listinfo/python-ideas

If you mark constant.DEBUG as constant and compile your project with astoptimizer, enable_debug has no effect (if it was compiled with DEBUG=False). So only use it if DEBUG will not be changed at runtime. It cannot be used if your users might run your applucation in debug mode. To compare it to the C language, DEBUG would be a #define and astoptimizer can be see as a preprocessor. Victor Le 30 déc. 2012 11:59, "Stefan Behnel" a écrit :

Victor Stinner, 30.12.2012 11:42:

...

My astoptimizer provides tools to really *remove* debug at compilation, so the overhead of the debug code is just null.

You can for example declare your variable project.config.DEBUG as constant with the value 0, where project.config is a module. So the if statement in "from project.config import DEBUG ... if DEBUG: ..." will be removed.

How would you know at compile time that it can be removed? How do you handle the example below?

Stefan

## constants.py

DEBUG = False

## enable_debug.py

import constants constants.DEBUG = True

## test.py

import enable_debug from constants import DEBUG

if DEBUG: print("DEBUGGING !")

_______________________________________________ Python-ideas mailing list Python-ideas@python.org http://mail.python.org/mailman/listinfo/python-ideas

I think the lambda: solution really is the best solution. The additional cost is the construction of one function object and one invocation per logging call, which i suspect is about the lower limit. It's also the most generally applicable: it has nothing specific to logging in it at all! So it seems to me that if we were to change anything, improving the lambdas (shorter syntax and/or optimizing away the overhead) would be the way to go over some string-interpolation-logging-specific special case in the interpreter. On Wed, Dec 26, 2012 at 5:49 AM, Greg Ewing wrote:

Rene Nejsum wrote:

...

Interessting alternatives, but they do not quite come on as flexible/usefull enough…

Often debug statements have a lot of text and variables, like:

log.debug( "The value of X, Y, Z is now: %d %s %d" % ( x, lookup(y), factorial(2**15))

That needn't be a problem:

log.lazydebug(lambda: "The value of X, Y, Z is now: %d %s %d" % (x, lookup(y), factorial(2**15)))

-- Greg

______________________________**_________________ Python-ideas mailing list Python-ideas@python.org http://mail.python.org/**mailman/listinfo/python-ideashttp://mail.python.org/mailman/listinfo/python-ideas