Improve performance of `test_util_vcs.py`

[ahal]

This test takes awhile, and since we run it across multiple Python versions, is the main reason why the unit task takes so long to run. It would be nice to figure out why it's so slow and see if we can speed it up at all.

[miladHakimi]

Hi @ahal,

I ran a profiler (pytest-profiling) on the tests and figured out that the subprocess.check_output() function is the main contributer to the runtime.

taskgraph/src/taskgraph/util/vcs.py

Lines 40 to 51 in 311cf52

	def run(self, *args: str, **kwargs):
	return_codes = kwargs.pop("return_codes", [])
	cmd = (self.binary,) + args
	try:
	return subprocess.check_output(
	cmd, cwd=self.path, env=self._env, encoding="utf-8", **kwargs
	)
	except subprocess.CalledProcessError as e:
	if e.returncode in return_codes:
	return ""
	raise

It is called by the Repository.run() method to run different commands like add, commit, reset, etc. Here is the output of the profiler:

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       52    0.001    0.000   22.405    0.431 runner.py:109(pytest_runtest_protocol)
       52    0.002    0.000   22.392    0.431 runner.py:117(runtestprotocol)
      156    0.001    0.000   22.389    0.144 runner.py:217(call_and_report)
 2123/572    0.005    0.000   22.381    0.039 _hooks.py:244(__call__)
 2123/572    0.002    0.000   22.379    0.039 _manager.py:77(_hookexec)
 2123/572    0.015    0.000   22.378    0.039 _callers.py:9(_multicall)
      156    0.001    0.000   22.357    0.143 runner.py:245(call_runtest_hook)
      156    0.002    0.000   22.355    0.143 runner.py:316(from_call)
      156    0.001    0.000   22.352    0.143 runner.py:260(<lambda>)
      321    0.023    0.000   21.337    0.066 subprocess.py:417(check_output)
      321    0.030    0.000   21.313    0.066 subprocess.py:506(run)
      313    0.004    0.000   20.940    0.067 vcs.py:40(run)
      321    0.021    0.000   20.673    0.064 subprocess.py:1163(communicate)
      623   19.903    0.032   19.909    0.032 {method 'read' of '_io.TextIOWrapper' objects}
       52    0.000    0.000   19.403    0.373 runner.py:158(pytest_runtest_call)
       52    0.000    0.000   19.401    0.373 python.py:1787(runtest)
       52    0.001    0.000   19.398    0.373 python.py:188(pytest_pyfunc_call)
       32    0.001    0.000    4.690    0.147 vcs.py:254(get_changed_files)
        2    0.000    0.000    3.414    1.707 test_util_vcs.py:465(test_workdir_outgoing)
       52    0.000    0.000    2.870    0.055 runner.py:153(pytest_runtest_setup)

I don't know how to properly optimize it though.

[ahal]

Hi @miladHakimi, sorry I totally missed this mention in my notifications.

I'm not too surprised by this finding, the tests themselves make a lot of calls out to the underlying version control system (hg or git) to funciton. So any calls to the VCS will be captured in the check_output call. For performance optimizations, we'll want to look into things like parallelization, reducing setup steps or looking into how to speed up the actual vcs (e.g, maybe use chg or a command server for Mercurial).

Let me know if you're still interested in working on this and we can dive into some more details!

[miladHakimi]

I'm interested in solving this issue. I can start exploring the code and look for areas of improvement including the things you mentioned. Then, write a small proposal of what to do so that we can iterate over it to find something that can be useful.

[AnsahMohammad]

I'd like to take a shot at this issue. It looks like check_output() is causing a significant bottleneck due to the high number of repo.run() calls across multiple test cases.

One possible optimization is to introduce lazy execution for run() and analyze how it impacts performance. Parallelization might also be a viable solution.

These were my findings :

Test-cases that took long to run :

