#1 – KurtJacobson 于 2017-11-25

@c-morley Could you review this?
Thanks!

#2 – c-morley 于 2017-11-26

I tested a bit now. I do wonder about CPU cost of logging – but I think there is some low hanging fruit stop logging to help. (I in fact had removed a print in gcode to help with cpu load.

#3 – KurtJacobson 于 2017-11-26

Hi Chris, thanks for reviewing.

When I first set up logging in Hazzy I was concerned about increasing CPU load as well, so I ran some tests and decided that the benefits of using the logging module outweighed the downsides of using print.
As I recall using log instead of print resulted in adding about 0.1s to the start up time of 3s, and since the vast majority of log messages are printed at start up it, I don’t think it has much of an effect at all later on.

Out of curiosity I wrote a little script (below) to compare the time performance of print and log. I put it in lib/python/qtvcp.

Bases on this script, print averages about 10 times faster than log when using the log level of DEBUG, but if I set the log level to INFO then log is about 5 times faster than print. The vast majority of the log messages are at the DEBUG level (mainly for use during development), with relatively few at INFO or above, so I think under typical usage with log level of INFO, log might result in a net time saving over print.

Keep in mind that I have overridden the logging.Formater.format method to make it inspect (using a regex) each and every log message for tags specifying text to be colorized. I bet most of the time is spent here, so if you are interested in using logging, but are still concerned about CPU load I could remove this, or add a flag that could be set to enable it.

“ Python
#!/usr/bin/env python

import time
import logger

log = logger.initBaseLogger('TimedLogger')
#log.setLevel(logger.INFO)

Time logging 100 DEBUG messages

start_time = time.time()

for i in range(100):
log.debug('Logging {}'.format(i))

logtime = time.time() - starttime

Time printing 100 messages

start_time = time.time()

for i in range(100):
print('Logging {}'.format(i))

printtime = time.time() - starttime

log.info("Total time for logging: {}".format(log_time))
log.info("Total time for printing: {}".format(print_time))
log.info("Print is {} faster than logging".format(logtime / printtime))
“

#4 – KurtJacobson 于 2017-11-27

Thanks for merging @c-morley!