Python print函数执行顺序异常：测试装饰器输出错位问题

和GIL完全无关，核心是测试框架的输出捕获机制导致的顺序错乱：
比如你用的unittest这类框架，默认会捕获测试方法执行过程中所有stdout输出（包括装饰器finally块里的print内容），而框架自身的进度提示（如test_some_function ...）是直接输出到终端、不被捕获的。测试完成后，框架会先把捕获的输出追加到进度提示后面，再输出最终结果（如ok），就出现了你看到的顺序混乱。

方法1：直接输出到stderr（最简单稳定） #

测试框架一般不会捕获stderr的输出，把装饰器里的print改为输出到stderr，就能绕过捕获，让内容直接按代码顺序输出：

import sys
import datetime
import functools

TEST_INIT_START = datetime.datetime.now()

def timedisplay(func):
    @functools.wraps(func)
    def wrapper(self, *args, **kwargs):
        start = datetime.datetime.now()
        try:
            return func(self, *args, **kwargs)
        finally:
            # 所有输出指定到stderr
            print(file=sys.stderr)
            print(
                'Total time elapsed:',
                (datetime.datetime.now() - TEST_INIT_START).seconds,
                'seconds',
                file=sys.stderr
            )
            print(
                f'{func.__name__} test time elapsed:',
                (datetime.datetime.now() - start).seconds,
                'seconds',
                file=sys.stderr
            )
            # 去掉原来的Result: 输出，让框架自己输出结果（ok/fail）即可
    return wrapper

方法2：临时恢复原始stdout（绕过框架捕获） #

在finally块中临时替换sys.stdout为终端原始输出流，输出完成后再恢复框架的捕获流：

import sys
import datetime
import functools

TEST_INIT_START = datetime.datetime.now()
original_stdout = sys.stdout

def timedisplay(func):
    @functools.wraps(func)
    def wrapper(self, *args, **kwargs):
        start = datetime.datetime.now()
        try:
            return func(self, *args, **kwargs)
        finally:
            # 临时切换到原始stdout，绕过捕获
            sys.stdout = original_stdout
            print()
            print(
                'Total time elapsed:',
                (datetime.datetime.now() - TEST_INIT_START).seconds,
                'seconds',
            )
            print(
                f'{func.__name__} test time elapsed:',
                (datetime.datetime.now() - start).seconds,
                'seconds',
            )
            print('Result: ', end='')
            # 恢复框架的捕获流（依赖unittest内部实现，可能随版本变化）
            sys.stdout = self._outcome.test_case._stdout
    return wrapper

方法3：使用日志模块输出 #

用logging模块替代print，日志输出默认不会被测试框架捕获，能保证顺序正确：

import logging
import datetime
import functools

logging.basicConfig(level=logging.INFO, format='%(message)s')
logger = logging.getLogger(__name__)

TEST_INIT_START = datetime.datetime.now()

def timedisplay(func):
    @functools.wraps(func)
    def wrapper(self, *args, **kwargs):
        start = datetime.datetime.now()
        try:
            result = func(self, *args, **kwargs)
            logger.info('')
            logger.info(f'Total time elapsed: {(datetime.datetime.now() - TEST_INIT_START).seconds} seconds')
            logger.info(f'{func.__name__} test time elapsed: {(datetime.datetime.now() - start).seconds} seconds')
            logger.info('Result: ok')
            return result
        except Exception:
            logger.info('')
            logger.info(f'Total time elapsed: {(datetime.datetime.now() - TEST_INIT_START).seconds} seconds')
            logger.info(f'{func.__name__} test time elapsed: {(datetime.datetime.now() - start).seconds} seconds')
            logger.info('Result: fail')
            raise
    return wrapper

内容的提问来源于stack exchange，提问作者Kevin K.