Lazy evaluation of strings in python logging: comparing `%` with `.format`

Question

Is there any difference between these two calls:

import logging

logging.getLogger().debug('test: %i' % 42)

and

logging.getLogger().debug('test: {}'.format(42))

Where we assume 42 is replaced by some long computation (say 7.5 million years of computation) when it is cast to a string that produces a final answer of 42.

Is the first approach lazily evaluated in case logging is set to debug?

Check: https://stackoverflow.com/questions/40714555/python-string-formatting-is-more-efficient-than-format-function , for performance, probably will want `f-strings` which are faster than these methods, check: https://stackoverflow.com/questions/43123408/f-strings-in-python-3-6 — rafaelc, Aug 24 '18 at 22:52
Super useful reference, thanks RafaelC, though it hasn't clarified the lazy evaluation question. — David Parks, Aug 24 '18 at 22:54
In both of your examples, the formatted string gets fully evaluated by Python before the `logging` module gets involved in the process at all. You probably want to pass the format string and its parameters as *separate parameters* to `.debug()`, so that it actually does the formatting - I assume that it only does this if the message isn't going to be filtered out, but I'm not 100% sure of that. — jasonharper, Aug 24 '18 at 22:58
If you really want laziness, you need something like `if logging.getLogger().isEnabledFor(logging.DEBUG): …`. From your comments on the answers, though, it sounds like you don't need that. — abarnert, Aug 24 '18 at 23:32
See https://stackoverflow.com/q/4148790/2864740, perhaps. Solutions also show a proxy-object to *defer the cost of value generation*. Of course, generating debug values should still be "relatively quick" and "side-effect free" or the very act of enabling debugging will still be problematic/unexpected.. — user2864740, Aug 24 '18 at 23:40
Another related article: https://stackoverflow.com/questions/29147442/how-to-fix-pylint-logging-not-lazy — David Parks, Aug 24 '18 at 23:48

Martin · Accepted Answer · 2019-02-03T10:19:53.187

23

Neither are lazy. Both strings are interpolated before sent to logger. Lazy evaluation in terms of python logging is done with separate arguments. The documentation https://docs.python.org/2/library/logging.html suggest the following for lazy evaluation of string interpolation;

logging.getLogger().debug('test: %i', 42)

TL;DR In this case it’s easier to consider the following. We sent a primitive type (string) but only one argument to the logger. Thus it can’t be lazy.

edited Feb 03 '19 at 10:19

answered Aug 24 '18 at 23:02

Martin

619
5
13

1

Note that in Python 3.2+, [you can also do lazy evaluation with `str.format` style strings](https://docs.python.org/3/library/logging.html#logging.Formatter), although `%`-style is still the default. – abarnert Aug 24 '18 at 23:09
This is still *not lazy* in in the sense asked: `.debug('test: %i', takes_75_million_years_to_generate)` -- it only defers the creation of the *string* itself, not the generation of the value supplied as an argument, which is inconsequentially comparatively :} The original question is vague with "Where we assume 42 is replaced by some long computation (7.5 million years, for example) that produces a final answer of 42.", but once 42 is produced, the *cost has been paid*. – user2864740 Aug 24 '18 at 23:11
2

The original question was vague that way, my bad. I did only mean to ask about the evaluation of the string concatenation. Thank you bringing clarity to that point. – David Parks Aug 24 '18 at 23:15
I added "when cast to a string" to the original question to clarify this detail. – David Parks Aug 24 '18 at 23:44

score 5 · Answer 2 · answered Aug 24 '18 at 22:56

I'd take a look in the references I posted in the comments for more detailed information on % and .format().

For the lazy evaluation question, the answer is no.

A simple test will do

def func1(x):
    time.sleep(5)
    return(x)

def func2(x):
    #time.sleep(5)
    return(x)

%timeit 'debug1: %s' % func1(3)
5 s ± 1.31 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)
%timeit 'debug2: {}'.format(func1(3))
5 s ± 1.45 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)

%timeit 'debug1: %s' % func2(3)
297 ns ± 11.2 ns per loop (mean ± std. dev. of 7 runs, 1000000 loops each)
%timeit 'debug2: {}'.format(func2(3))
404 ns ± 4.56 ns per loop (mean ± std. dev. of 7 runs, 1000000 loops each)

In both .format (obviously) and % approaches,func() is calculated anyway.

Lazy evaluation of strings in python logging: comparing `%` with `.format`

2 Answers2