Subject: Slowness (caching issues?) in dependency checking

From: Jan Niklas Böhm <[email-masked]>
Date: Thu, 25 Aug 2022 18:05:38 +0200

Hello all,

while using goredo I encountered some slowness when checking targets.  I 
am not sure how exactly it is ocurring and was wondering whether this 
can be solved somehow.

I have attached an MWE that hopefully illustrates my point.  If the tar 
archive is decompressed there are five do files:
   all.do: does some computation by calling default.run.do
           a bunch of times in a deep folder hierarchy
   default.run.do: recursively prints some stuff
   default.suffix{,2}.do: both simply append some text to a target
   default.cat.do: prints a part of its file, used for side-effect

The target `all` creates a lot of folders in out/ so that the dependency 
tracking requires a bit of work (the default.run.do is seprarated by a 
lot of folders from the .run file `out/a/.../z/$i.$j.run`).

If the target is called with `redo-ifchange all.suffix.suffix2` then 
everything is being computed in order, as it should (takes ~25 sec. on 
my machine).

When the same line is executed again, all the dependencies need to be 
checked, which takes some time.  But what surprises me is that the time 
to check whether the .suffix or .suffix2 rule is ood is quite 
significant.  I used the following to benchmark the process:

      hyperfine 'redo-ifchange all.suffix' 'redo-ifchange 
all.suffix.suffix2'

and the results I get are:

     Benchmark 1: redo-ifchange all.suffix
       Time (mean ± σ):      7.107 s ±  0.587 s    [User: 7.464 s, 
System: 1.501 s]
       Range (min … max):    6.541 s …  8.101 s    10 runs

     Benchmark 2: redo-ifchange all.suffix.suffix2
       Time (mean ± σ):      8.161 s ±  0.093 s    [User: 8.626 s, 
System: 1.750 s]
       Range (min … max):    7.991 s …  8.234 s    10 runs

     Summary
       'redo-ifchange all.suffix' ran
         1.15 ± 0.10 times faster than 'redo-ifchange all.suffix.suffix2'

I did not expect that there would be this much of a discrepancy between 
those two targets, the overhead for .suffix2 should be negligible in 
comparison, but it still takes a second longer to check this target with 
`redo-ifchange`.  Just from how this seems to me I would think that it 
is something related to the cache.  Or is there another explanation for 
this?

When running redo with the debug flag the program gets to the line (from 
`ifchange.go`)

      [127847] dbg  collecting deps

quite fast but then seems to get stuck at that stage for a while until 
it then proceeds to spit out a lot of dependecy checking information.

If the file `default.suffix.do` is changed trivially (e.g. by changing 
the string it appends) then redo will also have another pause with the 
same line as above when running the .suffix dependency rule.  Doing this 
shows the issue quite clearly as there is a significant delay between 
the two targets:

     redo . all.suffix (default.suffix.do) (11.107s)
     redo all.suffix.suffix2 (default.suffix2.do) (15.130s)

I hope the mail somewhat outlined the issue but I am happy to provide 
more information or explanations.  I took a stab at the code but it was 
not really clear how I could solve my issue.

Thanks in advance and for reading all that text
Nik