Poor unit test performance using py_test rule #311
Description
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.