On Windows, dvc repro spends an awful lot of time in rwlock

[charlesbaynham]

Windows 7 / 10, dvc 0.93.0+f5d89f (after merging #3645)

Running cProfile on dvc repro -P in a repository with around 200 steps all of which are up to date. On my system this takes 65s, of which 42s is spent in _edit_rwlock.

I wonder, is it necessary to lock each individual file here? Couldn't the whole repository be locked instead?

Maybe a broader question: what are the respective purposes of .dvc/tmp/rwlock, .dvc/lockand .dvc/updater.lock?

[efiop]

Running cProfile on dvc repro -P in a repository with around 200 steps all of which are up to date. On my system this takes 65s, of which 42s is spent in _edit_rwlock.

Thanks for the investigation! That is indeed pretty strange, we need to take a closer look. Could you show your dvc version output btw?

I wonder, is it necessary to lock each individual file here? Couldn't the whole repository be locked instead?

Actually, that's what we used to do, but rwlock was introduced to support granular locking, so that you could run dvc in parallel.

Maybe a broader question: what are the respective purposes of .dvc/tmp/rwlock, .dvc/lockand .dvc/updater.lock?

Useful link: https://dvc.org/doc/user-guide/dvc-files-and-directories 🙂 rwlock is for granular locking of specific deps and outs, lock is for locking the whole repo (when you need to push/pull/etc or need to create/modify/delete dvc-file). updater.lock is for our updater worker, that checks for updates once a week.

[efiop]

@charlesbaynham Btw, have you tried running that on Linux? Wonder if this is windows-specific or if we have troubles everywhere.

[charlesbaynham]

Thanks for the run down @efiop, that's helpful. The version that ran the above was 0.93.0+f5d89f, which is v0.93.0 + the changes in PR #3645. That's necessary because otherwise the effect is swamped by all the time spent reproducing duplicate steps.

I'll give it a try on linux: annoyingly the repository I tested on has some case sensitivity problems which I've glossed over so far on Windows but which prevent it from working on linux, but I should fix that anyway.

The cProfile results for my repo on Windows:
repro_nowork.zip

[charlesbaynham]

Here's the cProfile results for dvc repro -P in the same repo, run on Linux and Windows.

repro_profile.zip

It looks like the same fraction of time is spend writing to rwlock in both (just via posix.fsync instead of nt.fsync)

[charlesbaynham]

Here's a screenshot of the profile for Windows:

Zooming in, you can see that the actual calls to Stage.changed() don't take much time at all, though that's where I'd have expected most of the load to be.

[efiop]

@charlesbaynham Sorry for the delay. Admitedly didn't have much time to look deeply into it, but could you give my patch a try, please:

pip uninstall -y dvc
# make sure there is no old dvc version installed
pip install git+https://github.com/efiop/dvc@3653

?

[charlesbaynham]

Yes that makes a lot of difference. Here are two profiles in the same repo on Window 7, one at v0.93.0+f5d89f and the other at your patch:

data_processing.zip

Your patch cuts the time spent in _reproduce_stages from 62s:

to 23s

[charlesbaynham]

But doesn't that just effectively disable the lock?