https://pantsbuild.org/ logo
Join Slack
Powered by
Hello. I wonder if I'm doing something wrong with ...
# general
r
Hello. I wonder if I'm doing something wrong with my tests or at least how to debug that issue. My pytest tests take a long time to execute. Each test file takes between 4 and 8 seconds to execute and there are ~200 files. On a dual core, it means it takes between 7 and 14 minutes to execute the first time. (Then most of the results are cached). That's a long time so I wonder if something isn't right with my setup.
e
Before getting to debugging, one surprising thing about Pants is that it does not honor the meaning of pytest session scoped fixtures. Do you have any of these that are used by ~all tests and are expensive?
r
Not really, I have autouse fixture but they're not expensive. That said, I lot a truckload of modules, some big like botocore,
I guess in a session the module aren't reloaded for each test, are they?
*modules
collecting tests take time.
e
Ok, so not fixtures. But you have a measurement that indicates test collection is taking a significant portion of this?
r
If I run pytest manually, I see the Collecting... message increasing for several seconds and then all tests execute. The whole process takes a bit more than 30 seconds
I don't know if pytest needs to do the full collections of test cases each time pants run it for a file
e
Aha, gotcha. It shouldn't since Pants will be calling pytest 400 separate times, each time with one test file; so the collection should take ~1/400th the time of running pytest manually. If you want to see more what's going on, you should run 
./pants --no-process-cleanup test --force ...
. That will force a run of your tests and print out a line like:
Copy code
./pants --no-process-cleanup test --force src/python/pants/util/strutil_test.py
16:00:55.92 [INFO] Preserving local process execution dir /tmp/pants-sandbox-ZCERnv for Run Pytest for src/python/pants/util/strutil_test.py:tests
16:00:56.27 [INFO] Completed: Run Pytest - src/python/pants/util/strutil_test.py:tests succeeded.

✓ src/python/pants/util/strutil_test.py:tests succeeded in 0.29s.
You can then use / edit the 
__run.sh
script in the printed out 
/tmp/pants-sandbox-*
directory to start drilling down on timings.
For example. I made this edit to the sandbox 
__run.sh
script:
Copy code
$ diff /tmp/pants-sandbox-ZCERnv/__run.sh.orig /tmp/pants-sandbox-ZCERnv/__run.sh
5c5
< ./pytest_runner.pex_pex_shim.sh --no-header src/python/pants/util/strutil_test.py
---
> ./pytest_runner.pex_pex_shim.sh src/python/pants/util/strutil_test.py "$@"
And then I could:
Copy code
$ hyperfine '/tmp/pants-sandbox-ZCERnv/__run.sh --collect-only'
Benchmark 1: /tmp/pants-sandbox-ZCERnv/__run.sh --collect-only
  Time (mean ± σ):     170.3 ms ±   2.5 ms    [User: 149.4 ms, System: 20.9 ms]
  Range (min … max):   166.1 ms … 174.6 ms    17 runs

$ hyperfine /tmp/pants-sandbox-ZCERnv/__run.sh
Benchmark 1: /tmp/pants-sandbox-ZCERnv/__run.sh
  Time (mean ± σ):     249.1 ms ±   2.8 ms    [User: 225.6 ms, System: 23.3 ms]
  Range (min … max):   246.2 ms … 254.8 ms    12 runs
So, in this case, I can see collection overhead is roughly 70% of runtime. That's not really fair attribution since collection takes the import hit and importing has to happen anyway, but hopefully this makes clear how you can drill in on what's going on. If you can't track down what's taking so long using this technique, an implication can be its the overhead of pants setting up this sandbox that is the slow part. I'm not sure we give you an easy way to see that overhead timing.
r
ah nice, I'll try to find out. Thanks for the tips!
Ok the collection takes a lot of time but I think it is a dependency issue on my app. I'll try to fix that fix. Funny how it uncovers issues in the code 🙂
💯 1
5 Views
Open in Slack
PreviousNext
Powered by