ASV version > 0.5.0 causing slowdowns when running asv dev?

[mroeschke]

cc @datapythonista (mentioned today)

In pandas we pinned asv < 0.5.0 in pandas-dev/pandas#45886 because the CI check that ran asv dev was taking 3+ hours.

On main branch before pin: https://github.com/pandas-dev/pandas/runs/5094054780?check_suite_focus=true
On main branch after pin: https://github.com/pandas-dev/pandas/runs/5123068568?check_suite_focus=true

This might be due to other spurious issues (GHA flakiness, etc.), but the fact that pinning the asv version solved this issue is suspicious.

[datapythonista]

Things I see:

• There was a failure in the benchmarks, which is unexpected: https://github.com/pandas-dev/pandas/runs/5094054780?check_suite_focus=true#step:6:5100
• From the timestamps seem like getting information from the machine took 45 minutes. Which is not normal. Also, I'm not sure if running asv machine in the CI is very helpful. I think saving the machine is useful when we keep the history of the benchmarks, not to test if the benchmarks work. https://github.com/pandas-dev/pandas/runs/5094054780?check_suite_focus=true#step:6:81
• There is a benchmark that took 40 minutes based on the timestamps: https://github.com/pandas-dev/pandas/runs/5094054780?check_suite_focus=true#step:6:132
• I thought we were calling asv with the option to show the durations, but I don't see the durations in the log. Maybe it can be added

@LucyJimenez do you want to have a look at this when you finish with the other tasks you're working on?

[LucyJimenez]

Yes, of course! I'm going to check it.

[mroeschke]

+1 for removing asv machine from the check if not needed. I think it was added because it was "recommended" in the docs? https://asv.readthedocs.io/en/stable/using.html#running-benchmarks

+1 to add the durations

[datapythonista]

I had a look, and benchmarks also run slow locally. I didn't realize when I did a test run before the release, but I didn't time it properly. The problem doesn't seem to be in any particular benchmark, all them look to be running slower.

I saw this commit, that if I understand correctly, seems to be implementing that each benchmark run in a separate process. The overheat of starting a new process could explain why benchmarks are significantly slower. I didn't check in too much detail, but seems like for benchmarks to run in a separate process they should be prefixed with timeraw_. So, if things are working correctly, this shouldn't happen in pandas benchmarks, but maybe things are not working as expected.

[rgommers]

FYI, we are seeing major slowdowns in Scipy's benchmark CI job as well, see scipy/scipy#15568.

[mroeschke]

Shot in the dark, but this commit, which was after the 0.4.2 release but before 0.5.0, looks like it changed the way regression are calculated which may cause a computational slowdown (I haven't studied what it's doing thoroughly). #934

[datapythonista]

I started to have a look, but looks like the problem is not as obvious as I thought. I run the next benchmark with both 0.42 and 0.51, and timings are about the same.

Benchmark:

import functools


class Sample:
    def time_reduce(self):
        return functools.reduce(lambda x, y: x + y, range(100_000_000))

0.42:

$ time asv run -v --python=same
· Running '/home/mgarcia/mambaforge/envs/asv-dev/bin/python3.9 -c import sys; print(str(sys.version_info[0]) + "." + str(sys.version_info[1]))'
  OUTPUT -------->
  3.9
· Discovering benchmarks
·· Running '/home/mgarcia/src/asv/asv/benchmark.py discover /home/mgarcia/asv_perf/benchmarks /tmp/tmp6xk2o9gr/result.json' in existing-py_home_mgarcia_mambaforge_envs_asv-dev_bin_python3.9
·· Running '/home/mgarcia/mambaforge/envs/asv-dev/bin/python3.9 /home/mgarcia/src/asv/asv/benchmark.py discover /home/mgarcia/asv_perf/benchmarks /tmp/tmp6xk2o9gr/result.json'
· Running 1 total benchmarks (1 commits * 1 environments * 1 benchmarks)
[  0.00%] ·· Benchmarking existing-py_home_mgarcia_mambaforge_envs_asv-dev_bin_python3.9
[  0.00%] ··· Running '/home/mgarcia/src/asv/asv/benchmark.py run_server /home/mgarcia/asv_perf/benchmarks /tmp/asv-forkserver-uqdvtfxf/socket' in existing-py_home_mgarcia_mambaforge_envs_asv-dev_bin_python3.9
[  0.00%] ··· Running '/home/mgarcia/mambaforge/envs/asv-dev/bin/python3.9 /home/mgarcia/src/asv/asv/benchmark.py run_server /home/mgarcia/asv_perf/benchmarks /tmp/asv-forkserver-uqdvtfxf/socket'
[ 50.00%] ··· Running (sample.Sample.time_reduce--).
[100.00%] ··· sample.Sample.time_reduce                                                                                                                            7.40±0.08s

