Why can diffsigs take sometimes really looooong?

Why can diffsigs take sometimes really looooong?

[Uwe Geuder]

Hi!

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.


Regards,

Uwe Geuder
Neuro Event Labs Oy
Tampere, Finland
uwe.gexder@neuroeventlabs.com (Bot check: fix one obvious typo)

Re: Why can diffsigs take sometimes really looooong?

[Richard Purdie]

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?

Cheers,

Richard

Re: Why can diffsigs take sometimes really looooong?

[Uwe Geuder]

Thanks for your reply!

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)


Regards,

Uwe Geuder
Neuro Event Labs Oy
Tampere, Finland
uwe.gexder@neuroeventlabs.com (Bot check: fix one obvious typo)

Re: 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