Subject: Re: Slowness (caching issues?) in dependency checking

From: Niklas Böhm <[email-masked]>
Date: Sun, 28 Aug 2022 20:30:37 +0200

>> (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.

That makes sense, then I guess this could be further decreased by 
setting REDO_NO_SYNC=1, although that was just something I noticed and 
am not bothered by.

> 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.

Thank you, that resolves my issue and helps by a lot.  I have played 
around with it for a bit and now the program checks the dependencies a 
lot faster in the example case.  On a local disk it went from 10 seconds 
down to 1.5 and on the NFS it's now from 22 minutes down to about 3, so 
quite big improvements.

>> 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.

I agree that this is probably the explanation of the remaining 
difference, but that is an acceptable trade-off since the difference is 
not that large anymore.  By using separate files goredo plays much nicer 
with distributed systems; the sqlite database gets corrupted when more 
than one computer accesses it via a networked FS.

Thank you for the fast response and improving the software so quickly.