bazel-contrib / bazel-contrib/rules_python

Poor unit test performance using py_test rule

未关闭
#311 14 条评论 15 个 reaction 已指派 1 人 已被 @thundergolfer 认领 在 GitHub 查看
主要语言
Starlark
星标
688
派生
721
平均合并
15 小时 7 分钟
30 天内合并 PR
76

描述

I'm in the process of switching our rather large Python codebase over to using Bazel and have just finished getting our entire unit test suite to run using Bazel. Our tests are written using `unittest` and we leveraged pytest as our test runner. Typically a full run of the test suite (~6000 tests) would take around 10 minutes. However, with Bazel I'm now observing run times of about 40 minutes. Of course, once things are cached it is super fast.

I knew to expect some overhead but I haven't seen anything like this with other Bazel projects I've worked on.

I went ahead and collected some timings/profile information using the `analyize-profile` option that Bazel has for subsets of our unit tests. `bazel clean` was run before each timing run.

First for our web package: `./bazel test tests/python/web/...`. This consist of 70 test targets. Profile information:

```
=== PHASE SUMMARY INFORMATION ===

Total launch phase time 6.702 s 2.35%
Total init phase time 0.267 s 0.09%
Total loading phase time 1.632 s 0.57%
Total analysis phase time 5.197 s 1.82%
Total preparation phase time 0.032 s 0.01%
Total execution phase time 271.452 s 95.15%
Total finish phase time 0.017 s 0.01%
------------------------------------------------
Total run time 285.301 s 100.00%

Critical path (165.526 s):
Time Percentage Description
392 ms 0.24% action 'Creating source manifest for //tests/python/web/controllers/api listing_check_ins_test'
16.616 s 10.04% action 'Creating runfiles tree bazel-out/darwin-py2-fastbuild/bin/tests/python/web/controllers/api/listing_check_ins_test.runfiles'
12.5 ms 0.01% runfiles for //tests/python/web/controllers/api listing_check_ins_test
148.505 s 89.72% action 'Testing //tests/python/web/controllers/api listing_check_ins_test'
```

So since this `listing_check_ins_test` (which is actually a slow test) seems to be the critical path I tried running it on its own:

```
=== PHASE SUMMARY INFORMATION ===

Total launch phase time 0.060 s 0.12%
Total init phase time 0.139 s 0.28%
Total loading phase time 1.616 s 3.28%
Total analysis phase time 4.551 s 9.25%
Total preparation phase time 0.017 s 0.04%
Total execution phase time 42.820 s 87.00%
Total finish phase time 0.016 s 0.03%
------------------------------------------------
Total run time 49.221 s 100.00%

Critical path (42.567 s):
Time Percentage Description
154 ms 0.36% action 'Creating source manifest for //tests/python/web/controllers/api listing_check_ins_test'
920 ms 2.16% action 'Creating runfiles tree bazel-out/darwin-py2-fastbuild/bin/tests/python/web/controllers/api/listing_check_ins_test.runfiles'
11.6 ms 0.03% runfiles for //tests/python/web/controllers/api listing_check_ins_test
41.481 s 97.45% action 'Testing //tests/python/web/controllers/api listing_check_ins_test'
```

It seems noteworthy that when run by itself it's 3x faster.

At this point I wanted to compare to pytest.

When testing the web package using pytest we see the following result: `216 passed in 96.19 seconds`

When running the single slow test with pytest: `11 passed in 32.79 seconds`.

Interestingly when running the executable that Bazel produces directly (`./listing_check_ins_test`) I observe a similar time to that of pytest.

Ultimately Bazel profiling seems to indicate:
* That the majority of time is spent in the execution phase.
* Running tests in parallel seems to very negatively impact test speed.
* At least what Bazel is outputting when run on its own has the same performance.

Any advice on how to continue to investigate this further would be appreciated.

贡献指南

打开贡献指南

评估

这个 Issue 还没有评估数据。

把新 issue 发到你的邮箱

精选适合新手参与的 GitHub issue 摘要。