dvc exp run: takes a long time before launching the actual command when a .venv exists

[ettadar]

Bug Report

Description

When running dvc exp run ... with a virtual env in the repo root, it takes around two minutes before launching the actual command.

Reproduce

1. create a virtual env in <repo_root>/.venv/ (for example using poetry) and install some packages
2. dvc exp run ...

Expected

to start executing the actual command in a few seconds

Environment information

Output of dvc doctor:

DVC version: 2.0.5 (pip)
---------------------------------
Platform: Python 3.7.9 on Linux-5.4.0-1037-gcp-x86_64-with-debian-buster-sid
Supports: gs, http, https, s3
Cache types: hardlink, symlink
Cache directory: ext4 on /dev/sda1
Caches: local
Remotes: gs
Workspace directory: ext4 on /dev/sda1
Repo: dvc, git

Additional Information (if any):

Verbose output:

2021-03-16 15:48:53,638 TRACE: Namespace(all_pipelines=False, cd='pipelines/CHANGED_NAME', checkpoint_resume=None, cmd='run', cprofile=False, cprofile_dump='dump.prof', downstream=True, dry=False, force=False, force_downstream=False, func=<class 'dvc.command.experiments.CmdExperimentsRun'>, glob=False, instrument=False, instrument_open=False, interactive=False, jobs=None, metrics=False, name=None, no_commit=False, no_run_cache=False, pdb=False, pipeline=False, pull=False, queue=False, quiet=0, recursive=False, reset=False, run_all=False, set_param=[], single_item=False, targets=['eval-meta-model'], tmp_dir=False, verbose=2, version=None)
2021-03-16 15:48:53,926 DEBUG: Check for update is enabled.
2021-03-16 15:50:01,151 DEBUG: Detaching HEAD at 'HEAD'
2021-03-16 15:50:01,187 DEBUG: Stashing workspace
2021-03-16 15:50:54,364 DEBUG: Stashing changes in 'refs/stash'
2021-03-16 15:50:54,532 DEBUG: Applying stash commit '7c9e6f9fe2abce3d2327e354e960444940e746d8'
2021-03-16 15:52:11,572 DEBUG: Stashing changes in 'refs/exps/stash'
2021-03-16 15:52:11,767 DEBUG: Stashed experiment '91fce24' with baseline 'fb6ee5d' for future execution.
2021-03-16 15:52:11,814 DEBUG: Restoring stashed workspace
2021-03-16 15:52:11,815 DEBUG: Popping from stash 'refs/stash'
2021-03-16 15:52:11,816 DEBUG: Applying stash commit '7c9e6f9fe2abce3d2327e354e960444940e746d8'
2021-03-16 15:52:11,868 DEBUG: Dropping 'refs/stash@{0}'
2021-03-16 15:52:11,876 DEBUG: Restore HEAD to 'develop'
2021-03-16 15:52:11,918 DEBUG: Detaching HEAD at 'fb6ee5d6ee5360be997e811d2a3ef9e0baaa1c4e'
2021-03-16 15:53:19,951 DEBUG: Popping from stash 'refs/exps/stash'
2021-03-16 15:53:19,952 DEBUG: Applying stash commit '91fce2416944991765e55f9cd998d92534027ffa'
2021-03-16 15:53:19,994 DEBUG: Dropping 'refs/exps/stash@{0}'
2021-03-16 15:53:20,058 DEBUG: Running repro in...

Firsts lines of cprofile:

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000  394.863  394.863 experiments.py:514(run)
        1    0.000    0.000  394.857  394.857 __init__.py:828(run)
      3/1    0.000    0.000  394.857  394.857 __init__.py:46(wrapper)
        1    0.000    0.000  394.853  394.853 run.py:10(run)
        1    0.000    0.000  394.853  394.853 __init__.py:343(reproduce_one)
      380    0.003    0.000  388.698    1.023 __init__.py:340(_backend_func)
        6    0.001    0.000  387.632   64.605 dulwich.py:600(status)
        6    0.013    0.002  387.622   64.604 porcelain.py:1190(status)
       12    1.066    0.089  387.318   32.276 porcelain.py:1244(get_untracked_paths)
   280229    0.981    0.000  363.320    0.001 ignore.py:357(is_ignored)
   280229   23.477    0.000  362.340    0.001 ignore.py:328(find_matching)
  9014023   67.075    0.000  321.129    0.000 ignore.py:214(find_matching)
173364321   96.171    0.000  240.649    0.000 ignore.py:192(match)
        3    0.000    0.000  224.885   74.962 dulwich.py:229(is_dirty)
        1    0.000    0.000  192.206  192.206 __init__.py:52(wrapper)
        1    0.000    0.000  192.201  192.201 __init__.py:698(_workspace_repro)
        1    0.000    0.000  151.503  151.503 __init__.py:43(wrapper)
        1    0.000    0.000  151.502  151.502 __init__.py:422(new)
        1    0.000    0.000  151.502  151.502 __init__.py:138(_stash_exp)
        2    0.000    0.000  151.205   75.603 stash.py:32(push)
173378518  144.498    0.000  144.498    0.000 {method 'match' of 're.Pattern' objects}
323668/220470    0.956    0.000  138.575    0.001 {built-in method builtins.next}
        1    0.000    0.000  136.356  136.356 base.py:213(reproduce)
 1027/993    0.002    0.000   81.383    0.082 contextlib.py:107(__enter__)
        2    0.000    0.000   80.830   40.415 __init__.py:464(stash_workspace)
        1    0.000    0.000   74.087   74.087 base.py:384(commit)
        1    0.000    0.000   60.420   60.420 scm_context.py:9(run)
 1029/994    0.004    0.000   56.554    0.057 contextlib.py:116(__exit__)
        2    0.000    0.000   55.998   27.999 base.py:179(track_file_changes)
        1    0.000    0.000   55.998   55.998 __init__.py:274(remind_to_track)
        1    0.000    0.000   55.998   55.998 __init__.py:275(_filter)
        1    0.000    0.000   55.685   55.685 __init__.py:263(_prune_untracked_lockfiles)
        1    0.000    0.000   55.685   55.685 dulwich.py:217(untracked_files)
   283179    2.699    0.000   18.172    0.000 posixpath.py:453(relpath)
  2449599    3.932    0.000   12.142    0.000 ignore.py:315(_load_path)
  6500781    6.644    0.000   11.609    0.000 os.py:806(fsencode)
   574130    1.034    0.000    8.712    0.000 posixpath.py:376(abspath)
   851139    4.892    0.000    7.593    0.000 posixpath.py:75(join)
   583137    4.076    0.000    6.275    0.000 posixpath.py:338(normpath)
   280242    0.322    0.000    5.920    0.000 ignore.py:241(from_path)

[courentin]

seems like we have the same issue #5638

[pmrowla]

Duplicate of #5638

Will close this and move the discussion there