Currently desispec.io.read_spectra etc. functions generate log messages like
INFO:spectra.py:291:read_spectra: iotime 0.338 sec to read coadd-special-bright-14886.fits at 2024-05-19T18:26:21.245807
These iotime messages are really useful for understanding pipeline problems, but are overly chatty for interactive work.
Update the iotime logging to only print messages if $DESI_LOG_IOTIME is set. We would set this for pipeline operations, but not by default so that interactive work wouldn't have these chatty messages.
Implementation details
Currently this iotime logging is implemented like like
so that the "should I print something or not?" logic would be isolated to a single iotime.log function, but that would have the effect of making the log message appear from iotime.log instead of associated with whatever reader/writer is actually reporting the timing.
It seems that we need something like
if iotime.log_timing():
log.info(iotime.format('write', outfile, duration))
but that seems yucky to have to if bracket every iotime log. Maybe it would be better to do something like:
# in desispec.iotime
def get_io_logger():
if 'DESI_LOG_IOTIME' in os.environ:
iologger = get_logger(level='info')
else:
iologger = get_logger(level='debug')
# in reader/writing code
iolog = iotime.get_io_logger()
...
iolog.info(iotime.format('write', outfile, duration))
i.e. create a different logger object for io vs. normal logging so that they can act at different levels depending upon DESI_LOG_IOTIME.
Fancier idea: add a custom log.iotime level to our DESI logger in desiutil. This would use both DESI_LOGLEVEL and DESI_LOG_IOTIME to determine whether something should be logged or not.
Other ideas are welcome.
Other notes
You can avoid them by setting $DESI_LOGLEVEL=warning but then you lose all the other INFO-level messages. Changing all the iotime logging to a DEBUG-level is also undesirable because that makes the logs too chatty for production running.
Currently
desispec.io.read_spectraetc. functions generate log messages likeThese iotime messages are really useful for understanding pipeline problems, but are overly chatty for interactive work.
Update the iotime logging to only print messages if $DESI_LOG_IOTIME is set. We would set this for pipeline operations, but not by default so that interactive work wouldn't have these chatty messages.
Implementation details
Currently this iotime logging is implemented like like
I was tempted to change this to
so that the "should I print something or not?" logic would be isolated to a single
iotime.logfunction, but that would have the effect of making the log message appear fromiotime.loginstead of associated with whatever reader/writer is actually reporting the timing.It seems that we need something like
but that seems yucky to have to
ifbracket everyiotimelog. Maybe it would be better to do something like:i.e. create a different logger object for io vs. normal logging so that they can act at different levels depending upon DESI_LOG_IOTIME.
Fancier idea: add a custom
log.iotimelevel to our DESI logger in desiutil. This would use both DESI_LOGLEVEL and DESI_LOG_IOTIME to determine whether something should be logged or not.Other ideas are welcome.
Other notes
You can avoid them by setting $DESI_LOGLEVEL=warning but then you lose all the other INFO-level messages. Changing all the iotime logging to a DEBUG-level is also undesirable because that makes the logs too chatty for production running.