Pytorch：为什么在 DDP 中记录失败？答案

【问题标题】：Pytorch: why logging fails in DDP?Pytorch：为什么在 DDP 中记录失败？
【发布时间】：2020-11-09 13:11:25
【问题描述】：

我想在分布式数据并行管理的进程之一中使用日志记录。但是，日志在以下代码中不打印任何内容（代码源自this tutorial）：

#!/usr/bin/python

import os, logging
# logging.basicConfig(level=logging.DEBUG)

import torch

def setup(rank, world_size):
    os.environ['MASTER_ADDR'] = 'localhost'
    os.environ['MASTER_PORT'] = '12355'

    # Initialize the process group.
    dist.init_process_group('NCCL', rank=rank, world_size=world_size)


def cleanup():
    dist.destroy_process_group()


class ToyModel(nn.Module):
    def __init__(self):
        super(ToyModel, self).__init__()
        self.net1 = nn.Linear(10, 10)
        self.relu = nn.ReLU()
        self.net2 = nn.Linear(10, 5)

    def forward(self, x):
        return self.net2(self.relu(self.net1(x)))


def demo_basic(rank, world_size):
    setup(rank, world_size)

    if rank == 0:
        logger = logging.getLogger('train')
        logger.setLevel(logging.DEBUG)
        logger.info(f'Running DPP on rank={rank}.')

    # Create model and move it to GPU.
    model = ToyModel().to(rank)
    ddp_model = DDP(model, device_ids=[rank])

    loss_fn = nn.MSELoss()
    optimizer = optim.SGD(ddp_model.parameters(), lr=0.001)  # optimizer takes DDP model.

    optimizer.zero_grad()
    inputs = torch.randn(20, 10)  # .to(rank)

    outputs = ddp_model(inputs)

    labels = torch.randn(20, 5).to(rank)
    loss_fn(outputs, labels).backward()

    optimizer.step()

    cleanup()


def run_demo(demo_func, world_size):
    mp.spawn(
        demo_func,
        args=(world_size,),
        nprocs=world_size,
        join=True
    )


def main():
    run_demo(demo_basic, 4)


if __name__ == "__main__":
    main()

但是，当我取消注释第 4 行时，日志记录工作。请问一下这个bug的原因和解决方法？

【问题讨论】：

除非我记错了，否则第 6 行是空的 - 我猜你的意思是第 4 行？
@Xtrem532 感谢您的指出。现在更正。

标签： python-3.x pytorch python-multiprocessing python-logging

【解决方案1】：

更新

让我们简要回顾一下logging 模块中的记录器是如何工作的。

记录器以树形结构组织，即每个记录器都有一个唯一的parent 记录器。默认情况下，它将是 root 记录器，而 root 记录器没有父记录器。

当您在记录器上调用Logger.info 方法（此处为简单起见忽略级别检查）时，记录器会迭代其所有handlers 并让它们处理当前记录，例如处理程序可以是可以打印到标准输出的 StreamHandler，也可以是打印到某个文件的 FileHandler）。当前 logger 的所有 handler 完成工作后，会将记录交给其父 logger，父 logger 以相同的方式处理记录，即迭代父 logger 的所有 handler 并让它们处理记录，最终通过记录到“祖父母”。这个过程一直持续到当前记录器树的根节点，它没有父节点。

检查下面的实现或here：

def callHandlers(self, record):
    c = self
    found = 0
    while c:
        for hdlr in c.handlers:
            found = found + 1
            if record.levelno >= hdlr.level:
                hdlr.handle(record)
        if not c.propagate:
            c = None    #break out
        else:
            c = c.parent

因此，在您的情况下，您没有为 train 记录器指定任何处理程序。当您取消注释第 6 行时，即通过调用 logging.basicConfig(level=logging.DEBUG)，将为 root 记录器创建一个 StreamHandler。尽管train 记录器没有任何处理程序，但它的父记录器有一个StreamHandler，即root 记录器，它打印您实际看到的任何内容，而train 记录器在这种情况下不打印任何内容。当注释中的第 6 行时，甚至没有为 root 处理程序创建一个 StreamHandler，因此在这种情况下不会打印任何内容。所以其实这个问题与DDP无关。

顺便说一句，我一开始无法重现您的问题的原因是因为我使用的是 PyTorch 1.8，其中 logging.info 将在执行 dist.init_process_group 期间为 MPI 以外的后端调用，它隐式调用 @987654344 @，为根记录器创建一个StreamHandler，并且似乎按预期打印消息。

================================================ ========================

一个可能的原因：因为在dist.init_process_group的执行过程中，它会调用_store_based_barrier，最终会调用logging.info（见源代码here）。所以如果你在调用dist.init_process_group之前调用logging.basicConfig，它会被提前初始化，这使得root logger忽略所有级别的日志。

您的代码中不是这种情况，因为logging.basicConfig 位于文件的顶部，它将在dist.init_process_group 之前的第一个执行。实际上，在填充了 nn 和 dist 等缺失的导入之后，我可以运行您提供的代码，但日志记录工作正常。也许你试图减少代码重现问题，却在不知不觉中规避了真正的问题？您能否仔细检查一下这是否能解决您的问题？

【讨论】：

您好，由于 stackoverflow 的限制，其余的 import 语句从第 6 行中删除。除了这些，什么都没有。我在torch 1.7上尝试了上面的代码，但logging不起作用。
顺便说一句，我留下了一个类似的问题here。我不熟悉日志记录和多进程。如果你能弄清楚，我将不胜感激。 :D
@Tengerye 检查我的更新，我认为它现在也可以回答您的另一个问题。
我可以从你的回答中理解第一个问题。但是，为什么在单个进程中创建记录器之间的输出不同？（示例提供here）

【解决方案2】：

我将为像我这样不熟悉 python 的日志记录机制的人澄清我的发现。

问题不是因为 Pytorch 和任何第三方软件包都可能引发这种现象。原因是logging 是单例的。对basicConfig 的任何修改都会影响我们的代码和来自第三方的代码。

我目前的解决方案是创建一个模块级记录器并在不同模块之间共享它。

【讨论】：