*** Jan Niklas Böhm [2022-08-27 11:11]:
>I would expect that in both cases the amount of time taken would be almost
>equal and not multiple seconds apart.  Does this behavior not arise on your
>machine?  I've tried this out with the new version 1.26 now.

That one is reproducible indeed on my machine:

    % redo all.suffix
    [it tooks ~3.38sec]

    % vi default.suffix.do
    % time redo-ifchange all.suffix
    redo all.suffix (default.suffix.do) (10.258s)
    user:9,19s sys:6,35s mem:191902/11 io:13/36 13,162

    % vi default.suffix.do
    % time redo-ifchange all.suffix.suffix2
    redo . all.suffix (default.suffix.do) (10.266s)
    redo all.suffix.suffix2 (default.suffix2.do) (13.166s)
    user:12,45s sys:6,79s mem:200804/11 io:10/75 16,138

    % time redo-ifchange all.suffix.suffix2
    user:6,38s sys:5,47s mem:193014/11 io:0/0 10,204

>(As an aside, it is a bit odd that `time` reports 5 seconds more than redo
>does.)

Well, goredo tries to report time exactly spent on run target. Its
"started=now()" (analogue) is placed as near as possible to the exec()
call, and finished=now() is placed just after exec() is finished. So
that time does not include related supplementary things like dealing
with temporary files, committing state files, working with lockfiles and
similar things. Moreover multiple goroutines are run, that can create
additional processes, meaning additional context switches.

As I can see, OOD checking+building (first redo-ifchange call in my
output) takes ~10sec according to goredo's measurement and ~13sec told
by time-command. So there is ~3sec overhead not measured by goredo. The
second redo-ifchange reports about the same ~10sec of work spent on
all.suffix, ~13sec (the same time told by time-command of first
redo-ifchange) for all.suffix.suffix2 and yet another additional ~3sec
overhead, giving resulting ~16sec of total execution time.

Those 3sec of "overhead" looks pretty scaring big. However after each
target is finished, goredo deal with temporary files, lockfiles, their
syncing, fully copying of dependency .rec-files by fully parsing them.

>What I was wondering about is whether the ood information regarding
>`default.run.do` is cached.  Since this file is the same for all of
>`out/a/.../z/$i.$j.run` it need only be checked once.

No caching is done at all there.

>I would
>assume that this information could be cached for a single invocation of
>`redo-ifchange`, or is it not intended?

Well, currently I do not see any drawbacks of caching that kind of
information. Seems that there should not be any kind of races. OOD
checking is done at the very beginning of goredo invocation and later
only the targets are run.

I made 1.27.0 release that caches OOD decisions and file existence
checks. Profiling shows that majority of time goredo spent in syscalls.
Actually my time-command's output shows that too.

Next biggest bottleneck was the parser of .rec files. It applied regular
expression for nearly each line of those .rec files, that took nearly 2
seconds in total. I threw out regexp and know:

    % time redo-ifchange all.suffix.suffix2
    user:1,67s sys:0,17s mem:207956/11 io:0/0 1,198

But profiling showed that nearly 800ms is still spent on parsing
dependencies. However your redotest created:

    % cat **.rec G "^Type:" W
    87785
    % cat **.rec W
    292957

87k records with 292k lines in them.

>As another note: the apenwarr-redo implementation takes roughly 0.5 seconds
>to `redo-ifchange` the target on a tmpfs and 1 minute on and NFS, so it is
>quite a lot faster.  Is this expected due to this implementation storing the
>ood information in a single sqlite file?

After seeing 292k of lines goredo parses in redotest, I am confident
that apenwarr/redo is faster exactly because of that: dealing with
single-file efficient database vs parsing of 87k number of records in
1028 files (however I am doubt that reading of cached 1k files is
non-negligible time). Of course previously goredo also produced huge
amount of syscalls, that was the major obstacle.

-- 
Sergey Matveev (http://www.stargrave.org/)
OpenPGP: 12AD 3268 9C66 0D42 6967  FD75 CB82 0563 2107 AD8A