real	0m30.531s
user	0m30.233s
sys	0m0.079s

0.51:

$ time asv run -v --python=same
· Running '/home/mgarcia/mambaforge/envs/asv-dev/bin/python3.9 -c import sys; print(str(sys.version_info[0]) + "." + str(sys.version_info[1]))'
  OUTPUT -------->
  3.9
· Discovering benchmarks
·· Running '/home/mgarcia/src/asv/asv/benchmark.py discover /home/mgarcia/asv_perf/benchmarks /tmp/tmpt1ut3k60/result.json' in existing-py_home_mgarcia_mambaforge_envs_asv-dev_bin_python3.9
·· Running '/home/mgarcia/mambaforge/envs/asv-dev/bin/python3.9 /home/mgarcia/src/asv/asv/benchmark.py discover /home/mgarcia/asv_perf/benchmarks /tmp/tmpt1ut3k60/result.json'
· Running 1 total benchmarks (1 commits * 1 environments * 1 benchmarks)
[  0.00%] ·· Benchmarking existing-py_home_mgarcia_mambaforge_envs_asv-dev_bin_python3.9
[  0.00%] ··· Running '/home/mgarcia/src/asv/asv/benchmark.py run_server /home/mgarcia/asv_perf/benchmarks /tmp/asv-forkserver-m32fvn68/socket' in existing-py_home_mgarcia_mambaforge_envs_asv-dev_bin_python3.9
[  0.00%] ··· Running '/home/mgarcia/mambaforge/envs/asv-dev/bin/python3.9 /home/mgarcia/src/asv/asv/benchmark.py run_server /home/mgarcia/asv_perf/benchmarks /tmp/asv-forkserver-m32fvn68/socket'
[ 50.00%] ··· Running (sample.Sample.time_reduce--).
[100.00%] ··· sample.Sample.time_reduce                                                                                                                            7.13±0.05s

real	0m29.433s
user	0m29.125s
sys	0m0.082s

I'll continue to have a look. Hopefully I can find a small example that replicates the performance issue, without having to test with the whole pandas benchmark suite (which takes more than 3 hours to finish with the slowdown.

[datapythonista]

Ok, was quite tricky, but I finally found the problem. The cause is this commit: e3de319

The problem is more a feature than a bug. It only happens with asv dev. Seems like until 0.4.2, asv dev by default was executing each benchmark once (equivalent to using --quick). But in that commit, asv dev stops having that default, to be the same as asv run --python=same, so it just avoids creating environments, but other than that is a regular asv run, which runs benchmarks multiple times.

So, the solution is immediate, and is just adding the --quick, and timings should (hopefully) be similar in 0.5.1 and 0.4.2. And probably worth already moving from asv dev to asv run with the appropriate parameters. asv dev is just a shortcut, and it clearly causes more problems than the value it adds. I'd simply remove it in the next version, 0.6.0, or I can deprectate it in that version, and remove it in the next (but since the change in behavior from 0.4 to 0.5, I don't think it's worth a two-step deprecation).

[HaoZeke]

This is still present: scipy/scipy#18857 (review)

[datapythonista]

Seems like not using --quick by default in asv dev was intentional. And easy fix would be to just add this parameter. I think I may prefer to just run the benchmarks once for asv dev by default, but since it was intentional I closed the issue and updated the call in pandas. Feel free to do whatever you think it's best here, just wanted to let you know in case the comment above is not clear.