The PyTorch compiler hijacks my logger and floods it with DEBUG messages

1

This is my logger.py file:

import sys
import datetime
import pytz
import logging

eastern = pytz.timezone('US/Eastern')


class StdErrFilter(logging.Filter):
    def filter(self, rec):
        return rec.levelno in (logging.ERROR,)


class StdOutFilter(logging.Filter):
    def filter(self, rec):
        return rec.levelno in (logging.DEBUG, logging.INFO, logging.WARNING, logging.NOTSET)


def timetz(*args):
    return datetime.datetime.now(tz=eastern).timetuple()


def get_logger(caller, level=None, filename: str = None):
    logger = logging.getLogger(caller)

    format_str = '%(process)s - %(asctime)s - %(name)s - %(levelname)s - %(message)s'
    formatter = logging.Formatter(format_str)
    logging.Formatter.converter = timetz

    h1 = logging.StreamHandler(sys.stdout)
    h1.setLevel(logging.INFO)
    h1.setFormatter(formatter)
    h1.addFilter(StdOutFilter())

    h2 = logging.StreamHandler(sys.stderr)
    h2.setLevel(logging.ERROR)
    h2.setFormatter(formatter)
    h2.addFilter(StdErrFilter())

    logging.basicConfig(level=logging.NOTSET, format=format_str, handlers=[h1, h2])

    if filename:
        file_handler = logging.FileHandler(filename)
        file_handler.setLevel(logging.INFO)
        file_handler.setFormatter(formatter)
        logger.addHandler(file_handler)

    return logger

Which is instantiated like this:

log = get_logger(__name__)

Unfortunately the pytorch compiler is flooding my logger with DEBUG messages. What’s the best way for us to manage this situation? I would like to capture useful messages (i.e. errors) from the compiler, but I don’t need the DEBUG messages. Thanks!

2

A feature request to add more control in the PyTorch logging util. is tracked here so you might want to check if this request would also cover your use case.

1 Like
3

I’ll need to play around with your example code to give exact guidance, but PyTorch library is supposed to install its own handler which will prevent our logs from getting to the root logger by default, so figuring out why that didn’t work would have been my first step.

4

@ezyang The issue here is that both torch._dynamo and torch._inductor are writing to the root logger. I haven’t seen pytorch-eager logs in the root logger. One thing to note, we weren’t having this issue prior to Feb 1, something changed in the nightly builds. For the code above, if we change the level=logging.INFO in the basicConfig, then we just get the INFO messages from the compiler, which are useful. But I would prefer to have control of our own DEBUG messages. thanks!

5

Since the issue you are seeing began at Feb 1st, this PR could be related.

6

This https://github.com/pytorch/pytorch/pull/94858 should fix this issue, let me know if you continue seeing it after this PR is merged.