bazel-contrib / bazel-contrib/rules_python

Poor unit test performance using py_test rule

オープン
#311 コメント 14 件 リアクション 15 件 担当者 1 名 @thundergolfer が担当を希望しています GitHub で見る
主要言語
Starlark
スター
688
フォーク
721
平均マージ
15時間 7分
マージ済み PR(30日)
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 を短くまとめたダイジェスト。