Pytest 在测试后花费的时间最多？答案

【问题标题】：Pytest spending most time post-test?Pytest 在测试后花费的时间最多？
【发布时间】：2021-02-28 20:01:51
【问题描述】：

我通过pytest 运行一个函数（在下面的示例中）需要 71 秒才能运行。但是，pytest 会多花 6 到 7 分钟做……某事。我可以从日志文件中看出预期的测试是在 7 分钟开始时执行的，但我无法想象之后会发生什么（如果相信“最慢持续时间”输出的话，显然这不是拆解）。

pytest 函数本身极小：

def test_preprocess_and_train_model():
    import my_module.pipeline as pipeline  # noqa

    pipeline.do_pipeline(do_s3_upload=False,
                         debug=True, update_params={'tf_verbosity': 0})

如果我手动运行 test_preprocess_and_train_model()（例如，如果我通过解释器而不是通过 pytest 调用函数），大约需要 70 秒。

发生了什么，我该如何加快速度？

▶  pytest --version
pytest 6.2.2
▶ python --version
Python 3.8.5
▶ time pytest -k test_preprocess_and_train_model -vv --durations=0                                             
====================================================== test session starts =======================================================
platform darwin -- Python 3.8.5, pytest-6.2.2, py-1.9.0, pluggy-0.13.1 -- /usr/local/opt/python@3.8/bin/python3.8
cachedir: .pytest_cache
rootdir: /Users/blah_blah_blah/tests
collected 3 items / 2 deselected / 1 selected                                                                                    

test_pipelines.py::test_preprocess_and_train_model PASSED                                                                  [100%] 

======================================================== warnings summary ========================================================
test_pipelines.py::test_preprocess_and_train_model
  /Users/your_name_here/Library/Python/3.8/lib/python/site-packages/tensorflow/python/autograph/impl/api.py:22: DeprecationWarning: the imp module is deprecated in favour of importlib; see the module's documentation for alternative uses
    import imp

test_pipelines.py: 3604341 warnings
  sys:1: DeprecationWarning: PY_SSIZE_T_CLEAN will be required for '#' formats

test_pipelines.py::test_preprocess_and_train_model
  /Users/your_name_here/Library/Python/3.8/lib/python/site-packages/tensorflow/python/keras/engine/training.py:2325: UserWarning: `Model.state_updates` will be removed in a future version. This property should not be used in TensorFlow 2.0, as `updates` are applied automatically.
    warnings.warn('`Model.state_updates` will be removed in a future version. '

-- Docs: https://docs.pytest.org/en/stable/warnings.html
======================================================= slowest durations ========================================================
71.88s call     test_pipelines.py::test_preprocess_and_train_model
0.00s teardown test_pipelines.py::test_preprocess_and_train_model
0.00s setup    test_pipelines.py::test_preprocess_and_train_model
================================= 1 passed, 2 deselected, 3604343 warnings in 422.15s (0:07:02) ==================================
pytest -k test_preprocess_and_train_model -vv --durations=0  305.95s user 158.42s system 104% cpu 7:26.14 total

【问题讨论】：

你能发布被测代码和测试本身吗？
亲爱的@MarcelloRomani，测试本身只有一行，并调用了辅助脚本。不幸的是，我不能包含该代码（它是专有的），但这相当于训练 TensorFlow 模型并将一些数据上传到 S3。但是，如上面的输出所示，调用本身只有 71.88 秒。
我刚刚尝试抑制 S3 上传；问题仍然存在。
另外四个事实：首先，70 秒后，pytest 将“PASSED”打印到屏幕上。其次，在额外的 6 分钟内，pytest 将我的一个处理器保持在 100% 的 CPU 使用率。第三，我在 MacOS 11.2.2 上测试；在 Ubuntu 上运行，我没有观察到问题。第四，细心的读者可能会注意到上面的 360 万（！）错误信息；使用“--disable-warnings”运行不会改变任何东西。
在不向我们展示一些代码或可重现的示例的情况下，不确定有人可以如何帮助您。那时这只是一个猜谜游戏。

标签： python pytest profiling

【解决方案1】：

我想我会发布这个解决方案，以防它帮助其他人。

theY4Kman 对代码进行分析的建议非常好。我自己的代码按预期在 70 秒内运行并干净地退出，但它产生了 360 万条警告消息。 pytest 中的每条警告消息都会触发一次 os.stat() 检查（以确定是哪一行代码产生了警告），评估 3.6M 系统调用需要 5 分钟左右。如果我在 pytest 的warnings.py 中注释掉了warning_record_to_str() 的核心，那么 pytest 大约需要 140 秒（即大部分问题都解决了）。

这也解释了为什么性能取决于平台（Mac 与 Ubuntu），因为错误消息的数量差异很大。

如果我理解正确的话，似乎有两个可悲的结论：

即使我使用--disable-warnings 标志，pytest 似乎也很乐意收集所有警告，统计它们等；它只是不打印它们。在我的例子中，这意味着 pytest 花费了 85% 的时间来计算它立即丢弃的信息。
os.stat() 检查发生在 Python 的 linecache.py 函数中。由于我收到了 360 万次相同的警告，我预计该函数将运行一次 os.stat() 并缓存结果，但这并没有发生。我想我只是误解了有关此功能的预期用途的一些基本内容。

【讨论】：