status: "recalculating" hashes each call

[pared]

When calling status on modified dir, DVC shows message Computing file/dir hashes (only done once) for each status call.
Reproduction script:

#!/bin/bash

set -exu

TMPDIR=issue-7390
mkdir $TMPDIR
pushd $TMPDIR

wsp=test_wspace
rp=test_repo

rm -rf $wsp && mkdir $wsp && pushd $wsp

mkdir $rp && pushd $rp

git init --quiet
dvc init --quiet
dvc config core.checksum_jobs 1

git add -A
git commit -am "init"

mkdir data

for i in {1..2000}
do
	dd if=/dev/random of=data/file$i bs=1k count=10 >& /dev/null
done

dvc add data
time dvc status
echo modification >> data/another_file

time dvc status 
time dvc status 

It might not necessarily be an issue with DVC, as "calculation" for subsequent status calls seems to be faster than the original one. Maybe it's just a problem with a message.

EDIT:
Running previous script for much bigger files shows that the recalculation does not happen. So its probably a message that is the problem.

[dberenbaum]

@pared Are you sure the recalculation doesn't happen? I see that subsequent calls take just as long.

This seems related to known regressions from the current refactoring. @efiop Is this expected?

$ time dvc status
wiki.dvc:
        changed outs:
                modified:           wiki
dvc status  47.80s user 11.55s system 104% cpu 56.869 total
$ time dvc status
wiki.dvc:
        changed outs:
                modified:           wiki
dvc status  47.78s user 11.07s system 102% cpu 57.451 total

A smaller dataset to reproduce:

$ dvc get-url http://images.cocodataset.org/zips/val2017.zip
$ unzip val2017.zip
$ dvc add val2017
$ echo foo > val2017/foo
$ time dvc status
val2017.dvc:
        changed outs:
                modified:           val2017
dvc status  5.62s user 1.18s system 98% cpu 6.896 total
$ time dvc status
val2017.dvc:
        changed outs:
                modified:           val2017
dvc status  5.61s user 1.19s system 95% cpu 7.105 total
$ dvc add val2017
$ time dvc status
Data and pipelines are up to date.
dvc status  0.42s user 0.13s system 95% cpu 0.575 total

[dtrifiro]

Can confirm:

+ dvc add data
100% Adding...|██████████|1/1 [00:07,  7.09s/file]

To track the changes with git, run:

    git add .gitignore data.dvc

To enable auto staging, run:

	dvc config core.autostage true
+ dvc status
Data and pipelines are up to date.

real	0m0.569s
user	0m0.454s
sys	0m0.077s
+ echo modification
+ dvc status
data.dvc:
	changed outs:
		modified:           data

real	0m2.941s
user	0m2.494s
sys	0m0.243s
+ dvc status
data.dvc:
	changed outs:
		modified:           data

real	0m3.053s
user	0m2.555s
sys	0m0.301s```

[daavoo]

The hashes are not recalculated, they are retrieved from the md5s db, so messaging is somehow misleading.
It's true that "computing" it's only done once but it should not say 'computing hashes' if we are not computing, IMO.

Times for subsequent runs are the same, though.

I run with viztracer as follows (same snippet from @pawel but I just used 50 files instead of 2000 for clearer debug):

dvc status --viztracer --viztracer-depth 10
dvc status --viztracer --viztracer-depth 10

And visualized with:

vizviewer viztracer.dvc-20220218_093001.json

[daavoo]

It appears that 114a07e introduced a performance downgrade for status:

# Previous commit
# @34697ef2983cd4fac7cc66aefc8577fdde8980b4
dvc status  0,31s user 0,11s system 64% cpu 0,654 total
# @114a07e7a448b667682fbe331ac06efbf4453494
dvc status  1,46s user 0,32s system 98% cpu 1,807 total

After 114a07e, when there is a new untracked file, we are building a new Tree object (_get_tree_obj->_build_tree) on each status call.

Before 114a07e, we were loading from state (_load_from_state) from the stagging DB.

This is causing the Computing file/dir hashes (only done once) to appear and the performance downgrade.

I suspect this affects more places beyond status.

cc @efiop @pmrowla

[pared]

@dberenbaum strange, what dvc version you used? For me on latest master, (500 files, 10Mb each):

+ dvc add data
100% Adding...|██████████████████████████████████████████████████████████████████████████████████████████████████|1/1 [00:12, 12.75s/file]
                                                                                                                                          
To track the changes with git, run:                                                                                                       

    git add .gitignore data.dvc

To enable auto staging, run:

        dvc config core.autostage true

real    0m13.364s
user    0m8.684s
sys     0m1.900s
+ echo modification
+ tee data/another_file
+ dvc status
data.dvc:                                                                                                                                 
        changed outs:                                                                                                                     
                modified:           data

real    0m0.959s
user    0m0.759s
sys     0m0.163s
+ dvc status
data.dvc:                                                                                                                                 
        changed outs:                                                                                                                     
                modified:           data

real    0m0.984s
user    0m0.789s
sys     0m0.162s

[dberenbaum]

@pared I also used latest master. Maybe I misinterpreted your concern. It seems like the two status calls after modification took the same time, which I thought was the problem?

[pared]

Sorry @dberenbaum, my concern was that we get Computing file/dir hashes (only done once) each time we call dvc status - so its clearly not done only once. I am yet not sure if recalculation actually happens, but the message seems misleading.

[pared]

We have been looking into that with @daavoo and it seems that before 114a07e

staging DB, under .dvc/tmp/staging was able to locate hash_info for the target:

https://github.com/iterative/dvc/blob/114a07e7a448b667682fbe331ac06efbf4453494/dvc/objects/stage.py#L231-L232

however, after the change, staging db became a ReferenceObjectDB, and underlying MemoryFileSystem does not seem to find staged dir, _load_from_state fails with FileNotFoundError and the tree gets build as @daavoo mentioned in previous comment . We did not manage to find exactly why.