logger Pigro valutazione stringa di messaggio

Question

sto usando il modulo di registrazione standard di Python nella mia applicazione di pitone:

 
import logging 
logging.basicConfig(level=logging.INFO) 
logger = logging.getLogger("log") 
while True: 
    logger.debug('Stupid log message " + ' '.join([str(i) for i in range(20)])) 
    # Do something 

Il problema è che, anche se il livello di debug non è abilitazione, che stupido messaggio di log viene valutata su ogni iterazione del ciclo, che danneggia male le prestazioni.

C'è qualche soluzione per questo?

In C++ abbiamo log4cxx pacchetto che fornisce le macro in questo modo:
LOG4CXX_DEBUG(logger, messasage)
che valuta in modo efficace per

 
if (log4cxx::debugEnabled(logger)) { 
    log4cxx.log(logger,log4cxx::LOG4CXX_DEBUG, message) 
} 

Ma dal momento che non ci sono le macro in Python (per quanto ne so), se c'è un modo efficiente fare il logging?

Answer 1

Il modulo di registrazione ha già un supporto parziale per ciò che si desidera fare. Fare questo:

log.debug("Some message: a=%s b=%s", a, b) 

... invece di questo:

log.debug("Some message: a=%s b=%s" % (a, b)) 

Il modulo di registrazione è abbastanza intelligente per non produrre il messaggio di log completo se il messaggio viene effettivamente registrato da qualche parte.

Per applicare questa funzione alla richiesta specifica, è possibile creare una classe lazyjoin.

class lazyjoin: 
    def __init__(self, s, items): 
     self.s = s 
     self.items = items 
    def __str__(self): 
     return self.s.join(self.items) 

usare in questo modo (si noti l'uso di un generatore di espressione, aggiungendo alla pigrizia):

logger.info('Stupid log message %s', lazyjoin(' ', (str(i) for i in range(20)))) 

Ecco una demo che mostra questo funziona.

>>> import logging 
>>> logging.basicConfig(level=logging.INFO) 
>>> logger = logging.getLogger("log") 
>>> class DoNotStr: 
...  def __str__(self): 
...   raise AssertionError("the code should not have called this") 
... 
>>> logger.info('Message %s', DoNotStr()) 
Traceback (most recent call last): 
... 
AssertionError: the code should not have called this 
>>> logger.debug('Message %s', DoNotStr()) 
>>> 

Nella demo, La chiamata logger.info() ha colpito l'errore asserzione, mentre logger.debug() non ha ottenuto così lontano.

Answer 2

import logging 
import time 

logging.basicConfig(level=logging.INFO) 
logger = logging.getLogger("log") 

class Lazy(object): 
    def __init__(self,func): 
     self.func=func 
    def __str__(self): 
     return self.func() 

logger.debug(Lazy(lambda: time.sleep(20))) 

logger.info(Lazy(lambda: "Stupid log message " + ' '.join([str(i) for i in range(20)]))) 
# INFO:log:Stupid log message 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 

Se si esegue lo script, si noterà il primo comando logger.debug non prende 20 secondi per l'esecuzione. Questo mostra che l'argomento non viene valutato quando il livello di registrazione è inferiore al livello impostato.

Answer 3

Come Shane sottolinea, utilizzando

log.debug("Some message: a=%s b=%s", a, b) 

... invece di questo:

log.debug("Some message: a=%s b=%s" % (a, b)) 

consente di risparmiare un po 'di tempo da solo eseguendo la stringa di formattazione se il messaggio è in realtà registrato.

questo non risolve completamente il problema, anche se, come potrebbe essere necessario pre-elaborare i valori per formattare nella stringa, ad esempio:

log.debug("Some message: a=%s b=%s", foo.get_a(), foo.get_b()) 

In tal caso, obj.get_a() e obj.get_b() sarà calcolato pari a se non si verifica alcuna registrazione.

Una soluzione che potrebbe essere quella di utilizzare le funzioni lambda, ma questo richiede alcune macchine in più:

class lazy_log_debug(object): 
    def __init__(self, func): 
     self.func = func 
     logging.debug("%s", self) 
    def __str__(self): 
     return self.func() 

... allora è possibile accedere con il seguente:

lazy_log_debug(lambda: "Some message: a=%s b=%s" % (foo.get_a(), foo.get_b())) 

In tal caso , la funzione lambda sarà solo da chiamare se log.debug decide di eseguire la formattazione, quindi chiama il metodo __str__.

Attenzione: il sovraccarico di questa soluzione potrebbe benissimo eccedere il vantaggio :-) Ma almeno in teoria, rende possibile eseguire perfettamente il logging pigro.

Answer 4

Ovviamente il seguente non è efficiente come una macro:

if logger.isEnabledFor(logging.DEBUG): 
    logger.debug(
     'Stupid log message ' + ' '.join([str(i) for i in range(20)]) 
    ) 

ma semplice, evaluates in lazy fashion ed è 4 volte più veloce rispetto alla risposta accettata:

class lazyjoin: 
    def __init__(self, s, items): 
     self.s = s 
     self.items = items 

    def __str__(self): 
     return self.s.join(self.items) 

logger.debug(
    'Stupid log message %s', lazyjoin(' ', (str(i) for i in range(20))) 
) 

Vedere benchmark-src per il mio impostare.