Lo snippet lo dimostra in maniera molto banale.
import logging
import time
log = logging.getLogger(__name__)
class SleepingBeauty(object):
def __init__(self):
super(SleepingBeauty, self).__init__()
def __str__(self):
time.sleep(2)
return "Yaaawn"
def test():
log.info('Starting')
sb = SleepingBeauty()
t0 = time.time()
log.debug('Testing str.format method: {0}'.format(sb))
t1 = time.time()
log.debug('Testing old awful method: %s', sb)
t2 = time.time()
log.info('Stopped')
log.info('Now some stats: t1-t0 = %.2f - t2-t1 = %.2f', t1-t0, t2-t1)
if __name__ == '__main__':
logging.basicConfig(level=logging.INFO)
test()
Il succo della questione è semplice:
Il livello di logging è INFO, quindi le chiamate "log.debug" non produrranno effetti.
Eppure nella prima delle due si pagano due secondi solo per preparare la stringa da passare alla chiamata, salvo poi scoprire che non verrà mai mostrata nei log.
La seconda invece non causa ritardi. Infatti l'esecuzione di "log.debug" termina (a causa dell'incompatibilità con il livello INFO) ben PRIMA di eseguire "str(sb)".
Chiaro, no? :-)
Post
