multiprocessing+logging+tqdm进度条闪烁显示0%问题求助

问题现象 #

• 配置VERBOSITY = 0时，工作进程内的log调用无输出，进度条显示完全正常
• 配置VERBOSITY = 1开启工作进程INFO级别日志后，进度条可固定在屏幕底部，但绝大多数时间显示进度为0%，仅偶尔闪烁显示正确的进度数值与百分比

可复现代码 #

import itertools
import logging
import multiprocessing
import random
import sys
import time

import tqdm
from tqdm.contrib import DummyTqdmFile

log: logging.Logger = logging.getLogger(__name__)


DEFAULT_FORMAT = "[%(asctime)s.%(msecs)06d][%(processName)s][%(threadName)s][%(levelname)s][%(module)s] %(message)s"
VERBOSITY = 1


def configure_logger(log: logging.Logger, verbosity: int, *, format: str = DEFAULT_FORMAT, dry_run: bool = False):
    """Configures the logger instance based on verbosity level"""

    # can't use force=true as it requires Python >= 3.8
    root = logging.getLogger()
    for handler in root.handlers:
        root.removeHandler(handler)

    if dry_run:
        format = format.replace(" %(message)s", "[DRY RUN] %(message)s")
    logging.basicConfig(format=format, datefmt="%Y-%m-%d %H:%M:%S", stream=DummyTqdmFile(sys.stdout))

    verbosity_to_loglevel = {0: logging.WARNING, 1: logging.INFO, 2: logging.DEBUG}
    log.setLevel(verbosity_to_loglevel[min(verbosity, 2)])

    if verbosity >= 4:
        logging.getLogger().setLevel(logging.INFO)
    if verbosity >= 5:
        logging.getLogger().setLevel(logging.DEBUG)

def by_n(iterable, n):
    """Iterate by chunks of n items"""
    return (tuple(filter(lambda x: x is not None, x)) for x in itertools.zip_longest(*[iter(iterable)] * n))


def _worker(batch):
    log.info("Let's go!")
    for i in batch:
        log.info("Processing item %d", i)
        time.sleep(random.uniform(0.1, 0.2))
    log.info("Done!")

    return len(batch)

if __name__ == "__main__":
    configure_logger(log, VERBOSITY)

    log.info("Let's go!")

    foos = list(range(1000))
    kwargs = {
        "desc": "Processing...",
        "total": len(foos),
        "leave": True,
        "mininterval": 1,
        "maxinterval": 5,
        "unit": "foo",
        "dynamic_ncols": True,
    }
    pbar = tqdm.tqdm(**kwargs)

    with multiprocessing.Pool(processes=5) as workers_pool:
        for batch_length in workers_pool.imap_unordered(
            _worker,
            by_n(foos, min(10 + int((len(foos) - 10) / 100), 1000)),
        ):
            pbar.update(batch_length)

    log.info("Done!")

根因分析 #

1. VERBOSITY=0时日志级别为WARNING，工作进程内只有INFO级别的日志，不会触发流写入，没有输出干扰，进度条自然正常显示。
2. VERBOSITY=1时异常的核心原因是**DummyTqdmFile不是多进程安全的**：
   • 代码在主进程中配置日志流为DummyTqdmFile(sys.stdout)，multiprocessing在类Unix系统默认使用fork模式创建工作进程，子进程会继承主进程的文件描述符与logger配置，直接向stdout写日志。
   • DummyTqdmFile的作用是在单进程场景下拦截输出，自动清空当前行的进度条、写入日志内容、再重绘进度条，避免日志打乱进度条显示，但这个逻辑只在主进程的tqdm实例维护，子进程写流时不会触发主进程的进度条重绘，反而会直接覆盖终端当前行（也就是进度条所在行）的内容。
   • 代码中tqdm配置了mininterval=1，主进程每秒才会刷新一次进度条，而子进程每0.1~0.2秒就会输出一条日志，绝大多数时候进度条行被子进程的日志清空/覆盖为初始的0%状态，只有刚好撞上主进程刷新进度条的瞬间，才会显示正确进度。

修复方案 #

优先选择无跨进程流竞争的方案：

• 子进程不直接写终端流：用multiprocessing.Queue把子进程的日志内容传回主进程，由主进程统一调用tqdm.write()方法输出日志，该方法原生兼容tqdm的进度条重绘逻辑，不会出现覆盖问题。
• 快速适配方案：将日志流与tqdm输出流分离，比如tqdm默认输出到stderr，就把日志配置为输出到stdout，两个独立流不会互相覆盖；注意不要在子进程中复用主进程包装过的DummyTqdmFile流，子进程初始化时单独配置日志handler即可。
• 不推荐用跨进程锁包日志输出的方案，实现复杂且容易出现死锁、性能损耗问题。

内容的提问来源于stack exchange，提问作者Gregory Pakosz