Time            test-case
============================================================================== slowest durations ==============================================================================
4.40s call     test/test_util_vcs.py::test_workdir_outgoing[hg]
3.50s call     test/test_util_vcs.py::test_get_changed_files_two_revisions[hg]
2.22s call     test/test_util_vcs.py::test_working_directory_clean[hg]
2.12s call     test/test_util_vcs.py::test_find_latest_common_revision[hg]
1.59s call     test/test_util_vcs.py::test_update[hg]
1.49s call     test/test_util_vcs.py::test_get_changed_files_one_added_file[hg]
1.37s call     test/test_util_vcs.py::test_get_changed_files_one_deleted_file[hg]
1.37s call     test/test_util_vcs.py::test_does_revision_exist_locally[hg]
1.31s call     test/test_util_vcs.py::test_get_changed_files_one_modified_file[hg]
1.17s call     test/test_util_vcs.py::test_branch[hg]
0.76s call     test/test_util_vcs.py::test_get_changed_files_no_changes[hg]
0.59s call     test/test_util_vcs.py::test_get_commit_message[hg-commit message in\u2026 pure utf8]
0.58s setup    test/test_util_vcs.py::test_workdir_outgoing[hg]
0.58s call     test/test_util_vcs.py::test_get_commit_message[hg-commit message in... ascii]
0.54s setup    test/test_util_vcs.py::test_get_repository[git]
0.54s call     test/test_util_vcs.py::test_all_remote_names[hg]
0.38s call     test/test_util_vcs.py::test_get_repo_path[hg]
0.33s call     test/test_util_vcs.py::test_remote_name_many_remotes[hg]
0.32s call     test/test_util_vcs.py::test_remote_name_default_and_origin[hg]
0.21s setup    test/test_util_vcs.py::test_find_latest_common_revision[hg]
0.21s setup    test/test_util_vcs.py::test_remote_name_many_remotes[hg]
0.20s call     test/test_util_vcs.py::test_calculate_head_rev[hg]
0.19s setup    test/test_util_vcs.py::test_default_branch_remote_query[hg]
0.19s setup    test/test_util_vcs.py::test_remote_name_default_and_origin[hg]
0.18s call     test/test_util_vcs.py::test_remote_name_no_remote[hg]
0.18s setup    test/test_util_vcs.py::test_all_remote_names[hg]
0.18s setup    test/test_util_vcs.py::test_remote_name[hg]
0.16s call     test/test_util_vcs.py::test_remote_name[hg]
0.07s call     test/test_util_vcs.py::test_workdir_outgoing[git]
0.04s call     test/test_util_vcs.py::test_get_changed_files_two_revisions[git]
0.03s call     test/test_util_vcs.py::test_find_latest_common_revision[git]
0.03s call     test/test_util_vcs.py::test_working_directory_clean[git]
0.03s call     test/test_util_vcs.py::test_get_changed_files_one_modified_file[git]
0.03s call     test/test_util_vcs.py::test_remote_name_many_remotes[git]
0.03s setup    test/test_util_vcs.py::test_workdir_outgoing[git]
0.03s call     test/test_util_vcs.py::test_branch[git]
0.03s call     test/test_util_vcs.py::test_remote_name_default_and_origin[git]
0.03s setup    test/test_util_vcs.py::test_all_remote_names[git]
0.02s setup    test/test_util_vcs.py::test_default_branch_remote_query[git]
0.02s call     test/test_util_vcs.py::test_update[git]
0.02s setup    test/test_util_vcs.py::test_find_latest_common_revision[git]
0.02s call     test/test_util_vcs.py::test_get_commit_message[git-commit message in\u2026 pure utf8]
0.02s call     test/test_util_vcs.py::test_get_changed_files_one_added_file[git]
0.02s setup    test/test_util_vcs.py::test_remote_name_many_remotes[git]
0.02s setup    test/test_util_vcs.py::test_remote_name[git]
0.02s setup    test/test_util_vcs.py::test_remote_name_default_and_origin[git]
0.02s call     test/test_util_vcs.py::test_get_commit_message[git-commit message in... ascii]
0.02s call     test/test_util_vcs.py::test_all_remote_names[git]
0.02s call     test/test_util_vcs.py::test_get_changed_files_one_deleted_file[git]
0.02s call     test/test_util_vcs.py::test_does_revision_exist_locally[git]
0.01s call     test/test_util_vcs.py::test_default_branch_cloned_metadata[git]
0.01s call     test/test_util_vcs.py::test_default_branch_remote_query[git]
0.01s setup    test/test_util_vcs.py::test_get_commit_message[git-commit message in... ascii]
0.01s call     test/test_util_vcs.py::test_get_changed_files_no_changes[git]
0.01s call     test/test_util_vcs.py::test_remote_name[git]
0.01s call     test/test_util_vcs.py::test_default_branch_guess[git]
0.01s setup    test/test_util_vcs.py::test_get_commit_message[git-commit message in\u2026 pure utf8]
0.01s call     test/test_util_vcs.py::test_get_repo_path[git]

• [hg] tests are significantly slower than [git]
• Repeated repo.run() calls across multiple tests seem to be a major contributor.