[yocto] Why can diffsigs take sometimes really looooong?

[Richard Purdie]

On Mon, 2018-07-16 at 11:26 +0300, Uwe Geuder wrote:
> On Sun, Jul 15, 2018 at 1:38 PM, Richard Purdie  wrote:
> > On Fri, 2018-07-13 at 19:18 +0300, Uwe Geuder wrote:
> > > At times I find the diffsigs command useful/educational to
> > > understand
> > > what is going on in my build.
> > > 
> > > $ bitbake-diffsigs -t myimage do_image
> > > 
> > > Often the result is shown in no time. However, recently I got
> > > some
> > > cases were it takes 150 (!) minutes to show a simple difference
> > > (1
> > > line
> > > changed in do_install of systemd).
> > > 
> > > In comparision building after that change (with sstate) takes
> > > some 10
> > > minutes. And building everything from scratch (no sstate) takes
> > > just
> > > a
> > > bit over 50 minutes on the same machine.
> > > 
> > > Of course the build can make good use of my 8 cores / 16 threads,
> > > whereas diffsigs seems to run in only 1 core. Still, shouldn't
> > > every
> > > build calculate all the dependencies, so running diffsigs should
> > > only
> > > be
> > > a small fraction of that work?
> > > 
> > > Is there a natural explanation why diffsigs can sometimes be so
> > > slow?
> > > Just curious to understand what is going on there.
> > > 
> > > I am on Rocko 2.4.3 if that makes a difference.
> > 
> > Is your sstate directory on something slow like NFS?
> > 
> 
> No, it is on the same ext4 as the rest of my build area. Backed by an
> Intel NVMe flash drive, so hopefully that is of reasonable quality...
> 
> Here is the output of the time command from a new "record" diffsigs
> run
> shortly after my first posting
> 
> > real    244m8.594s
> > user    137m21.897s
> > sys     8m17.606s
> 
> So there is already more than 2 hours of CPU usage. Because diffsigs
> seems to be single threaded, that is a lower bound even with the best
> filesystem/disk.
> 
> This build environment has been in use in development work for a
> couple of days. So there are many different signatures. But that
> should not make any significant difference if I compare just the 2
> last ones, should it?
> 
> When I had such a long run for the first time I first thought I had
> run in an endless loop. strace showed that the same files were opened
> again and again. However, in the end the command completed. I haven't
> made an effort yet to understand the pattern how it opens these
> files.
> 
> For clean builds with no previous sstate I need "only" something like
> 
> > real	54m53.939s
> > user 3268446 - 103936 = 3164510 = 527m25.10s
> > system 820431 - 1345 = 136m30.86s
> 
> (These numbers are from overlayfs over ext4 on the same disk. Don't
> have
> any numbers without the additional overlayfs handy right now.
> According
> to experience the additional overlayfs leads to very similar wall
> times,
> just significant extra system CPU time)

Based on the above info, it seems there is something scaling badly in
whatever algorithm that code is using :(

I don't remember much about that code in particular, I do know I've
never been happy with its chances of successfully reporting what the
user actually wanted to know. Its been on my todo list for a while to
go back and try and create a command which actually gives the user the
information they wanted but there have been other more pressing
issues...

I'd certainly be interested in understanding where the current code is
scaling badly...

Cheers,

Richard